Sun Feb 27 09:33:02 2011 : Debug: Listening on authentication address * port 1812
Sun Feb 27 09:33:02 2011 : Debug: Listening on accounting address * port 1813
Sun Feb 27 09:33:02 2011 : Debug: Listening on command file /var/run/radiusd/radiusd.sock
Sun Feb 27 09:33:02 2011 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Sun Feb 27 09:33:02 2011 : Debug: Listening on proxy address * port 1814
Sun Feb 27 09:33:02 2011 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=0, length=118
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0200000a016461746131
        Message-Authenticator = 0xca2cf684fdf563ae9f7a70dc903c94c7
Sun Feb 27 09:33:31 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:31 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:31 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:31 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:31 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:31 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP packet type response id 0 length 10
Sun Feb 27 09:33:31 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns updated
Sun Feb 27 09:33:31 2011 : Info: [files] users: Matched entry data1 at line 79
Sun Feb 27 09:33:31 2011 : Info: ++[files] returns ok
Sun Feb 27 09:33:31 2011 : Info: ++[expiration] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[logintime] returns noop
Sun Feb 27 09:33:31 2011 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Sun Feb 27 09:33:31 2011 : Info: ++[pap] returns noop
Sun Feb 27 09:33:31 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:31 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP Identity
Sun Feb 27 09:33:31 2011 : Info: [eap] processing type tls
Sun Feb 27 09:33:31 2011 : Info: [tls] Initiate
Sun Feb 27 09:33:31 2011 : Info: [tls] Start returned 1
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns handled
Sending Access-Challenge of id 0 to 172.23.35.62 port 62548
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "4"
        EAP-Message = 0x010100061520
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x8fea28458feb3d827bd98591604cf6d5
Sun Feb 27 09:33:31 2011 : Info: Finished request 0.
Sun Feb 27 09:33:31 2011 : Debug: Going to the next request
Sun Feb 27 09:33:31 2011 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=1, length=220
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0201005e150016030100530100004f03014d6afb7131262c032c18450713b3265251ef7e3bc4994a649dae386691bf77fa00002800390038003500160013000a00330032002f000700050004001500120009001400110008000600030100
        State = 0x8fea28458feb3d827bd98591604cf6d5
        Message-Authenticator = 0x91de3f4dee5349e12d78ba274eda15a3
