wierd problem with freeradius 2.1.1

12 Nov 2008

      Hi,
I have freeradius 2.1.1 configured to handle peap and ttls/mschap2 
against AD. It accepts usernames in 3 formats "DOMAIN\username", 
"username@domain" and "username". The problem is that one of the formats 
doesn't work. It can be any one of the three and can change when I 
reboot the machine where the server is running and doesn't change if I 
only restart the server itself and it can be different for different 
wireless clients. I have a similarly configured 1.1.7 and it's been 
working perfectly.

2.1.1 runs on RHEL5 (REd Hat Enterprise Linux) 64-bit and I also tried 
it on RHEL4 32-bit with the same results.
There is no reject from the server but looking at the packet trace I can 
see that instead of a TLS encrypted handshake message the client gets a 
PEAP request and replies with Deauthentication

This is a packet trace of a successful session:
    228 11:45:27.797692 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, Identity [RFC3748]
    230 11:45:27.802659 Cisco_89:9d:49        IntelCor_d6:da:d5     
EAP      Request, PEAP [Palekar]
    232 11:45:27.804773 IntelCor_d6:da:d5     Cisco_89:9d:49        
TLSv1    Client Hello
    234 11:45:27.808900 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Server Hello, Certificate, Server Hello Done
    236 11:45:27.811647 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, PEAP [Palekar]
    238 11:45:27.814901 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Server Hello, Certificate, Server Hello Done
    240 11:45:27.815646 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, PEAP [Palekar]
    242 11:45:27.818397 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Server Hello, Certificate, Server Hello Done
    244 11:45:27.820270 IntelCor_d6:da:d5     Cisco_89:9d:49        
TLSv1    Client Key Exchange, Change Cipher Spec, Encrypted Handshake 
Message
    246 11:45:27.837270 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Change Cipher Spec, Encrypted Handshake Message
    248 11:45:27.845145 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, PEAP [Palekar]
    250 11:45:27.848520 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Application Data
    252 11:45:27.849269 IntelCor_d6:da:d5     Cisco_89:9d:49        
TLSv1    Application Data
    254 11:45:27.852894 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Application Data
    256 11:45:27.862774 IntelCor_d6:da:d5     Cisco_89:9d:49        
TLSv1    Application Data

And this is unsuccessful session:
    162 16:12:11.521443 Cisco_89:9d:49        IntelCor_d6:da:d5     
EAP      Request, Identity [RFC3748]
    165 16:12:11.572735 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAPOL    Start
    167 16:12:11.573466 Cisco_89:9d:49        IntelCor_d6:da:d5     
EAP      Request, Identity [RFC3748]
    283 16:12:22.521827 IntelCor_d6:da:d5     Cisco_89:9d:49        IEEE 
802.11 QoS Null function (No data), SN=0, FN=0, Flags=.......TC
    319 16:12:25.126804 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, Identity [RFC3748]
    321 16:12:25.131179 Cisco_89:9d:49        IntelCor_d6:da:d5     
EAP      Request, PEAP [Palekar]
    323 16:12:25.132286 IntelCor_d6:da:d5     Cisco_89:9d:49        
SSL      Client Hello
    325 16:12:25.136419 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Server Hello, Certificate, Server Hello Done
    327 16:12:25.140310 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, PEAP [Palekar]
    329 16:12:25.143789 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Server Hello, Certificate, Server Hello Done
    331 16:12:25.144547 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, PEAP [Palekar]
    333 16:12:25.147047 Cisco_89:9d:49        IntelCor_d6:da:d5     
TLSv1    Server Hello, Certificate, Server Hello Done
    335 16:12:25.148670 IntelCor_d6:da:d5     Cisco_89:9d:49        
EAP      Response, PEAP [Palekar]
    337 16:12:25.151045 Cisco_89:9d:49        IntelCor_d6:da:d5     
EAP      Request, PEAP [Palekar]
    339 16:12:25.164296 IntelCor_d6:da:d5     Cisco_89:9d:49        IEEE 
802.11 Deauthentication, SN=2842, FN=0, Flags=........C

