Freeradius and winbind problem

3 Aug 2009

      I have a problem with my freeradius installed on a Debian Lenny :
I want to use PEAP with Active Directory. It works fine during a few 
minutes.
After that, freeradius don't send the Access-Accept, it seems it waits 
for a response which never comes.
I must restart winbind daemon and freeradius to succeed an authentification.

The client is Aruba, but I have tested with Netgear with the same result.

Here is the debug when it doesn't work and after when it works :

rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=189, length=173
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020100130141434d535c6a686d6f6e6c6f7264
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0x21e1615eabadbb261c919283b3f5c77c
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:20 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 1 length 19
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
rlm_pap: WARNING! No "known good" password found for the user.  
Authentication may fail because of this.
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: EAP Identity
  rlm_eap: processing type tls
  rlm_eap_tls: Initiate
  rlm_eap_tls: Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 189 to 10.254.0.32 port 32822
        EAP-Message = 0x010200061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1867aeb710f826cb3d04781dae
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=190, length=252
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x0202005019800000004616030100410100003d03014a76aea459001bbf5e7c46d2faf33b74835c5f446843ed2fe97a84f4d5380fa300001600040005000a000900640062000300060013001200630100
        State = 0x67acae1867aeb710f826cb3d04781dae
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0xebe44d56018b2078dc05fd10b49363ea
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:20 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 2 length 80
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  TLS Length 70
rlm_eap_tls:  Length Included
  eaptls_verify returned 11
    (other): before/accept initialization
    TLS_accept: before/accept initialization
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0041], ClientHello
    TLS_accept: SSLv3 read client hello A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello
    TLS_accept: SSLv3 write server hello A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 06fa], Certificate
    TLS_accept: SSLv3 write certificate A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
    TLS_accept: SSLv3 write server done A
    TLS_accept: SSLv3 flush data
    TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
  eaptls_process returned 13
  rlm_eap_peap: EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 190 to 10.254.0.32 port 32822
        EAP-Message = 
0x0103040019c000000757160301004a0200004603014a76aea439fe1adad0be15346fa9ddb8a2d4a2f98c906b8c279870926a73bd9e20684cafb03aa6b70221b0faa4f14e7a5ef2d5a7927a97cfdc560d0ac5b580b7b200040016030106fa0b0006f60006f30003243082032030820289a003020102020104300d06092a864886f70d010104050030819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a130441434d53310b3009060355040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f72
        EAP-Message = 
0x6974793126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e6672301e170d3039303531323037303233315a170d3139303531303037303233315a3070310b3009060355040613024652310f300d060355040813064672616e6365310d300b060355040a130441434d5331193017060355040313106c2d726164697573312e48512e444f4d3126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e667230820122300d06092a864886f70d01010105000382010f003082010a0282010100b591a1d3adb4e4ea8041108e8b7858638f181e1b0c9439ae22b6dd85f754c9
        EAP-Message = 
0x5a0cb03b3a5f5e44294598d31b1e69590452621253f761f2986999ef6e7814965bf0cbe10b16e0295fb88efc68979772f5053ba685d9af99b39994cbf17accde0831c26685960431dc4ac3696bf061ff0496a142ce2a576ad16c66c766cfe47038139a0584effb5bd1f63e502ae117e5286c79ad82192194bace81564e2c0ee5217b277a6969fd865a19152913cf50718ab09ccf01375bc1d5e7d501be14882cc1932693221a3274898e2d7387ced11b273c72d69a7719df1e43df7b6f54e7b70e9f3d91f216dcf1499e7ed37299fc3a982410737cde9ae04d76ab4053be800b0f0203010001a317301530130603551d25040c300a06082b0601050507
        EAP-Message = 