Sun Feb 27 09:33:31 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:31 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:31 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:31 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:31 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:31 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP packet type response id 1 length 94
Sun Feb 27 09:33:31 2011 : Info: [eap] Continuing tunnel setup.
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:31 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:31 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:31 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP/ttls
Sun Feb 27 09:33:31 2011 : Info: [eap] processing type ttls
Sun Feb 27 09:33:31 2011 : Info: [ttls] Authenticate
Sun Feb 27 09:33:31 2011 : Info: [ttls] processing EAP-TLS
Sun Feb 27 09:33:31 2011 : Info: [ttls] eaptls_verify returned 7 
Sun Feb 27 09:33:31 2011 : Info: [ttls] Done initial handshake
Sun Feb 27 09:33:31 2011 : Info: [ttls]     (other): before/accept initialization
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: before/accept initialization
Sun Feb 27 09:33:31 2011 : Info: [ttls] <<< TLS 1.0 Handshake [length 0053], ClientHello  
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: SSLv3 read client hello A
Sun Feb 27 09:33:31 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length 002a], ServerHello  
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: SSLv3 write server hello A
Sun Feb 27 09:33:31 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length 085e], Certificate  
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: SSLv3 write certificate A
Sun Feb 27 09:33:31 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length 020d], ServerKeyExchange  
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: SSLv3 write key exchange A
Sun Feb 27 09:33:31 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone  
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: SSLv3 write server done A
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: SSLv3 flush data
Sun Feb 27 09:33:31 2011 : Info: [ttls]     TLS_accept: Need to read more data: SSLv3 read client certificate A
Sun Feb 27 09:33:31 2011 : Debug: In SSL Handshake Phase 
Sun Feb 27 09:33:31 2011 : Debug: In SSL Accept mode  
Sun Feb 27 09:33:31 2011 : Info: [ttls] eaptls_process returned 13 
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns handled
Sending Access-Challenge of id 1 to 172.23.35.62 port 62548
        EAP-Message = 0x0102040015c000000aad160301002a0200002603014d6a8aeb7af495482d03fafad8295aa8b3effdc746deb36a85ebc5936778e62500003900160301085e0b00085a0008570003a6308203a23082028aa003020102020101300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479
        EAP-Message = 0x301e170d3131303232373031333335335a170d3131303432383031333335335a307c310b3009060355040613024652310f300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e312330210603550403131a4578616d706c65205365727665722043657274696669636174653120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100c5d83404209a1398b8c9eaaab33fde479378e058c180ba30bd360f33b16a29248716ba3811ff708cabeb1756a502f9e991e1a7836cfaa3dc1f4f4013b7f6
        EAP-Message = 0xc30da449f91f7e4fc4d3b9fe7eb18bc41aa0a5c0a5b5af7a566731c309e609d75ab01f5e74d8342a97c0a4380abf4021ae4f3534b281936fd51974ceaa763a4b8c34f96cfc8878773487f8a35b8a4945e183fbe082960a8d4840d9588586030b0d159e38bd43dc09bcdaa512bb638aed9e98dea107ff74acd61fbaca777bfc9ee11bb15e061744c44816768817c22c55f79c4f8ecf22831d2c0ef5faeeadf44dbad9ef919d6342ae74f279ea5cad50f939253ad0cc0b56d3d32de6eee070435657b90203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d01010505000382010100123eec65680ad13742
        EAP-Message = 0xd558d6d091e711b046b82871fcfd9572f94366097bf25272bf59fd4754a2d8483186f4a09d7591d9bd02acb17cb49cacb750e4071be071b9f93662cdfba5951aa09d41b80a6d17b7bed03c030a9f2e1b5a7bd575d5cd47c1227130cca2a522cd3751bdbd2c14527d83a33ce12a1bcb83ba01a13ccdc3061bdb0002ecdba191e78f148d915865a482c2d9e51492b8da03e3f771dad85295915d99b013aac885c2c28e51b68dc7895fda644bf66a952d073188f178c3c7bde9e7b152ae498302af8d7b6a30425354d9716a634bdf712e7b6ee9bcccf02352d61d995668906045b7b26b484a8d842c2147acb6811066c364484be495dddf460004ab308204
        EAP-Message = 0xa73082038fa0030201020209
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x8fea28458ee83d827bd98591604cf6d5
Sun Feb 27 09:33:31 2011 : Info: Finished request 1.
Sun Feb 27 09:33:31 2011 : Debug: Going to the next request
Sun Feb 27 09:33:31 2011 : Debug: Waking up in 4.4 seconds.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=2, length=132
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020200061500
        State = 0x8fea28458ee83d827bd98591604cf6d5
        Message-Authenticator = 0x059a1bd99c5d583736321021066d77d0