Here is an example  of a failed session from the server debug:
rad_recv: Access-Request packet from host 10.16.17.33 port 32770, 
id=254, length=378
        User-Name = "username@adelaide.edu.au"
        Calling-Station-Id = "00-1F-3B-D6-DA-D5"
        Called-Station-Id = "00-23-04-89-9D-40:dev-UofA"
        NAS-Port = 29
        NAS-IP-Address = 10.16.17.33
        NAS-Identifier = "c4404-01-lg45-d3-nt"
        Airespace-Wlan-Id = 7
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "977"
        EAP-Message = 
0x020300a719800000009d1603010098010000940301491a294895f3db20fdb54221a9e3f3d6201c394835761953775233784549a7c320d5e5e5c9f84361b56c294e147e0ff1c8402384b74f32f27b9b9e93c46b1da6440018002f00350005000ac009c00ac013c0140032003800130004010000330000001d001b0100186131303032373538406164656c616964652e6564752e6175000a00080006001700180019000b00020100
        State = 0x29bd479429be5e064d1acd012c09ab36
        Message-Authenticator = 0xf3843f7b19a689f2590496657c26c1c0
Wed Nov 12 11:24:38 2008 : Info: +- entering group authorize {...}
Wed Nov 12 11:24:38 2008 : Info: ++[preprocess] returns ok
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log] 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands 
to /var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: %t -> Wed Nov 12 
11:24:38 2008
Wed Nov 12 11:24:38 2008 : Info: ++[auth_log] returns ok
Wed Nov 12 11:24:38 2008 : Info: ++[mschap] returns noop
Wed Nov 12 11:24:38 2008 : Info: [suffix] Looking up realm 
"adelaide.edu.au" for User-Name = "username@adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Found realm "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Stripped-User-Name = 
"username"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Realm = "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Authentication realm is LOCAL.
Wed Nov 12 11:24:38 2008 : Info: ++[suffix] returns ok
Wed Nov 12 11:24:38 2008 : Info: [ntdomain] Request already proxied.  
Ignoring.
Wed Nov 12 11:24:38 2008 : Info: ++[ntdomain] returns ok
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP packet type response id 3 
length 167
Wed Nov 12 11:24:38 2008 : Info: [eap] Continuing tunnel setup.
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns ok
Wed Nov 12 11:24:38 2008 : Info: Found Auth-Type = EAP
Wed Nov 12 11:24:38 2008 : Info: +- entering group authenticate {...}
Wed Nov 12 11:24:38 2008 : Info: [eap] Request found, released from the list
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP/peap
Wed Nov 12 11:24:38 2008 : Info: [eap] processing type peap
Wed Nov 12 11:24:38 2008 : Info: [peap] processing EAP-TLS
Wed Nov 12 11:24:38 2008 : Debug:   TLS Length 157
Wed Nov 12 11:24:38 2008 : Info: [peap] Length Included
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_verify returned 11
Wed Nov 12 11:24:38 2008 : Info: [peap]     (other): before/accept 
initialization
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: before/accept 
initialization
Wed Nov 12 11:24:38 2008 : Info: [peap] <<< TLS 1.0 Handshake [length 
0098], ClientHello 
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: SSLv3 read 
client hello A
Wed Nov 12 11:24:38 2008 : Info: [peap] >>> TLS 1.0 Handshake [length 
002a], ServerHello 
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: SSLv3 write 
server hello A
Wed Nov 12 11:24:38 2008 : Info: [peap] >>> TLS 1.0 Handshake [length 
090b], Certificate 
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: SSLv3 write 
certificate A
Wed Nov 12 11:24:38 2008 : Info: [peap] >>> TLS 1.0 Handshake [length 
0004], ServerHelloDone 
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: SSLv3 write 
server done A
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: SSLv3 flush data
Wed Nov 12 11:24:38 2008 : Info: [peap]     TLS_accept: Need to read 
more data: SSLv3 read client certificate A
Wed Nov 12 11:24:38 2008 : Debug: In SSL Handshake Phase
Wed Nov 12 11:24:38 2008 : Debug: In SSL Accept mode 
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_process returned 13
Wed Nov 12 11:24:38 2008 : Info: [peap] EAPTLS_HANDLED
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns handled
Sending Access-Challenge of id 254 to 10.16.17.33 port 32770
        EAP-Message = 
