Long Access time

Josh Shamir josh.shamir at gmail.com
Tue May 8 19:45:50 CEST 2007 

On 5/8/07, Alan DeKok <aland at 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

More information about the Freeradius-Users mailing list