Sun Feb 27 09:33:31 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:31 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:31 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:31 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:31 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:31 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP packet type response id 2 length 6
Sun Feb 27 09:33:31 2011 : Info: [eap] Continuing tunnel setup.
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:31 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:31 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:31 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP/ttls
Sun Feb 27 09:33:31 2011 : Info: [eap] processing type ttls
Sun Feb 27 09:33:31 2011 : Info: [ttls] Authenticate
Sun Feb 27 09:33:31 2011 : Info: [ttls] processing EAP-TLS
Sun Feb 27 09:33:31 2011 : Info: [ttls] Received TLS ACK
Sun Feb 27 09:33:31 2011 : Info: [ttls] ACK handshake fragment handler
Sun Feb 27 09:33:31 2011 : Info: [ttls] eaptls_verify returned 1 
Sun Feb 27 09:33:31 2011 : Info: [ttls] eaptls_process returned 13 
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns handled
Sending Access-Challenge of id 2 to 172.23.35.62 port 62548
        EAP-Message = 0x0103040015c000000aad00e91f3d8686d55494300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3131303232373031333335335a170d3131303432383031333335335a308193310b3009060355040613024652310f300d0603550408130652616469757331123010
        EAP-Message = 0x06035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930820122300d06092a864886f70d01010105000382010f003082010a0282010100da454f1c7095f1ff117161f3de2d13b3bad1fb43a943f71a8ad2e006a46d200c8f8c47a370f29a6e3215fe30c944fc87354d1a87badb0135cd7e7d248830ca731b2efa666a7ef6e5051cb3dafb36e0d812eb4eaa2cf9c59721775cb94a42e5266f26d6f856e16baa7a0504
        EAP-Message = 0x1b119bf995f07ced6d6546c844d70fb97eae68f3fa54acbe71296fa1b4b9c11684ff673e40e6fdc68cc4ebffad9a36717a1ccffca0a1315b3f680ed5df200bbadf5ff26137b09986a6e2e4cc468a2cb68a49b78e50909d7eb388927faf5f350f176a6da453fde10aa6a998822f0caa5c27772b291361f2966ac623d85f5689ee8c6402e2f697d61bfefd31fc22e75077f4843699b50203010001a381fb3081f8301d0603551d0e04160414b1b236b6fde53a7b09d79dab65ff76c3ec88ecd43081c80603551d230481c03081bd8014b1b236b6fde53a7b09d79dab65ff76c3ec88ecd4a18199a48196308193310b3009060355040613024652310f300d
        EAP-Message = 0x060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900e91f3d8686d55494300c0603551d13040530030101ff300d06092a864886f70d010105050003820101004d5f094e0d923e7bf961bc50f881f1cb682a1562b134cde97a02c1148d4adf73893cf103fa46d2335ccf05d60e6f7a05cc5ea7845fb2d2e9b25dcb2dd829bd1ee41fc95d13600b5bad921fb77d20
        EAP-Message = 0x3660dae6b972a858aa2ec672
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x8fea28458de93d827bd98591604cf6d5
Sun Feb 27 09:33:31 2011 : Info: Finished request 2.
Sun Feb 27 09:33:31 2011 : Debug: Going to the next request
Sun Feb 27 09:33:31 2011 : Debug: Waking up in 4.4 seconds.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=3, length=132
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020300061500
        State = 0x8fea28458de93d827bd98591604cf6d5
        Message-Authenticator = 0x5aab4ebab70401f4f3e3fcbc6bcd595e
Sun Feb 27 09:33:31 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:31 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:31 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:31 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:31 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:31 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:31 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP packet type response id 3 length 6
Sun Feb 27 09:33:31 2011 : Info: [eap] Continuing tunnel setup.
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:31 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:31 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:31 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:31 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:31 2011 : Info: [eap] EAP/ttls
Sun Feb 27 09:33:31 2011 : Info: [eap] processing type ttls
Sun Feb 27 09:33:31 2011 : Info: [ttls] Authenticate
Sun Feb 27 09:33:31 2011 : Info: [ttls] processing EAP-TLS
Sun Feb 27 09:33:31 2011 : Info: [ttls] Received TLS ACK
Sun Feb 27 09:33:31 2011 : Info: [ttls] ACK handshake fragment handler
Sun Feb 27 09:33:31 2011 : Info: [ttls] eaptls_verify returned 1 
Sun Feb 27 09:33:31 2011 : Info: [ttls] eaptls_process returned 13 
Sun Feb 27 09:33:31 2011 : Info: ++[eap] returns handled
Sending Access-Challenge of id 3 to 172.23.35.62 port 62548
        EAP-Message = 0x010402cb158000000aad5ab78c759ba9db8617607ae43643021e6e921a19c1f38522c578423fbaf775cc6741db990b7fe3b4c0d0a900b79824fb9e374126513ff3b576f47ffe24a5f5aae4ab65cee00d57821dabee2f15cdb37e1cf9c455d6ddc44f1840c91a2a03e991e4b30f60c90ebc7eeefeaa3e38b1306b6a1153450f3bb7d58d4c752d12960c6f578e30b66ed5cfba671af82e4a7b30b56c6670e247d8dfc46c85c687ff9afcd7623eaa2a0fb5160301020d0c0002090080aebfb33af7cd387d331acfe0fea8f39fd2540da23f0038c0a2fc1c92fa46e0ce7e4b6be78a094ddadcf480a1b18931afba238cc0aecbbb4ad6b37c51679f600c2176
        EAP-Message = 0x7fcae6299d7b8e32a6f411910bc68ed938ac397737a51738018ea2f31ea3bf17def31ec7372d46a3201b6c791c1837466e2030254c25ceda3c0c79609fbb0001020080949ba2cbbcc25acf1cf174f460302ee26ab1762ddece3b2ad4c54d211efe33315ddf1aa780518837ead1b02173ff6f88fb8daab08eca3ea42da027a317120436990ecb60d6c6ea6343ba41f4743c7e2781bb497b4cab29bae1559534019ae954c45e5b5be55182a148f34774df7e9d97fdb1ff8938102cc8b0ecc5e0e28dbc2f0100583b3ac121b1b71a06de1beb3233453fcc4d02251fddaf20ea91adb0b8770c8033b32e40f91844ee844ef489a0719689a7f80c5c49dc2402
        EAP-Message = 0xb3f376551f80bf44ef0fb207bcb395f284f8a616ded2b328af81e2a1c688ac7b5b930f4b5dd242316ee5af710ce5d46da8843aafc24ec40f00ffdf23f783c720c86c139a82b30469d4fc9271e0990502e3f45f89f3d0845d37faecac471d4bab19422ef9b14f38b6ae1f15e59dc87cbf1c16174b6c654bd59a52b27aae91ab5cd9b714def6e55adec85c107cbfa4b5cd99f1351ab60b216d62fbd8072b9b0d00d7fab375082720e7b86236b42aff6d1078b13488a028e3735c4a20369a75ff6e4dfab510402ddcb316030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x8fea28458cee3d827bd98591604cf6d5