0x0104040019c000000948160301002a020000260301491a294e3f610fb297f401436df8548042ce957ae530c81f6d2915e3379992bb00002f00160301090b0b0009070009040004b9308204b53082041ea00302010202033f048e300d06092a864886f70d01010505003081ec310b30090603550406130255533110300e060355040813074172697a6f6e61311330110603550407130a53636f74747364616c6531253023060355040a131c537461726669656c6420546563686e6f6c6f676965732c20496e632e3130302e060355040b1327687474703a2f2f7777772e737461726669656c64746563682e636f6d2f7265706f7369746f72793131302f
        EAP-Message = 
0x06035504031328537461726669656c64205365637572652043657274696669636174696f6e20417574686f72697479312a302806092a864886f70d010901161b70726163746963657340737461726669656c64746563682e636f6d301e170d3036313231333231333931365a170d3038313231333231333931365a3065311f301d060355040a13167261646975732e6164656c616964652e6564752e61753121301f060355040b1318446f6d61696e20436f6e74726f6c2056616c696461746564311f301d060355040313167261646975732e6164656c616964652e6564752e617530819f300d06092a864886f70d010101050003818d003081890281
        EAP-Message = 
0x8100d7fbf50a4906fe53cda9cb3597730e36b640eaad16028c68cc317ec62b4c9d2351ba870cb637a42f51f30c29ba6ee783df929b0a430589c9e719ad6f35be2fa2ef652e78f202201aef69a218ff9c7a88abb3caf692912d3e3be9e97f2d027906627102787b3f4229a5fc0ce71daa1a5688b489b0590cf631297649b57e1021af0203010001a38201e9308201e530090603551d1304023000300b0603551d0f0404030205a0301d0603551d250416301406082b0601050507030106082b0601050507030230560603551d1f044f304d304ba049a0478645687474703a2f2f6365727469666963617465732e737461726669656c64746563682e636f
        EAP-Message = 
0x6d2f7265706f7369746f72792f737461726669656c6469737375696e672e63726c30520603551d20044b30493047060b6086480186fd6d010717013038303606082b06010505070201162a687474703a2f2f6365727469666963617465732e676f64616464792e636f6d2f7265706f7369746f727930818006082b0601050507010104743072302906082b06010505073001861d687474703a2f2f6f6373702e737461726669656c64746563682e636f6d304506082b060105050730028639687474703a2f2f6365727469666963617465732e676f64616464792e636f6d2f7265706f7369746f72792f73665f69737375696e672e637274301d060355
        EAP-Message = 0x1d0e04160414fe709c5e71bf
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x29bd479428b95e064d1acd012c09ab36
Wed Nov 12 11:24:38 2008 : Info: Finished request 45.
Wed Nov 12 11:24:38 2008 : Debug: Going to the next request
Wed Nov 12 11:24:38 2008 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.16.17.33 port 32770, 
id=255, length=217
        User-Name = "username@adelaide.edu.au"
        Calling-Station-Id = "00-1F-3B-D6-DA-D5"
        Called-Station-Id = "00-23-04-89-9D-40:dev-UofA"
        NAS-Port = 29
        NAS-IP-Address = 10.16.17.33
        NAS-Identifier = "c4404-01-lg45-d3-nt"
        Airespace-Wlan-Id = 7
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "977"
        EAP-Message = 0x020400061900
        State = 0x29bd479428b95e064d1acd012c09ab36
        Message-Authenticator = 0xf2794b5e43df427c07ab233e76e5ae0f