0x0301300d06092a864886f70d010104050003818100628fd16c16c9ca25d9fd4bf42b45dd9d1bba1b64146625d572b86a97e6c3780315511194fcf2510c4ce99393e61a63af985e6eb48438e8ef10d1f56f0380f626d9290e6b30f3459aa1ee66ae0556c5f5971a603343af9472105cabfb70eb144cb043f5cfadcc3a536f44bf3cd98c2bbb63af699594956609f75af9c9cadfe4e40003c9308203c53082032ea003020102020900ad028a9e72fb0f0a300d06092a864886f70d010104050030819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a13
        EAP-Message = 0x0441434d53310b3009060355
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1866afb710f826cb3d04781dae
Finished request 4.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=191, length=178
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020300061900
        State = 0x67acae1866afb710f826cb3d04781dae
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0x69b0156bc0eb57e635cba7dbdc059fcf
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:20 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 3 length 6
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
  rlm_eap_tls: ack handshake fragment handler
  eaptls_verify returned 1
  eaptls_process returned 13
  rlm_eap_peap: EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 191 to 10.254.0.32 port 32822
        EAP-Message = 
0x010403671900040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f726974793126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e6672301e170d3036303232383134323835375a170d3236303232333134323835375a30819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a130441434d53310b3009060355040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f726974793126302406092a
        EAP-Message = 
0x864886f70d0109011617706f73746d61737465724061636d732e6173736f2e667230819f300d06092a864886f70d010101050003818d0030818902818100bc7d9f74ab64f276ac4c0059fbb63dd341d6e3f6938bbcc1d18614b5218a137322253da30d2c08e67d48425c192b3693766807b794f928a931adbe115181bc8f00941de778eb402079cce8298e0dd0fe6e80921db123209728442395c238c2902ac3dc5b9f23d239fadea85e62cabd30a3c6cdb162c46fd51e6d386ba868a3390203010001a382010730820103301d0603551d0e041604149cbb859d57389413b3def35ced857b46105dc5de3081d30603551d230481cb3081c880149cbb85
        EAP-Message = 
0x9d57389413b3def35ced857b46105dc5dea181a4a481a130819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a130441434d53310b3009060355040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f726974793126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e6672820900ad028a9e72fb0f0a300c0603551d13040530030101ff300d06092a864886f70d0101040500038181001b0a6fb0e890320aadf9c0baa7f3ca810ad2c8e6f246bdeadc
        EAP-Message = 
0xcda483532b27e5fb39164b2e3db6fb717f8534442e9efd065309d0e6c9d1a6e90c2fba2b7beb1e72f794bcccd2fc95190c65d9e97d1d37089610db9f6238adff67a1a2c818bd2e7ad5707603d6eb25e47681a57aceda1d2e2ea0e9ced9ba61c463f671a1b1d2f716030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1865a8b710f826cb3d04781dae
Finished request 5.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=192, length=494
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x0204014019800000013616030101061000010201006246ea1f8687d388d33a330d27ac41af039202ed25cc671b6c3b8feb6c70e61b80b965c252763ae7ad471ddf2019e8350ee0ee2562198dfdcf9280f8d44be13abbd17c2cf3c54daa125da6def0eab93a83a47ffcd4f183d3b44784edbbfab51f8db3c18cfaae60c6e2d25e398a1b57aaad2b97279c9501bef114811f2a617268718db187b5989b1f584752479c2a645877ff7ce68781e79dec1ca2c436d35d6497e0618fd1608c5b9b884569a3178c0baeeabb32a14b5c1c134adb18058ed373874a666e31a6a0a46220b63c275732db13abba3450b09ec624a2bf920f7a82439104b46d7ec901d1
        EAP-Message = 
0x40d0e6c361ac05a3d36a80be2c6097880ce35f69b19a5dbe1403010001011603010020c9efd83f8f0f46b740068191ae62591016a0d2039264d4e4dc79cc4377557e15
        State = 0x67acae1865a8b710f826cb3d04781dae
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0xf3f7bf3ef7829cbf5076a085ad37306e
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:20 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 4 length 253
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  TLS Length 310
rlm_eap_tls:  Length Included
  eaptls_verify returned 11
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
    TLS_accept: SSLv3 read client key exchange A
  rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001]
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished
    TLS_accept: SSLv3 read finished A
  rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001]
    TLS_accept: SSLv3 write change cipher spec A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished
    TLS_accept: SSLv3 write finished A
    TLS_accept: SSLv3 flush data
    (other): SSL negotiation finished successfully
SSL Connection Established
  eaptls_process returned 13
  rlm_eap_peap: EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 192 to 10.254.0.32 port 32822
        EAP-Message = 
