On 5/8/07, Alan DeKok <aland@deployingradius.com> wrote:
Sounds like the supplicant or access point has issues.
It can be an access point problem? About the communication with Coovachilli or Radius? Or proxy.conf bad configured?
Which doesn't include a final Access-Accept, or Access-Reject.
Here it is: rad_recv: Access-Request packet from host 192.168.181.1:32806, id=249, length=177 User-Name = "luca.tar" State = 0x6e06a4c26ade18c076519b870babcfa0 EAP-Message = 0x0208002b19001703010020a756da39e479810ae0a78707912f9ed7c572929c37cdbdf2d725c2f2571be6c0 Message-Authenticator = 0xc1ea0ec6b1b52c6afd928b12970dbd09 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:54 2007 : Debug: Processing the authorize section of radiusd.conf Tue May 8 10:29:54 2007 : Debug: modcall: entering group authorize for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "preprocess" returns ok for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "chap" returns noop for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "mschap" returns noop for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 505 Tue May 8 10:29:54 2007 : Debug: rlm_realm: No '@' in User-Name = "luca.tar", looking up realm NULL Tue May 8 10:29:54 2007 : Debug: rlm_realm: Found realm "NULL" Tue May 8 10:29:54 2007 : Debug: rlm_realm: Adding Stripped-User-Name = "luca.tar" Tue May 8 10:29:54 2007 : Debug: rlm_realm: Proxying request from user luca.tar to realm NULL Tue May 8 10:29:54 2007 : Debug: rlm_realm: Adding Realm = "NULL" Tue May 8 10:29:54 2007 : Debug: rlm_realm: Authentication realm is LOCAL. Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "suffix" returns noop for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 505 Tue May 8 10:29:54 2007 : Debug: rlm_eap: EAP packet type response id 8 length 43 Tue May 8 10:29:54 2007 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "eap" returns updated for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 505 Tue May 8 10:29:54 2007 : Debug: users: Matched entry DEFAULT at line 154 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Entering ldap_groupcmp() Tue May 8 10:29:54 2007 : Debug: radius_xlat: 'ou=stat,dc=univ,dc=il' Tue May 8 10:29:54 2007 : Debug: radius_xlat: '(uid=luca.tar)' Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=it, with filter (uid=luca.tar) Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:54 2007 : Debug: radius_xlat: '(|(&(objectClass=GroupOfNames)(member=cn\3dLuca Tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2 cdc\3dil))(&(objectClass=GroupOfUniqueNames)(uniquemember=cn\3dLuca Tar\2cou\3dfaculty\2cou\3ddspsa\2cou\3dstat\2cdc\3duniv\2cdc\3dil)))' Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=it, with filter (&(cn=professor)(|(&(objectClass=GroupOfNames)(member=cn\3d Luca 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:54 2007 : Debug: rlm_ldap: object not found or got ambiguous search result Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:54 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:54 2007 : Debug: rlm_ldap::ldap_groupcmp: User found in group professor Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:54 2007 : Debug: users: Matched entry DEFAULT at line 176 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "files" returns ok for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 505 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: - authorize Tue May 8 10:29:54 2007 : Debug: rlm_ldap: performing user authorization for luca.tar Tue May 8 10:29:54 2007 : Debug: radius_xlat: '(uid=luca.tar)' Tue May 8 10:29:54 2007 : Debug: radius_xlat: 'ou=stat,dc=univ,dc=il' Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: performing search in ou=stat,dc=univ,dc=il, with filter (uid=luca.tar) Tue May 8 10:29:54 2007 : Debug: rlm_ldap: checking if remote access for luca.tar is allowed by userPassword Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Added password PASSWORD in check items Tue May 8 10:29:54 2007 : Debug: rlm_ldap: looking for check items in directory... Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Adding radiusGroupName as Ldap-Group, value professor & op=21 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Adding radiusCallingStationId as Calling-Station-Id, value 00-0C-F1-18-64-E5 & op=21 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Adding radiusCallingStationId as Calling-Station-Id, value 00-1B-63-00-0C-DE & op=21 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Adding userPassword as User-Password, value PASSWORD & op=21 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: looking for reply items in directory... Tue May 8 10:29:54 2007 : Debug: rlm_ldap: Adding radiusFilterId as Filter-Id, value 98 & op=11 Tue May 8 10:29:54 2007 : Debug: rlm_ldap: user luca.tar authorized to use remote access Tue May 8 10:29:54 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "ldap" returns ok for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: calling checkval (rlm_checkval) for request 505 Tue May 8 10:29:54 2007 : Debug: rlm_checkval: Item Name: Calling-Station-Id, Value: 00-1B-63-00-0C-DE Tue May 8 10:29:54 2007 : Debug: rlm_checkval: Value Name: Calling-Station-Id, Value: 00-0C-F1-18-64-E5 Tue May 8 10:29:54 2007 : Debug: rlm_checkval: Value Name: Calling-Station-Id, Value: 00-1B-63-00-0C-DE Tue May 8 10:29:54 2007 : Debug: modsingle[authorize]: returned from checkval (rlm_checkval) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authorize]: module "checkval" returns ok for request 505 Tue May 8 10:29:54 2007 : Debug: modcall: leaving group authorize (returns updated) for request 505 Tue May 8 10:29:54 2007 : Debug: rad_check_password: Found Auth-Type EAP Tue May 8 10:29:54 2007 : Debug: auth: type "EAP" Tue May 8 10:29:54 2007 : Debug: Processing the authenticate section of radiusd.conf Tue May 8 10:29:54 2007 : Debug: modcall: entering group authenticate for request 505 Tue May 8 10:29:54 2007 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 505 Tue May 8 10:29:54 2007 : Debug: rlm_eap: Request found, released from the list Tue May 8 10:29:54 2007 : Debug: rlm_eap: EAP/peap Tue May 8 10:29:54 2007 : Debug: rlm_eap: processing type peap Tue May 8 10:29:54 2007 : Debug: rlm_eap_peap: Authenticate Tue May 8 10:29:54 2007 : Debug: rlm_eap_tls: processing TLS Tue May 8 10:29:54 2007 : Debug: eaptls_verify returned 7 Tue May 8 10:29:54 2007 : Debug: rlm_eap_tls: Done initial handshake Tue May 8 10:29:54 2007 : Debug: eaptls_process returned 7 Tue May 8 10:29:54 2007 : Debug: rlm_eap_peap: EAPTLS_OK Tue May 8 10:29:54 2007 : Debug: rlm_eap_peap: Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 02 08 00 0b 21 00 03 00 02 00 01 Tue May 8 10:29:54 2007 : Debug: rlm_eap_peap: Received EAP-TLV response. Tue May 8 10:29:54 2007 : Debug: rlm_eap_peap: Tunneled data is valid. Tue May 8 10:29:54 2007 : Debug: rlm_eap_peap: Success Tue May 8 10:29:54 2007 : Debug: rlm_eap: Freeing handler Tue May 8 10:29:54 2007 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 505 Tue May 8 10:29:54 2007 : Debug: modcall[authenticate]: module "eap" returns ok for request 505 Tue May 8 10:29:54 2007 : Debug: modcall: leaving group authenticate (returns ok) for request 505 Tue May 8 10:29:54 2007 : Auth: Login OK: [luca.tar/<no User-Password attribute>] (from client chilli port 0 cli 00-1B-63-00-0C-DE) Sending Access-Accept of id 249 to 192.168.181.1 port 32806 Service-Type == Framed-User Filter-Id = "98" MS-MPPE-Recv-Key = 0xf3e32519ac70611ad1e77ff451de9cbd1b505f0107bc55a34a6fca9b8a295bf4 MS-MPPE-Send-Key = 0x4b66b29e9f0570d621bd6e059e447ce157b2f6290a4a3cdfdf90f8f1f1bd0458 EAP-Message = 0x03080004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "luca.tar" Tue May 8 10:29:54 2007 : Debug: Finished request 505 Tue May 8 10:29:54 2007 : Debug: Going to the next request Tue May 8 10:29:54 2007 : Debug: Waking up in 5 seconds...
I don't know why this would be happening. I haven't seen it happen on various MAC's I have access to.
:) Best regards. Josh