Wed Nov 12 11:24:38 2008 : Info: +- entering group authorize {...}
Wed Nov 12 11:24:38 2008 : Info: ++[preprocess] returns ok
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log] 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands 
to /var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: %t -> Wed Nov 12 
11:24:38 2008
Wed Nov 12 11:24:38 2008 : Info: ++[auth_log] returns ok
Wed Nov 12 11:24:38 2008 : Info: ++[mschap] returns noop
Wed Nov 12 11:24:38 2008 : Info: [suffix] Looking up realm 
"adelaide.edu.au" for User-Name = "username@adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Found realm "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Stripped-User-Name = 
"username"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Realm = "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Authentication realm is LOCAL.
Wed Nov 12 11:24:38 2008 : Info: ++[suffix] returns ok
Wed Nov 12 11:24:38 2008 : Info: [ntdomain] Request already proxied.  
Ignoring.
Wed Nov 12 11:24:38 2008 : Info: ++[ntdomain] returns ok
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP packet type response id 4 
length 6
Wed Nov 12 11:24:38 2008 : Info: [eap] Continuing tunnel setup.
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns ok
Wed Nov 12 11:24:38 2008 : Info: Found Auth-Type = EAP
Wed Nov 12 11:24:38 2008 : Info: +- entering group authenticate {...}
Wed Nov 12 11:24:38 2008 : Info: [eap] Request found, released from the list
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP/peap
Wed Nov 12 11:24:38 2008 : Info: [eap] processing type peap
Wed Nov 12 11:24:38 2008 : Info: [peap] processing EAP-TLS
Wed Nov 12 11:24:38 2008 : Info: [peap] Received TLS ACK
Wed Nov 12 11:24:38 2008 : Info: [peap] ACK handshake fragment handler
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_verify returned 1
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_process returned 13
Wed Nov 12 11:24:38 2008 : Info: [peap] EAPTLS_HANDLED
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns handled
Sending Access-Challenge of id 255 to 10.16.17.33 port 32770
        EAP-Message = 
0x010503fc1940137b8a796c791f63339cc98f1d7e301f0603551d23041830168014ac55deb7ea13ebfc9868e253601ef1253e8ceee7303d0603551d110436303482167261646975732e6164656c616964652e6564752e6175821a7777772e7261646975732e6164656c616964652e6564752e6175300d06092a864886f70d010105050003818100029139d07b6cae175ece69c94e0e5c8d4505577787beb56df5b14c2086a078c1e8565a656b3165ad14078cde6ad2dfe34172b2b9d94296e8880e1639729ae30997b70330a191278675379c25005a767105d3bbf27c1d134dcff7a23ef8f5b8b39f724cf468b03a35964f97e3a97b40e1cbc6b8e177f9
        EAP-Message = 
0x992b30457d2fbaf4407e00044530820441308203aaa00302010202020104300d06092a864886f70d01010505003081bb312430220603550407131b56616c69436572742056616c69646174696f6e204e6574776f726b31173015060355040a130e56616c69436572742c20496e632e31353033060355040b132c56616c694365727420436c617373203220506f6c6963792056616c69646174696f6e20417574686f726974793121301f06035504031318687474703a2f2f7777772e76616c69636572742e636f6d2f3120301e06092a864886f70d0109011611696e666f4076616c69636572742e636f6d301e170d3034303131343231303532315a17
        EAP-Message = 
0x0d3234303130393231303532315a3081ec310b30090603550406130255533110300e060355040813074172697a6f6e61311330110603550407130a53636f74747364616c6531253023060355040a131c537461726669656c6420546563686e6f6c6f676965732c20496e632e3130302e060355040b1327687474703a2f2f7777772e737461726669656c64746563682e636f6d2f7265706f7369746f72793131302f06035504031328537461726669656c64205365637572652043657274696669636174696f6e20417574686f72697479312a302806092a864886f70d010901161b70726163746963657340737461726669656c64746563682e636f6d
        EAP-Message = 