Sun Feb 27 09:33:31 2011 : Info: Finished request 3.
Sun Feb 27 09:33:31 2011 : Debug: Going to the next request
Sun Feb 27 09:33:31 2011 : Debug: Waking up in 4.2 seconds.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=4, length=330
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020400cc150016030100861000008200806c517a65da1e80bc3905a0cf169ea04a402b2292d0764d95b0641c02f3093e9d80927bf1899b3f6a819b9c83ba3dcea8c8b43c9c046672d7af310dd0f3e7d69ff271b869f964e9e29704e67cc276a015ad877b8695c05c25e0e4493f6cd5461f852cd273512e23ffc5533034913c666dd9eedc5c07ec838d3d8beb93de64cc96140301000101160301003098a5787a580e0d03da375ed706347bd2f55a3c11eb89ca8bea555e3274686f96da6769a4d316098df34aa72405ad999b
        State = 0x8fea28458cee3d827bd98591604cf6d5
        Message-Authenticator = 0xe6b4946b21fe190dbfdd4646f75e60dc
Sun Feb 27 09:33:32 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:32 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:32 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:32 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:32 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:32 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP packet type response id 4 length 204
Sun Feb 27 09:33:32 2011 : Info: [eap] Continuing tunnel setup.
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:32 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:32 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:32 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP/ttls
Sun Feb 27 09:33:32 2011 : Info: [eap] processing type ttls
Sun Feb 27 09:33:32 2011 : Info: [ttls] Authenticate
Sun Feb 27 09:33:32 2011 : Info: [ttls] processing EAP-TLS
Sun Feb 27 09:33:32 2011 : Info: [ttls] eaptls_verify returned 7 
Sun Feb 27 09:33:32 2011 : Info: [ttls] Done initial handshake
Sun Feb 27 09:33:32 2011 : Info: [ttls] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange  
Sun Feb 27 09:33:32 2011 : Info: [ttls]     TLS_accept: SSLv3 read client key exchange A
Sun Feb 27 09:33:32 2011 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec [length 0001]  
Sun Feb 27 09:33:32 2011 : Info: [ttls] <<< TLS 1.0 Handshake [length 0010], Finished  
Sun Feb 27 09:33:32 2011 : Info: [ttls]     TLS_accept: SSLv3 read finished A
Sun Feb 27 09:33:32 2011 : Info: [ttls] >>> TLS 1.0 ChangeCipherSpec [length 0001]  
Sun Feb 27 09:33:32 2011 : Info: [ttls]     TLS_accept: SSLv3 write change cipher spec A
Sun Feb 27 09:33:32 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length 0010], Finished  
Sun Feb 27 09:33:32 2011 : Info: [ttls]     TLS_accept: SSLv3 write finished A
Sun Feb 27 09:33:32 2011 : Info: [ttls]     TLS_accept: SSLv3 flush data
Sun Feb 27 09:33:32 2011 : Info: [ttls]     (other): SSL negotiation finished successfully
Sun Feb 27 09:33:32 2011 : Debug: SSL Connection Established 
Sun Feb 27 09:33:32 2011 : Info: [ttls] eaptls_process returned 13 
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns handled
Sending Access-Challenge of id 4 to 172.23.35.62 port 62548
        EAP-Message = 0x0105004515800000003b1403010001011603010030f877b1c62540abb7ed8f2e0fce88e8d9b4fd67959dcfd7e320f4ecd6aa0f0572470905b202cd386512fad3b1f790ea85
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x8fea28458bef3d827bd98591604cf6d5
Sun Feb 27 09:33:32 2011 : Info: Finished request 4.
Sun Feb 27 09:33:32 2011 : Debug: Going to the next request
Sun Feb 27 09:33:32 2011 : Debug: Waking up in 4.1 seconds.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=5, length=222
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020500601500170301002058a75f475c69d073be67f1d9d5d4221df12510d38d517492fd2fa390f7c5c6691703010030e0ec07379f699504fd4862be8228f82e27a62fcba753af1a4fb782ae4e5598f497b497cb3a707bc3234d1d8fd7247e0b
        State = 0x8fea28458bef3d827bd98591604cf6d5
        Message-Authenticator = 0x406e419da0b30502ff18657f8418ed2f