0x01050031190014030100010116030100207740a100507477c1f718fb32124193de13aaead0837f5851882e8b7972a94c0c
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1864a9b710f826cb3d04781dae
Finished request 6.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=193, length=178
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020500061900
        State = 0x67acae1864a9b710f826cb3d04781dae
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0x318ea52e0b08a88236c56460b2cd2297
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:21 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 5 length 6
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
  rlm_eap_tls: ack handshake is finished
  eaptls_verify returned 3
  eaptls_process returned 3
  rlm_eap_peap: EAPTLS_SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 193 to 10.254.0.32 port 32822
        EAP-Message = 
0x0106002019001703010015e31d9132a53caf4685e485312527c05fc62af5b815
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1863aab710f826cb3d04781dae
Finished request 7.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=194, length=214
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x0206002a1900170301001f9bdb3d417ff127d40066de4a25ba5d90e9743ec8ddd21e88b35661d661bd21
        State = 0x67acae1863aab710f826cb3d04781dae
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0x2e4b14281e38b2f5c3a3d51bd8ae5247
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:21 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 6 length 42
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: Identity - ACMS\usertest
  PEAP: Got tunneled EAP-Message
        EAP-Message = 0x020600130141434d535c6a686d6f6e6c6f7264
  PEAP: Got tunneled identity of ACMS\usertest
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to ACMS\usertest
  PEAP: Sending tunneled request
        EAP-Message = 0x020600130141434d535c6a686d6f6e6c6f7264
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "ACMS\\usertest"
server inner-tunnel {
+- entering group authorize
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
  rlm_eap: EAP packet type response id 6 length 19
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: EAP Identity
  rlm_eap: processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
  PEAP: Got tunneled reply RADIUS code 11
        EAP-Message = 
0x010700281a0107002310ba2fc1f10c107456492d749e4c51620041434d535c6a686d6f6e6c6f7264
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x410be7cb410cfdb5854c84f429fbe15f
  PEAP: Processing from tunneled session code 0x1448b50 11
        EAP-Message = 
0x010700281a0107002310ba2fc1f10c107456492d749e4c51620041434d535c6a686d6f6e6c6f7264
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x410be7cb410cfdb5854c84f429fbe15f
  PEAP: Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 194 to 10.254.0.32 port 32822
        EAP-Message = 
0x0107003f19001703010034382dac222a8cbe39aa7423d7009bbb6cc7b99e27c8055439a29cc831faa8ceaeba250bd480aac0fd08a0f6be91a630027b16f8ec
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1862abb710f826cb3d04781dae
Finished request 8.
Going to the next request
Waking up in 4.6 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, 
id=195, length=268
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 1
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0013CE8BE8A6"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x020700601900170301005519e0c573c160d61825e0c1b4263659d02f871ee7d2b94b55e02b723733d2ac9b5f608539c59e517a7ba949007f888c19ee622fe8ae2a1886cf9977c98d49b80b2f6723b75097445c5f41cac1a738e381c73e56720b
        State = 0x67acae1862abb710f826cb3d04781dae
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.3"
        Message-Authenticator = 0xc298a38a0773ca5e6f26806e0750b6f7
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 11:32:21 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 7 length 96
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: EAP type mschapv2
  PEAP: Got tunneled EAP-Message
        EAP-Message = 
0x020700491a02070044318960abe2a4d2e1fe66969c8a71bbcfaa0000000000000000767c9816c36b03b2b3d7ae686db05eb5319239da6548f01e0041434d535c6a686d6f6e6c6f7264
  PEAP: Setting User-Name to ACMS\usertest
  PEAP: Sending tunneled request
        EAP-Message = 
0x020700491a02070044318960abe2a4d2e1fe66969c8a71bbcfaa0000000000000000767c9816c36b03b2b3d7ae686db05eb5319239da6548f01e0041434d535c6a686d6f6e6c6f7264
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "ACMS\\usertest"
        State = 0x410be7cb410cfdb5854c84f429fbe15f
server inner-tunnel {
+- entering group authorize
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
  rlm_eap: EAP packet type response id 7 length 73
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/mschapv2
  rlm_eap: processing type mschapv2
+- entering group MS-CHAP
  rlm_mschap: No Cleartext-Password configured.  Cannot create LM-Password.
  rlm_mschap: No Cleartext-Password configured.  Cannot create NT-Password.
  rlm_mschap: Told to do MS-CHAPv2 for usertest with NT-Password
        expand: --domain=%{mschap:NT-Domain} -> --domain=ACMS
        expand: --username=%{mschap:User-Name} -> --username=usertest
 mschap2: ba
        expand: --challenge=%{mschap:Challenge:-00} -> 
--challenge=b3dfd0f2062ff185
        expand: --nt-response=%{mschap:NT-Response:-00} -> 
--nt-response=767c9816c36b03b2b3d7ae686db05eb5319239da6548f01e
Exec-Program output: NT_KEY: 35E241131A9A3028B30C29496120AA85
Exec-Program-Wait: plaintext: NT_KEY: 35E241131A9A3028B30C29496120AA85
Exec-Program: returned: 0
rlm_mschap: adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server inner-tunnel
  PEAP: Got tunneled reply RADIUS code 11
        EAP-Message = 
0x010800331a0307002e533d34413435444431363133373234353141303230454339443134413644423132313746334130364546
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x410be7cb4003fdb5854c84f429fbe15f
  PEAP: Processing from tunneled session code 0x1448d00 11
        EAP-Message = 
0x010800331a0307002e533d34413435444431363133373234353141303230454339443134413644423132313746334130364546
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x410be7cb4003fdb5854c84f429fbe15f
  PEAP: Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 195 to 10.254.0.32 port 32822
        EAP-Message = 
0x0108004a1900170301003f363cfc69b8eb543b309b5e3b0eeba4662d61f3f1ec8a55a0b4b401f987bcd6f1d8cf5f9e3cdc0c7d0afb0a22b49f6b0e67a301a591480f764cd0f5156c126f
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x67acae1861a4b710f826cb3d04781dae
Finished request 9.
Going to the next request
Waking up in 4.6 seconds.
Cleaning up request 3 ID 189 with timestamp +539
Cleaning up request 4 ID 190 with timestamp +539
Cleaning up request 5 ID 191 with timestamp +539
Waking up in 0.1 seconds.
Cleaning up request 6 ID 192 with timestamp +539
Waking up in 0.1 seconds.
Cleaning up request 7 ID 193 with timestamp +540
Cleaning up request 8 ID 194 with timestamp +540
Cleaning up request 9 ID 195 with timestamp +540
Ready to process requests.

Here, it works :
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=80, 
length=167
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0201001001444f4d5c6361726c696f7a
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x74ac90d2e39e6e057f970e06f8d308f6
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:35 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 1 length 16
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
rlm_pap: WARNING! No "known good" password found for the user.  
Authentication may fail because of this.
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: EAP Identity
  rlm_eap: processing type tls
  rlm_eap_tls: Initiate
  rlm_eap_tls: Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 80 to 10.254.0.32 port 32822
        EAP-Message = 0x010200061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b1d3d4b9577b19a501eee06e
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=81, 
length=281
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x0202007019800000006616030100610100005d03014a76d2cb4fcdc3ecfcf18e4f349f62ca5dff023b687e8448aa20c99d8aaa1dc02052f6239bf116d56a2f94fc6106c098bb169d635312641c10d18e36178ea6e45c001600040005000a000900640062000300060013001200630100
        State = 0xb1d1cd33b1d3d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x8a4f52d9a7d1030ca81375cb707dbbf9
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 2 length 112
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  TLS Length 102
rlm_eap_tls:  Length Included
  eaptls_verify returned 11
    (other): before/accept initialization
    TLS_accept: before/accept initialization
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0061], ClientHello
    TLS_accept: SSLv3 read client hello A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello
    TLS_accept: SSLv3 write server hello A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 06fa], Certificate
    TLS_accept: SSLv3 write certificate A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
    TLS_accept: SSLv3 write server done A
    TLS_accept: SSLv3 flush data
    TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
  eaptls_process returned 13
  rlm_eap_peap: EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 81 to 10.254.0.32 port 32822
        EAP-Message = 