0x30819d300d06092a864886f70d010101050003818b0030818702818100db11436bdcd169785949e86e74140874116c7eb72aa822d8423c7acf9f50b246aea6671a2322be0fb334fbacac90aa5b28c270f6b68a802ae09b9c52e091a872a016e1c44e7d1109b39eb9d4f3b250c46d4808bdbc2a970c6da38a6a3c9acf4a34dc1edeea5a26c0a1a282a94afb862212903ab282d492919fa9459fc3a4dbfb020103a38201213082011d300c0603551d13040530030101ff300b0603551d0f040403020106304a0603551d1f04433041303fa03da03b8639687474703a2f2f6365727469666963617465732e737461726669656c64746563682e636f6d2f72
        EAP-Message = 0x65706f7369746f72
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x29bd47942bb85e064d1acd012c09ab36
Wed Nov 12 11:24:38 2008 : Info: Finished request 46.
Wed Nov 12 11:24:38 2008 : Debug: Going to the next request
Wed Nov 12 11:24:38 2008 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.16.17.33 port 32770, id=0, 
length=217
        User-Name = "username@adelaide.edu.au"
        Calling-Station-Id = "00-1F-3B-D6-DA-D5"
        Called-Station-Id = "00-23-04-89-9D-40:dev-UofA"
        NAS-Port = 29
        NAS-IP-Address = 10.16.17.33
        NAS-Identifier = "c4404-01-lg45-d3-nt"
        Airespace-Wlan-Id = 7
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "977"
        EAP-Message = 0x020500061900
        State = 0x29bd47942bb85e064d1acd012c09ab36
        Message-Authenticator = 0x0d141b37c603c7d45fa85a8a89de8c6c
Wed Nov 12 11:24:38 2008 : Info: +- entering group authorize {...}
Wed Nov 12 11:24:38 2008 : Info: ++[preprocess] returns ok
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log] 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands 
to /var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: %t -> Wed Nov 12 
11:24:38 2008
Wed Nov 12 11:24:38 2008 : Info: ++[auth_log] returns ok
Wed Nov 12 11:24:38 2008 : Info: ++[mschap] returns noop
Wed Nov 12 11:24:38 2008 : Info: [suffix] Looking up realm 
"adelaide.edu.au" for User-Name = "username@adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Found realm "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Stripped-User-Name = 
"username"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Realm = "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Authentication realm is LOCAL.
Wed Nov 12 11:24:38 2008 : Info: ++[suffix] returns ok
Wed Nov 12 11:24:38 2008 : Info: [ntdomain] Request already proxied.  
Ignoring.
Wed Nov 12 11:24:38 2008 : Info: ++[ntdomain] returns ok
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP packet type response id 5 
length 6
Wed Nov 12 11:24:38 2008 : Info: [eap] Continuing tunnel setup.
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns ok
Wed Nov 12 11:24:38 2008 : Info: Found Auth-Type = EAP
Wed Nov 12 11:24:38 2008 : Info: +- entering group authenticate {...}
Wed Nov 12 11:24:38 2008 : Info: [eap] Request found, released from the list
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP/peap
Wed Nov 12 11:24:38 2008 : Info: [eap] processing type peap
Wed Nov 12 11:24:38 2008 : Info: [peap] processing EAP-TLS
Wed Nov 12 11:24:38 2008 : Info: [peap] Received TLS ACK
Wed Nov 12 11:24:38 2008 : Info: [peap] ACK handshake fragment handler
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_verify returned 1
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_process returned 13
Wed Nov 12 11:24:38 2008 : Info: [peap] EAPTLS_HANDLED
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns handled
Sending Access-Challenge of id 0 to 10.16.17.33 port 32770
        EAP-Message = 
0x010601621900792f726f6f742e63726c304f0603551d20044830463044060b6086480186f845010717033035303306082b060105050702011627687474703a2f2f7777772e737461726669656c64746563682e636f6d2f7265706f7369746f7279303906082b06010505070101042d302b302906082b06010505073001861d687474703a2f2f6f6373702e737461726669656c64746563682e636f6d301d0603551d0e04160414ac55deb7ea13ebfc9868e253601ef1253e8ceee730090603551d2304023000300d06092a864886f70d0101050500038181007e1c98bead038d2585ee7c9088222bfe27f442b2ec7fb5fc726805a47d91ef28d17d2039
        EAP-Message = 
0x3b790837681852d58f03d2894f1e11d1e9a5744bfc5f67658471847859b7d6c9d7d79335e613ab943c8e9340898cc0d7f2e70752d1708f988ceba06dd1365390a08f16301edec3bf7f46a5952af9c8de3bdb77f4f232b13361a2303516030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x29bd47942abb5e064d1acd012c09ab36
Wed Nov 12 11:24:38 2008 : Info: Finished request 47.
Wed Nov 12 11:24:38 2008 : Debug: Going to the next request
Wed Nov 12 11:24:38 2008 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.16.17.33 port 32770, id=1, 
length=217
        User-Name = "username@adelaide.edu.au"
        Calling-Station-Id = "00-1F-3B-D6-DA-D5"
        Called-Station-Id = "00-23-04-89-9D-40:dev-UofA"
        NAS-Port = 29
        NAS-IP-Address = 10.16.17.33
        NAS-Identifier = "c4404-01-lg45-d3-nt"
        Airespace-Wlan-Id = 7
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "977"
        EAP-Message = 0x020600061900
        State = 0x29bd47942abb5e064d1acd012c09ab36
        Message-Authenticator = 0x17ceb443a291e862980fc4971fdc4a91