Sun Feb 27 09:33:32 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:32 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:32 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:32 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:32 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:32 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP packet type response id 5 length 96
Sun Feb 27 09:33:32 2011 : Info: [eap] Continuing tunnel setup.
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:32 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:32 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:32 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP/ttls
Sun Feb 27 09:33:32 2011 : Info: [eap] processing type ttls
Sun Feb 27 09:33:32 2011 : Info: [ttls] Authenticate
Sun Feb 27 09:33:32 2011 : Info: [ttls] processing EAP-TLS
Sun Feb 27 09:33:32 2011 : Info: [ttls] eaptls_verify returned 7 
Sun Feb 27 09:33:32 2011 : Info: [ttls] Done initial handshake
Sun Feb 27 09:33:32 2011 : Info: [ttls] eaptls_process returned 7 
Sun Feb 27 09:33:32 2011 : Info: [ttls] Session established.  Proceeding to decode tunneled attributes.
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled request
        EAP-Message = 0x0200000a016461746131
        FreeRADIUS-Proxied-To = 127.0.0.1
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled identity of data1
Sun Feb 27 09:33:32 2011 : Info: [ttls] Setting default EAP type for tunneled EAP session.
Sun Feb 27 09:33:32 2011 : Info: [ttls] Sending tunneled request
        EAP-Message = 0x0200000a016461746131
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "data1"
server inner-tunnel {
Sun Feb 27 09:33:32 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
Sun Feb 27 09:33:32 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:32 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:32 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:32 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:32 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[control] returns noop
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP packet type response id 0 length 10
Sun Feb 27 09:33:32 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns updated
Sun Feb 27 09:33:32 2011 : Info: [files] users: Matched entry data1 at line 79
Sun Feb 27 09:33:32 2011 : Info: ++[files] returns ok
Sun Feb 27 09:33:32 2011 : Info: ++[expiration] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[logintime] returns noop
Sun Feb 27 09:33:32 2011 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Sun Feb 27 09:33:32 2011 : Info: ++[pap] returns noop
Sun Feb 27 09:33:32 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:32 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
Sun Feb 27 09:33:32 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP Identity
Sun Feb 27 09:33:32 2011 : Info: [eap] processing type md5
Sun Feb 27 09:33:32 2011 : Debug: rlm_eap_md5: Issuing Challenge
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns handled
} # server inner-tunnel
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled reply code 11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "4"
        EAP-Message = 0x0101001604100372dc82370431f8f14928c266592d24
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x53b40ffc53b50b4f58ec2c3fa0e0d49d
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled Access-Challenge
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns handled
Sending Access-Challenge of id 5 to 172.23.35.62 port 62548
        EAP-Message = 0x0106004f1580000000451703010040bca89dbbb7318c11513ed33fb5ec5aa5c432495f05709197ad1f864245c370368fc80c70eecc4e1ef4e5db564a802b8fd3fab306627d7a9a34ccb3a896b38f2f
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x8fea28458aec3d827bd98591604cf6d5
Sun Feb 27 09:33:32 2011 : Info: Finished request 5.
Sun Feb 27 09:33:32 2011 : Debug: Going to the next request
Sun Feb 27 09:33:32 2011 : Debug: Waking up in 4.0 seconds.
rad_recv: Access-Request packet from host 172.23.35.62 port 62548, id=6, length=238
        User-Name = "data1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020600701500170301002047cfbb9ac28929c0252c75bc4a716895ca1c869bbf3bced77fd26aeefe7f480f1703010040d981127601e65a2d949a143f30f6e9d261afc9b0c07edaf0eb66799536673ebdafe3762a7321cff3bf0414f69aea1999d29dd44d7f36a31c560b4ec0ad969d39
        State = 0x8fea28458aec3d827bd98591604cf6d5
        Message-Authenticator = 0x6718ed7db8f26e4000dc05c198cd9120
