On 5/8/07, Alan DeKok <aland@deployingradius.com> wrote:
Perhaps you could explain what you mean by that. What's a "long access time"?
Excuse my english. I mean the time that passed between the user sends login information and the success authentication by the supplicant. Which doesn't include the debug output from the server. rad_recv: Access-Request packet from host 192.168.181.1:32806, id=241, length=134 User-Name = "luca.tar" EAP-Message = 0x02000012016c7563612e74617264656c6c61 Message-Authenticator = 0x52d025161d172ba39e1692bef02ef0af Calling-Station-Id = "00-1B-63-00-0C-DE" Called-Station-Id = "00-13-D4-CF-C5-1B" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 NAS-IP-Address = 0.0.0.0 NAS-Identifier = "14" Tue May 8 10:29:53 2007 : Debug: Processing the authorize section of radiusd.conf Tue May 8 10:29:53 2007 : Debug: modcall: entering group authorize for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "preprocess" returns ok for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "chap" returns noop for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "mschap" returns noop for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 497 Tue May 8 10:29:53 2007 : Debug: rlm_realm: No '@' in User-Name = " luca.tar", looking up realm NULL Tue May 8 10:29:53 2007 : Debug: rlm_realm: Found realm "NULL" Tue May 8 10:29:53 2007 : Debug: rlm_realm: Adding Stripped-User-Name = "luca.tar" Tue May 8 10:29:53 2007 : Debug: rlm_realm: Proxying request from user luca.tar to realm NULL Tue May 8 10:29:53 2007 : Debug: rlm_realm: Adding Realm = "NULL" Tue May 8 10:29:53 2007 : Debug: rlm_realm: Authentication realm is LOCAL. Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "suffix" returns noop for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 497 Tue May 8 10:29:53 2007 : Debug: rlm_eap: EAP packet type response id 0 length 18 Tue May 8 10:29:53 2007 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "eap" returns updated for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 497 Tue May 8 10:29:53 2007 : Debug: users: Matched entry DEFAULT at line 154 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Entering ldap_groupcmp() Tue May 8 10:29:53 2007 : Debug: radius_xlat: 'ou=stat,dc=univ,dc=il' Tue May 8 10:29:53 2007 : Debug: radius_xlat: '(uid=luca.tar)' Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (uid=luca.tar) Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: radius_xlat: '(|(&(objectClass=GroupOfNames)(member=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil))(&(objectClass=GroupOfUniqueNames)(uniquemember=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil)))' Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (&(cn=professor)(|(&(objectClass=GroupOfNames)(member=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil))(&(objectClass=GroupOfUniqueNames)(uniquemember=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil)))) Tue May 8 10:29:53 2007 : Debug: rlm_ldap: object not found or got ambiguous search result Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in cn=Luca tar,ou=faculty,ou=dspsa,ou=stat,dc=univ,dc=il, with filter (objectclass=*) Tue May 8 10:29:53 2007 : Debug: rlm_ldap::ldap_groupcmp: User found in group professor Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: users: Matched entry DEFAULT at line 176 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "files" returns ok for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 497 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: - authorize Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing user authorization for luca.tar Tue May 8 10:29:53 2007 : Debug: radius_xlat: '(uid=luca.tar)' Tue May 8 10:29:53 2007 : Debug: radius_xlat: 'ou=stat,dc=univ,dc=il' Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (uid=luca.tar) Tue May 8 10:29:53 2007 : Debug: rlm_ldap: checking if remote access for luca.tar is allowed by userPassword Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Added password PASSWORD in check items Tue May 8 10:29:53 2007 : Debug: rlm_ldap: looking for check items in directory... Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusGroupName as Ldap-Group, value professor & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusCallingStationId as Calling-Station-Id, value 00-0C-F1-18-64-E5 & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusCallingStationId as Calling-Station-Id, value 00-1B-63-00-0C-DE & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding userPassword as User-Password, value PASSWORD & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: looking for reply items in directory... Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusFilterId as Filter-Id, value 98 & op=11 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: user luca.tar authorized to use remote access Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "ldap" returns ok for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling checkval (rlm_checkval) for request 497 Tue May 8 10:29:53 2007 : Debug: rlm_checkval: Item Name: Calling-Station-Id, Value: 00-1B-63-00-0C-DE Tue May 8 10:29:53 2007 : Debug: rlm_checkval: Value Name: Calling-Station-Id, Value: 00-0C-F1-18-64-E5 Tue May 8 10:29:53 2007 : Debug: rlm_checkval: Value Name: Calling-Station-Id, Value: 00-1B-63-00-0C-DE Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from checkval (rlm_checkval) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "checkval" returns ok for request 497 Tue May 8 10:29:53 2007 : Debug: modcall: leaving group authorize (returns updated) for request 497 Tue May 8 10:29:53 2007 : Debug: rad_check_password: Found Auth-Type EAP Tue May 8 10:29:53 2007 : Debug: auth: type "EAP" Tue May 8 10:29:53 2007 : Debug: Processing the authenticate section of radiusd.conf Tue May 8 10:29:53 2007 : Debug: modcall: entering group authenticate for request 497 Tue May 8 10:29:53 2007 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 497 Tue May 8 10:29:53 2007 : Debug: rlm_eap: EAP Identity Tue May 8 10:29:53 2007 : Debug: rlm_eap: processing type tls Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: Initiate Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: Start returned 1 Tue May 8 10:29:53 2007 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 497 Tue May 8 10:29:53 2007 : Debug: modcall[authenticate]: module "eap" returns handled for request 497 Tue May 8 10:29:53 2007 : Debug: modcall: leaving group authenticate (returns handled) for request 497 Sending Access-Challenge of id 241 to 192.168.181.1 port 32806 Service-Type == Framed-User Filter-Id = "98" EAP-Message = 0x010100061920 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2db3a8c4fdfacad0a63ed88cb91f69a9 Tue May 8 10:29:53 2007 : Debug: Finished request 497 Tue May 8 10:29:53 2007 : Debug: Going to the next request Tue May 8 10:29:53 2007 : Debug: --- Walking the entire request list --- Tue May 8 10:29:53 2007 : Debug: Waking up in 6 seconds... rad_recv: Access-Request packet from host 192.168.181.1:32806, id=242, length=284 User-Name = "luca.tar" State = 0x2db3a8c4fdfacad0a63ed88cb91f69a9 EAP-Message = 0x0201009619800000008c1603010087010000830301464035e41ea33c0757d3137d926f9650e52bb43eb4f95e02971d6cf5b3e53740204162bc29a02118b82d65caf9b96ef014362bd9cf2a87224606e7ce317c99fd91003c002f000500040035000aff830009ff82000300080006ff8000320033003400380039003a0016001500140013001200110018001b001a0017001900010100 Message-Authenticator = 0x9fbe0741fb651146f161e55908be0246 Calling-Station-Id = "00-1B-63-00-0C-DE" Called-Station-Id = "00-13-D4-CF-C5-1B" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 NAS-IP-Address = 0.0.0.0 NAS-Identifier = "14" Tue May 8 10:29:53 2007 : Debug: Processing the authorize section of radiusd.conf Tue May 8 10:29:53 2007 : Debug: modcall: entering group authorize for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "preprocess" returns ok for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "chap" returns noop for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "mschap" returns noop for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 498 Tue May 8 10:29:53 2007 : Debug: rlm_realm: No '@' in User-Name = " luca.tar", looking up realm NULL Tue May 8 10:29:53 2007 : Debug: rlm_realm: Found realm "NULL" Tue May 8 10:29:53 2007 : Debug: rlm_realm: Adding Stripped-User-Name = "luca.tar" Tue May 8 10:29:53 2007 : Debug: rlm_realm: Proxying request from user luca.tar to realm NULL Tue May 8 10:29:53 2007 : Debug: rlm_realm: Adding Realm = "NULL" Tue May 8 10:29:53 2007 : Debug: rlm_realm: Authentication realm is LOCAL. Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "suffix" returns noop for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 498 Tue May 8 10:29:53 2007 : Debug: rlm_eap: EAP packet type response id 1 length 150 Tue May 8 10:29:53 2007 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "eap" returns updated for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 498 Tue May 8 10:29:53 2007 : Debug: users: Matched entry DEFAULT at line 154 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Entering ldap_groupcmp() Tue May 8 10:29:53 2007 : Debug: radius_xlat: 'ou=stat,dc=univ,dc=il' Tue May 8 10:29:53 2007 : Debug: radius_xlat: '(uid=luca.tar)' Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (uid=luca.tar) Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: radius_xlat: '(|(&(objectClass=GroupOfNames)(member=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil))(&(objectClass=GroupOfUniqueNames)(uniquemember=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil)))' Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (&(cn=professor)(|(&(objectClass=GroupOfNames)(member=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil))(&(objectClass=GroupOfUniqueNames)(uniquemember=cn\3dLuca tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil)))) Tue May 8 10:29:53 2007 : Debug: rlm_ldap: object not found or got ambiguous search result Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in cn=Luca tar,ou=faculty,ou=dspsa,ou=stat,dc=univ,dc=il, with filter (objectclass=*) Tue May 8 10:29:53 2007 : Debug: rlm_ldap::ldap_groupcmp: User found in group professor Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: users: Matched entry DEFAULT at line 176 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "files" returns ok for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 498 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: - authorize Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing user authorization for luca.tar Tue May 8 10:29:53 2007 : Debug: radius_xlat: '(uid=luca.tar)' Tue May 8 10:29:53 2007 : Debug: radius_xlat: 'ou=stat,dc=univ,dc=il' Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (uid=luca.tar) Tue May 8 10:29:53 2007 : Debug: rlm_ldap: checking if remote access for luca.tar is allowed by userPassword Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Added password PASSWORD in check items Tue May 8 10:29:53 2007 : Debug: rlm_ldap: looking for check items in directory... Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusGroupName as Ldap-Group, value professor & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusCallingStationId as Calling-Station-Id, value 00-0C-F1-18-64-E5 & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusCallingStationId as Calling-Station-Id, value 00-1B-63-00-0C-DE & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding userPassword as User-Password, value PASSWORD & op=21 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: looking for reply items in directory... Tue May 8 10:29:53 2007 : Debug: rlm_ldap: Adding radiusFilterId as Filter-Id, value 98 & op=11 Tue May 8 10:29:53 2007 : Debug: rlm_ldap: user luca.tar authorized to use remote access Tue May 8 10:29:53 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "ldap" returns ok for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: calling checkval (rlm_checkval) for request 498 Tue May 8 10:29:53 2007 : Debug: rlm_checkval: Item Name: Calling-Station-Id, Value: 00-1B-63-00-0C-DE Tue May 8 10:29:53 2007 : Debug: rlm_checkval: Value Name: Calling-Station-Id, Value: 00-0C-F1-18-64-E5 Tue May 8 10:29:53 2007 : Debug: rlm_checkval: Value Name: Calling-Station-Id, Value: 00-1B-63-00-0C-DE Tue May 8 10:29:53 2007 : Debug: modsingle[authorize]: returned from checkval (rlm_checkval) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authorize]: module "checkval" returns ok for request 498 Tue May 8 10:29:53 2007 : Debug: modcall: leaving group authorize (returns updated) for request 498 Tue May 8 10:29:53 2007 : Debug: rad_check_password: Found Auth-Type EAP Tue May 8 10:29:53 2007 : Debug: auth: type "EAP" Tue May 8 10:29:53 2007 : Debug: Processing the authenticate section of radiusd.conf Tue May 8 10:29:53 2007 : Debug: modcall: entering group authenticate for request 498 Tue May 8 10:29:53 2007 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 498 Tue May 8 10:29:53 2007 : Debug: rlm_eap: Request found, released from the list Tue May 8 10:29:53 2007 : Debug: rlm_eap: EAP/peap Tue May 8 10:29:53 2007 : Debug: rlm_eap: processing type peap Tue May 8 10:29:53 2007 : Debug: rlm_eap_peap: Authenticate Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: processing TLS Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: Length Included Tue May 8 10:29:53 2007 : Debug: eaptls_verify returned 11 Tue May 8 10:29:53 2007 : Debug: (other): before/accept initialization Tue May 8 10:29:53 2007 : Debug: TLS_accept: before/accept initialization Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: <<< TLS 1.0 Handshake [length 0087], ClientHello Tue May 8 10:29:53 2007 : Debug: TLS_accept: SSLv3 read client hello A Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello Tue May 8 10:29:53 2007 : Debug: TLS_accept: SSLv3 write server hello A Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 0641], Certificate Tue May 8 10:29:53 2007 : Debug: TLS_accept: SSLv3 write certificate A Tue May 8 10:29:53 2007 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone Tue May 8 10:29:53 2007 : Debug: TLS_accept: SSLv3 write server done A Tue May 8 10:29:53 2007 : Debug: TLS_accept: SSLv3 flush data Tue May 8 10:29:53 2007 : Debug: TLS_accept: Need to read more data: SSLv3 read client certificate A Tue May 8 10:29:53 2007 : Debug: In SSL Handshake Phase Tue May 8 10:29:53 2007 : Debug: In SSL Accept mode Tue May 8 10:29:53 2007 : Debug: eaptls_process returned 13 Tue May 8 10:29:53 2007 : Debug: rlm_eap_peap: EAPTLS_HANDLED Tue May 8 10:29:53 2007 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 498 Tue May 8 10:29:53 2007 : Debug: modcall[authenticate]: module "eap" returns handled for request 498 Tue May 8 10:29:53 2007 : Debug: modcall: leaving group authenticate (returns handled) for request 498 Sending Access-Challenge of id 242 to 192.168.181.1 port 32806 Service-Type == Framed-User Filter-Id = "98" EAP-Message = 0x0102040a19c00000069e160301004a020000460301464035013422c1c8ee0915e7d8316210df5d51e664d663b43340bb2872c73fc02040af0cceb7d93c433de2b180d3aec3e26711ef612403a44f27a0cd0f0f3e7b9d002f0016030106410b00063d00063a0002a9308202a53082020ea003020102020900ca3ef53cca0b2a55300d06092a864886f70d010104050030818a310b3009060355040613024954310e300c060355040813054c617a696f310d300b06035504071304526f6d6531153013060355040a130c4f7267616e697a6174696f6e311b301906035504031312436c69656e742063657274696669636174653128302606092a864886f7 EAP-Message = 0x0d01090116196e69636f6c612e6e6f7669656c6c6f40676d61696c2e636f6d301e170d3036313132313131313430315a170d3037313132313131313430315a308184310b3009060355040613024954310e300c060355040813054c617a696f310d300b06035504071304526f6d6531153013060355040a130c4f7267616e697a6174696f6e3119301706035504031310526f6f742063657274696669636174653124302206092a864886f70d0109011615617263636173406c75672d6973636869612e6f726730819f300d06092a864886f70d010101050003818d0030818902818100c789a0bd5d6467d61d71a7d4c82b2a3a8b9b81a5d91729c9fbda EAP-Message = 0x45665740fce1c201534ca6875147be2963dfb5b5fb47d86fe063f1d00c544a604ca005a0adc875eef5d6f0fb246320c5029708c041dbb1d27f26814997813afff69b64679cc4beec97fb3645932ee5b7ca64a56c896f4b43d9d4fb3da8ee8191e455be23c6e30203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d010104050003818100674941ba438233287efc08a1095bfd4ecd565ae3d7ba3e319ced3ca3c0ddfd2bc0ccd0aa11315dfca9fe4c53ab946fe4dee893007981cf69d8c7a237697ff61234f39089e1309c9c1c722206ae3c3db21a045fcc3cd6308cc9265bbfc5467ead15fc3957d6ce EAP-Message = 0x0074ab8e6876412b7125e5b5829de0bc58f36814ab5000f68bec00038b30820387308202f0a003020102020900ca3ef53cca0b2a53300d06092a864886f70d010104050030818a310b3009060355040613024954310e300c060355040813054c617a696f310d300b06035504071304526f6d6531153013060355040a130c4f7267616e697a6174696f6e311b301906035504031312436c69656e742063657274696669636174653128302606092a864886f70d01090116196e69636f6c612e6e6f7669656c6c6f40676d61696c2e636f6d301e170d3036313132313131313430305a170d3136303632313131313430305a30818a310b30090603550406 EAP-Message = 0x13024954310e300c060355040813054c617a696f310d Message-Authenticator = 0x00000000000000000000000000000000 State = 0x97a53de462e11aaa37c84d623f825ef1 Tue May 8 10:29:53 2007 : Debug: Finished request 498 Tue May 8 10:29:53 2007 : Debug: Going to the next request Tue May 8 10:29:53 2007 : Debug: Waking up in 6 seconds... And continue in the same mode..... Reading the log seems that some operations are repeated many time before the user can obtain the access to the network. Thanks