Wed Nov 12 11:24:38 2008 : Info: +- entering group authorize {...}
Wed Nov 12 11:24:38 2008 : Info: ++[preprocess] returns ok
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log] 
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands 
to /var/log/radius/radacct/10.16.17.33/auth-detail-20081112
Wed Nov 12 11:24:38 2008 : Info: [auth_log]     expand: %t -> Wed Nov 12 
11:24:38 2008
Wed Nov 12 11:24:38 2008 : Info: ++[auth_log] returns ok
Wed Nov 12 11:24:38 2008 : Info: ++[mschap] returns noop
Wed Nov 12 11:24:38 2008 : Info: [suffix] Looking up realm 
"adelaide.edu.au" for User-Name = "username@adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Found realm "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Stripped-User-Name = 
"username"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Adding Realm = "adelaide.edu.au"
Wed Nov 12 11:24:38 2008 : Info: [suffix] Authentication realm is LOCAL.
Wed Nov 12 11:24:38 2008 : Info: ++[suffix] returns ok
Wed Nov 12 11:24:38 2008 : Info: [ntdomain] Request already proxied.  
Ignoring.
Wed Nov 12 11:24:38 2008 : Info: ++[ntdomain] returns ok
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP packet type response id 6 
length 6
Wed Nov 12 11:24:38 2008 : Info: [eap] Continuing tunnel setup.
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns ok
Wed Nov 12 11:24:38 2008 : Info: Found Auth-Type = EAP
Wed Nov 12 11:24:38 2008 : Info: +- entering group authenticate {...}
Wed Nov 12 11:24:38 2008 : Info: [eap] Request found, released from the list
Wed Nov 12 11:24:38 2008 : Info: [eap] EAP/peap
Wed Nov 12 11:24:38 2008 : Info: [eap] processing type peap
Wed Nov 12 11:24:38 2008 : Info: [peap] processing EAP-TLS
Wed Nov 12 11:24:38 2008 : Info: [peap] Received TLS ACK
Wed Nov 12 11:24:38 2008 : Info: [peap] ACK handshake fragment handler
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_verify returned 1
Wed Nov 12 11:24:38 2008 : Info: [peap] eaptls_process returned 13
Wed Nov 12 11:24:38 2008 : Info: [peap] EAPTLS_HANDLED
Wed Nov 12 11:24:38 2008 : Info: ++[eap] returns handled
Sending Access-Challenge of id 1 to 10.16.17.33 port 32770
        EAP-Message = 0x010700061900
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x29bd47942dba5e064d1acd012c09ab36
Wed Nov 12 11:24:38 2008 : Info: Finished request 48.
Wed Nov 12 11:24:38 2008 : Debug: Going to the next request
Wed Nov 12 11:24:38 2008 : Debug: Waking up in 4.9 seconds.
Wed Nov 12 11:24:43 2008 : Info: Cleaning up request 44 ID 253 with 
timestamp +1137
Wed Nov 12 11:24:43 2008 : Info: Cleaning up request 45 ID 254 with 
timestamp +1137
Wed Nov 12 11:24:43 2008 : Info: Cleaning up request 46 ID 255 with 
timestamp +1137
Wed Nov 12 11:24:43 2008 : Info: Cleaning up request 47 ID 0 with 
timestamp +1137
Wed Nov 12 11:24:43 2008 : Info: Cleaning up request 48 ID 1 with 
timestamp +1137
Wed Nov 12 11:24:43 2008 : Debug: Ready to process requests.

Any help would be appreciated

--
Anatoli

wierd problem with freeradius 2.1.1

Anatoli Logvinski