Sun Feb 27 09:33:32 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:32 2011 : Info: ++[preprocess] returns ok
Sun Feb 27 09:33:32 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[digest] returns noop
Sun Feb 27 09:33:32 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:32 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:32 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP packet type response id 6 length 112
Sun Feb 27 09:33:32 2011 : Info: [eap] Continuing tunnel setup.
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:32 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:32 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:32 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP/ttls
Sun Feb 27 09:33:32 2011 : Info: [eap] processing type ttls
Sun Feb 27 09:33:32 2011 : Info: [ttls] Authenticate
Sun Feb 27 09:33:32 2011 : Info: [ttls] processing EAP-TLS
Sun Feb 27 09:33:32 2011 : Info: [ttls] eaptls_verify returned 7 
Sun Feb 27 09:33:32 2011 : Info: [ttls] Done initial handshake
Sun Feb 27 09:33:32 2011 : Info: [ttls] eaptls_process returned 7 
Sun Feb 27 09:33:32 2011 : Info: [ttls] Session established.  Proceeding to decode tunneled attributes.
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled request
        EAP-Message = 0x0201001604106937fd40f5f6f47b3476557c52589a76
        FreeRADIUS-Proxied-To = 127.0.0.1
Sun Feb 27 09:33:32 2011 : Info: [ttls] Sending tunneled request
        EAP-Message = 0x0201001604106937fd40f5f6f47b3476557c52589a76
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "data1"
        State = 0x53b40ffc53b50b4f58ec2c3fa0e0d49d
server inner-tunnel {
Sun Feb 27 09:33:32 2011 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
Sun Feb 27 09:33:32 2011 : Info: +- entering group authorize {...}
Sun Feb 27 09:33:32 2011 : Info: ++[chap] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[mschap] returns noop
Sun Feb 27 09:33:32 2011 : Info: [suffix] No '@' in User-Name = "data1", looking up realm NULL
Sun Feb 27 09:33:32 2011 : Info: [suffix] No such realm "NULL"
Sun Feb 27 09:33:32 2011 : Info: ++[suffix] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[control] returns noop
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP packet type response id 1 length 22
Sun Feb 27 09:33:32 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns updated
Sun Feb 27 09:33:32 2011 : Info: [files] users: Matched entry data1 at line 79
Sun Feb 27 09:33:32 2011 : Info: ++[files] returns ok
Sun Feb 27 09:33:32 2011 : Info: ++[expiration] returns noop
Sun Feb 27 09:33:32 2011 : Info: ++[logintime] returns noop
Sun Feb 27 09:33:32 2011 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Sun Feb 27 09:33:32 2011 : Info: ++[pap] returns noop
Sun Feb 27 09:33:32 2011 : Info: Found Auth-Type = EAP
Sun Feb 27 09:33:32 2011 : Info: # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
Sun Feb 27 09:33:32 2011 : Info: +- entering group authenticate {...}
Sun Feb 27 09:33:32 2011 : Info: [eap] Request found, released from the list
Sun Feb 27 09:33:32 2011 : Info: [eap] EAP/md5
Sun Feb 27 09:33:32 2011 : Info: [eap] processing type md5
Sun Feb 27 09:33:32 2011 : Info: [eap] Freeing handler
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:32 2011 : Info:   WARNING: Empty post-auth section.  Using default return values.
Sun Feb 27 09:33:32 2011 : Info: # Executing section post-auth from file /etc/raddb/sites-enabled/inner-tunnel
} # server inner-tunnel
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled reply code 2
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "4"
        EAP-Message = 0x03010004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "data1"