0x0103040019c000000757160301004a0200004603014a76d2ccf7d4afc8a7cdbafc342ef1b377a655e92f5329cd0367ba8ef969447f20e37338d7a07f9ad5f0fb0999ed7e6af69a00fefe44d7c085de718cd53f61f04d00040016030106fa0b0006f60006f30003243082032030820289a003020102020104300d06092a864886f70d010104050030819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a130441434d53310b3009060355040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f72
        EAP-Message = 
0x6974793126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e6672301e170d3039303531323037303233315a170d3139303531303037303233315a3070310b3009060355040613024652310f300d060355040813064672616e6365310d300b060355040a130441434d5331193017060355040313106c2d726164697573312e48512e444f4d3126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e667230820122300d06092a864886f70d01010105000382010f003082010a0282010100b591a1d3adb4e4ea8041108e8b7858638f181e1b0c9439ae22b6dd85f754c9
        EAP-Message = 
0x5a0cb03b3a5f5e44294598d31b1e69590452621253f761f2986999ef6e7814965bf0cbe10b16e0295fb88efc68979772f5053ba685d9af99b39994cbf17accde0831c26685960431dc4ac3696bf061ff0496a142ce2a576ad16c66c766cfe47038139a0584effb5bd1f63e502ae117e5286c79ad82192194bace81564e2c0ee5217b277a6969fd865a19152913cf50718ab09ccf01375bc1d5e7d501be14882cc1932693221a3274898e2d7387ced11b273c72d69a7719df1e43df7b6f54e7b70e9f3d91f216dcf1499e7ed37299fc3a982410737cde9ae04d76ab4053be800b0f0203010001a317301530130603551d25040c300a06082b0601050507
        EAP-Message = 
