Long Access time

Josh Shamir josh.shamir at gmail.com
Tue May 8 18:17:24 CEST 2007 

On 5/8/07, Alan DeKok <aland at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20070508/e5e6fa8f/attachment.html>

More information about the Freeradius-Users mailing list