Sun Feb 27 09:33:32 2011 : Info: [ttls] Got tunneled Access-Accept
Sun Feb 27 09:33:32 2011 : Info: [eap] Freeing handler
Sun Feb 27 09:33:32 2011 : Debug: rlm_eap_ttls: Freeing handler for user data1
Sun Feb 27 09:33:32 2011 : Info: ++[eap] returns ok
Sun Feb 27 09:33:32 2011 : Info: # Executing section post-auth from file /etc/raddb/sites-enabled/default
Sun Feb 27 09:33:32 2011 : Info: +- entering group post-auth {...}
Sun Feb 27 09:33:32 2011 : Info: [reply_log]    expand: /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d -> /var/log/radius/radacct/172.23.35.62/reply-detail-20110227
Sun Feb 27 09:33:32 2011 : Info: [reply_log] /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /var/log/radius/radacct/172.23.35.62/reply-detail-20110227
Sun Feb 27 09:33:32 2011 : Info: [reply_log]    expand: %t -> Sun Feb 27 09:33:32 2011
Sun Feb 27 09:33:32 2011 : Info: ++[reply_log] returns ok
Sun Feb 27 09:33:32 2011 : Info: ++[exec] returns noop
Sending Access-Accept of id 6 to 172.23.35.62 port 62548
        MS-MPPE-Recv-Key = 0x57718ff5e99e08f770ee3832bd9edf5cf3f010be6f9d200e86bb9afa55ca3c45
        MS-MPPE-Send-Key = 0x946a940cd99bb88a10de103fec50b1634f14869cc8f4da3788e099d5896cf272
        EAP-Message = 0x03060004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "data1"
Sun Feb 27 09:33:32 2011 : Info: Finished request 6.
Sun Feb 27 09:33:32 2011 : Debug: Going to the next request
Sun Feb 27 09:33:32 2011 : Debug: Waking up in 3.8 seconds.
Sun Feb 27 09:33:36 2011 : Info: Cleaning up request 0 ID 0 with timestamp +29
Sun Feb 27 09:33:36 2011 : Debug: Waking up in 0.5 seconds.
Sun Feb 27 09:33:36 2011 : Info: Cleaning up request 1 ID 1 with timestamp +29
Sun Feb 27 09:33:36 2011 : Info: Cleaning up request 2 ID 2 with timestamp +29
Sun Feb 27 09:33:36 2011 : Debug: Waking up in 0.2 seconds.
Sun Feb 27 09:33:36 2011 : Info: Cleaning up request 3 ID 3 with timestamp +29
Sun Feb 27 09:33:36 2011 : Debug: Waking up in 0.1 seconds.
Sun Feb 27 09:33:37 2011 : Info: Cleaning up request 4 ID 4 with timestamp +30
Sun Feb 27 09:33:37 2011 : Info: Cleaning up request 5 ID 5 with timestamp +30
Sun Feb 27 09:33:37 2011 : Debug: Waking up in 0.1 seconds.
Sun Feb 27 09:33:37 2011 : Info: Cleaning up request 6 ID 6 with timestamp +30
Sun Feb 27 09:33:37 2011 : Info: Ready to process requests.