0x0301300d06092a864886f70d010104050003818100628fd16c16c9ca25d9fd4bf42b45dd9d1bba1b64146625d572b86a97e6c3780315511194fcf2510c4ce99393e61a63af985e6eb48438e8ef10d1f56f0380f626d9290e6b30f3459aa1ee66ae0556c5f5971a603343af9472105cabfb70eb144cb043f5cfadcc3a536f44bf3cd98c2bbb63af699594956609f75af9c9cadfe4e40003c9308203c53082032ea003020102020900ad028a9e72fb0f0a300d06092a864886f70d010104050030819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a13
        EAP-Message = 0x0441434d53310b3009060355
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b0d2d4b9577b19a501eee06e
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=82, 
length=175
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020300061900
        State = 0xb1d1cd33b0d2d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x6db7cf5ed3d73d831bb04492bc36e0a8
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 3 length 6
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
  rlm_eap_tls: ack handshake fragment handler
  eaptls_verify returned 1
  eaptls_process returned 13
  rlm_eap_peap: EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 82 to 10.254.0.32 port 32822
        EAP-Message = 
0x010403671900040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f726974793126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e6672301e170d3036303232383134323835375a170d3236303232333134323835375a30819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a130441434d53310b3009060355040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f726974793126302406092a
        EAP-Message = 
0x864886f70d0109011617706f73746d61737465724061636d732e6173736f2e667230819f300d06092a864886f70d010101050003818d0030818902818100bc7d9f74ab64f276ac4c0059fbb63dd341d6e3f6938bbcc1d18614b5218a137322253da30d2c08e67d48425c192b3693766807b794f928a931adbe115181bc8f00941de778eb402079cce8298e0dd0fe6e80921db123209728442395c238c2902ac3dc5b9f23d239fadea85e62cabd30a3c6cdb162c46fd51e6d386ba868a3390203010001a382010730820103301d0603551d0e041604149cbb859d57389413b3def35ced857b46105dc5de3081d30603551d230481cb3081c880149cbb85
        EAP-Message = 
0x9d57389413b3def35ced857b46105dc5dea181a4a481a130819e310b3009060355040613024652310f300d060355040813064672616e63653111300f0603550407130853757265736e6573310d300b060355040a130441434d53310b3009060355040b13024449312730250603550403131e41434d53202d2043657274696669636174696f6e20417574686f726974793126302406092a864886f70d0109011617706f73746d61737465724061636d732e6173736f2e6672820900ad028a9e72fb0f0a300c0603551d13040530030101ff300d06092a864886f70d0101040500038181001b0a6fb0e890320aadf9c0baa7f3ca810ad2c8e6f246bdeadc
        EAP-Message = 
0xcda483532b27e5fb39164b2e3db6fb717f8534442e9efd065309d0e6c9d1a6e90c2fba2b7beb1e72f794bcccd2fc95190c65d9e97d1d37089610db9f6238adff67a1a2c818bd2e7ad5707603d6eb25e47681a57aceda1d2e2ea0e9ced9ba61c463f671a1b1d2f716030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b3d5d4b9577b19a501eee06e
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=83, 
length=491
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x020401401980000001361603010106100001020100621a6d6489a3b775a64ad3ee2f28e053794c50f912e68f4e67f03d70f8a0d1dd9dda173b2f6669f1b4c3bfdf17ae425ea3a2475b1191083540da42b1418efe2641b3a218326f60cf1b6eecd32d21409ea10079a2be923248253fd9a1c36db54260dc3562fb6c49245980d521d894763779662b0f70a32e0f48ae6b5767ea2c9e6c11409830b84f4bd3e553ee460afa486508d0e3e823fc251c6cd850cfbb1a43eecf83d5d03aed2e78f80f2e965ce7ceebf9259655c4c32d5efd88ed7a60ced5fcdaa5531be9bf7379597e25e7c37eca79eeca6ade118f9c7f904256e9f8b7d2563308f0480c8559
        EAP-Message = 
0x8942ff0c70a8c3ce206f908d3d2b3ee44fadc13d9a9f1e68140301000101160301002060d7e7fc4d412ea50f03efecf0d0cd8d01267753af8a16ff3095758ca82c3b9e
        State = 0xb1d1cd33b3d5d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x2c34b230bef2071b982d584fca5ec843
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 4 length 253
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  TLS Length 310
rlm_eap_tls:  Length Included
  eaptls_verify returned 11
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
    TLS_accept: SSLv3 read client key exchange A
  rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001]
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished
    TLS_accept: SSLv3 read finished A
  rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001]
    TLS_accept: SSLv3 write change cipher spec A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished
    TLS_accept: SSLv3 write finished A
    TLS_accept: SSLv3 flush data
    (other): SSL negotiation finished successfully
SSL Connection Established
  eaptls_process returned 13
  rlm_eap_peap: EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 83 to 10.254.0.32 port 32822
        EAP-Message = 
0x0105003119001403010001011603010020c9602cd84aa7982ac74fdd03d1b658d1fb963f2d3b8ead12ea31c58209248c2b
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b2d4d4b9577b19a501eee06e
Finished request 3.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=85, 
length=175
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020500061900
        State = 0xb1d1cd33b2d4d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x51af73ed1ede861fc06ee69ee7362ddd
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 5 length 6
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
  rlm_eap_tls: ack handshake is finished
  eaptls_verify returned 3
  eaptls_process returned 3
  rlm_eap_peap: EAPTLS_SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 85 to 10.254.0.32 port 32822
        EAP-Message = 
0x010600201900170301001514a38092da042a09a0d53f71c5db3c20253be3932a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b5d7d4b9577b19a501eee06e
Finished request 4.
Going to the next request
Waking up in 4.6 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=84, 
length=208
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x020600271900170301001c377f4b5460aaaa3ed396b66c24a6e7da327d38ffc15fdbbfa5071b7e
        State = 0xb1d1cd33b5d7d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x9458c933041125b9f6ca8610574f998f
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 6 length 39
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: Identity - ACMS\usertest
  PEAP: Got tunneled EAP-Message
        EAP-Message = 0x0206001001444f4d5c6361726c696f7a
  PEAP: Got tunneled identity of ACMS\usertest
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to ACMS\usertest
  PEAP: Sending tunneled request
        EAP-Message = 0x0206001001444f4d5c6361726c696f7a
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "ACMS\\usertest"
server inner-tunnel {
+- entering group authorize
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
  rlm_eap: EAP packet type response id 6 length 16
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: EAP Identity
  rlm_eap: processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
  PEAP: Got tunneled reply RADIUS code 11
        EAP-Message = 
0x010700251a0107002010556e70ce846691aea2c042838cb465b6444f4d5c6361726c696f7a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x5bbb7f125bbc65603c947384488c39d8
  PEAP: Processing from tunneled session code 0x1d6fa00 11
        EAP-Message = 
0x010700251a0107002010556e70ce846691aea2c042838cb465b6444f4d5c6361726c696f7a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x5bbb7f125bbc65603c947384488c39d8
  PEAP: Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 84 to 10.254.0.32 port 32822
        EAP-Message = 
0x0107003c190017030100315d3c38589f24e052410d29c4316debb268b576d1491c91397a2c2c47ed82de8d07e25f85ddbca888ce5f2f52498b00a17a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b4d6d4b9577b19a501eee06e
Finished request 5.
Going to the next request
Waking up in 4.6 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=86, 
length=262
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x0207005d19001703010052c5802a50a76626e911c84500e1b139ec0e448554c2539bfd8f2c422a750c6b46c2f45c07d81b631135434e59b0127081fbbb408133efa7d87546245dc74d5ea394ba4725db00c777e1db5649858339a6ff89
        State = 0xb1d1cd33b4d6d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0xaaba5a2f699aa217dc67dbd1ad2c1b8b
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 7 length 93
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: EAP type mschapv2
  PEAP: Got tunneled EAP-Message
        EAP-Message = 
0x020700461a0207004131b8a86f74525f79287c685926df8506b30000000000000000937766f3b6118923d4a2833ba1d198e1b0c984525ac7d57000444f4d5c6361726c696f7a
  PEAP: Setting User-Name to ACMS\usertest
  PEAP: Sending tunneled request
        EAP-Message = 
0x020700461a0207004131b8a86f74525f79287c685926df8506b30000000000000000937766f3b6118923d4a2833ba1d198e1b0c984525ac7d57000444f4d5c6361726c696f7a
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "ACMS\\usertest"
        State = 0x5bbb7f125bbc65603c947384488c39d8
server inner-tunnel {
+- entering group authorize
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
  rlm_eap: EAP packet type response id 7 length 70
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/mschapv2
  rlm_eap: processing type mschapv2
+- entering group MS-CHAP
  rlm_mschap: No Cleartext-Password configured.  Cannot create LM-Password.
  rlm_mschap: No Cleartext-Password configured.  Cannot create NT-Password.
  rlm_mschap: Told to do MS-CHAPv2 for usertest with NT-Password
        expand: --ACMSain=%{mschap:NT-ACMSain} -> --ACMSain=ACMS
        expand: --username=%{mschap:User-Name} -> --username=usertest
 mschap2: 55
        expand: --challenge=%{mschap:Challenge:-00} -> 
--challenge=b4dbd917acb3d690
        expand: --nt-response=%{mschap:NT-Response:-00} -> 
--nt-response=937766f3b6118923d4a2833ba1d198e1b0c984525ac7d570
Exec-Program output: NT_KEY: D139B35EDBE5A4E870E34920F2D63FEF
Exec-Program-Wait: plaintext: NT_KEY: D139B35EDBE5A4E870E34920F2D63FEF
Exec-Program: returned: 0
rlm_mschap: adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server inner-tunnel
  PEAP: Got tunneled reply RADIUS code 11
        EAP-Message = 
0x010800331a0307002e533d36303743343137423644323646333643423935313230443135454133304346393743383145354232
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x5bbb7f125ab365603c947384488c39d8
  PEAP: Processing from tunneled session code 0x1d48ad0 11
        EAP-Message = 
0x010800331a0307002e533d36303743343137423644323646333643423935313230443135454133304346393743383145354232
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x5bbb7f125ab365603c947384488c39d8
  PEAP: Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 86 to 10.254.0.32 port 32822
        EAP-Message = 
0x0108004a1900170301003f790d3c1318deb33bc9b0bffbdc62f89cb9ef00e48a4369d5176e082332ac0f3e1adeececf9133a24e2db88a48f131b24f96b470ad735d56aab1e398d8b1962
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b7d9d4b9577b19a501eee06e
Finished request 6.
Going to the next request
Waking up in 4.6 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=87, 
length=198
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x0208001d19001703010012c0833497cbb416bd4af4736ed09a77f33fcc
        State = 0xb1d1cd33b7d9d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0x11904e5ce88bdc7e4015519888a50038
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 8 length 29
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: EAP type mschapv2
  PEAP: Got tunneled EAP-Message
        EAP-Message = 0x020800061a03
  PEAP: Setting User-Name to ACMS\usertest
  PEAP: Sending tunneled request
        EAP-Message = 0x020800061a03
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "ACMS\\usertest"
        State = 0x5bbb7f125ab365603c947384488c39d8
server inner-tunnel {
+- entering group authorize
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
  rlm_eap: EAP packet type response id 8 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/mschapv2
  rlm_eap: processing type mschapv2
  rlm_eap: Freeing handler
++[eap] returns ok
Login OK: [ACMS\\usertest/<via Auth-Type = EAP>] (from client aruba1 
port 0 via TLS tunnel)
} # server inner-tunnel
  PEAP: Got tunneled reply RADIUS code 2
        EAP-Message = 0x03080004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "ACMS\\usertest"
  PEAP: Processing from tunneled session code 0x1d6d7f0 2
        EAP-Message = 0x03080004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "ACMS\\usertest"
  PEAP: Tunneled authentication was successful.
  rlm_eap_peap: SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 87 to 10.254.0.32 port 32822
        EAP-Message = 
0x010900261900170301001b740c352358b879b666b2617fe8fa1cb29288f5b899546d41a5655a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb1d1cd33b6d8d4b9577b19a501eee06e
Finished request 7.
Going to the next request
Waking up in 4.6 seconds.
rad_recv: Access-Request packet from host 10.254.0.32 port 32822, id=88, 
length=207
        User-Name = "ACMS\\usertest"
        NAS-IP-Address = 10.254.0.30
        NAS-Port = 2
        NAS-Identifier = "10.254.0.32"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "0018DECCECAA"
        Called-Station-Id = "000B86613054"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 
0x020900261900170301001bd911f82a6b41a035a62496200168b13d84f72b9c8b9d86ed23c3c0
        State = 0xb1d1cd33b6d8d4b9577b19a501eee06e
        Aruba-Essid-Name = "ACMS"
        Aruba-Location-Id = "254.1.2"
        Message-Authenticator = 0xc65b393765c82022a70ba974c1df2966
+- entering group authorize
++[preprocess] returns ok
        expand: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> 
/var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
rlm_detail: 
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to /var/log/freeradius/radacct/10.254.0.32/auth-detail-20090803
        expand: %t -> Mon Aug  3 14:06:36 2009
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
    rlm_realm: No '@' in User-Name = "ACMS\usertest", looking up realm NULL
    rlm_realm: No such realm "NULL"
++[suffix] returns noop
  rlm_eap: EAP packet type response id 9 length 38
  rlm_eap: Continuing tunnel setup.
++[eap] returns ok
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
+- entering group authenticate
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: Received EAP-TLV response.
  rlm_eap_peap: Success
  rlm_eap: Freeing handler
++[eap] returns ok
Login OK: [ACMS\\usertest/<via Auth-Type = EAP>] (from client aruba1 
port 2 cli 0018DECCECAA)
+- entering group post-auth
++[exec] returns noop
Sending Access-Accept of id 88 to 10.254.0.32 port 32822
        MS-MPPE-Recv-Key = 
0x695e9dd8253cf8ad3be2d108b81c7071284dce6533e98dfc3c776afd46f80a2a
        MS-MPPE-Send-Key = 
0x48dea6a783506a6d57acd8d4ae74e9911463c666e58cd632b44cb3146c832d30
        EAP-Message = 0x03090004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "ACMS\\usertest"
Finished request 8.
Going to the next request
Waking up in 4.6 seconds.
Cleaning up request 0 ID 80 with timestamp +164
Cleaning up request 1 ID 81 with timestamp +165
Cleaning up request 2 ID 82 with timestamp +165
Waking up in 0.2 seconds.
Cleaning up request 3 ID 83 with timestamp +165
Cleaning up request 4 ID 85 with timestamp +165
Cleaning up request 5 ID 84 with timestamp +165
Cleaning up request 6 ID 86 with timestamp +165
Cleaning up request 7 ID 87 with timestamp +165
Cleaning up request 8 ID 88 with timestamp +165

Thanks

Jean-Hubert Monlord