On Tuesday 08 June 2004 01:14 pm, Alan DeKok wrote:
> Zoltan Ori <[EMAIL PROTECTED]> wrote:
> > Another Access-Request packet is received. LDAP and the users file
> > are once again processed but now EAP complains that "User-Password
> > is required for EAP-MD5 authentication".
>
> So run the server in debugging mode, to see which entries in LDAP it
> matches.
>
OK
> > The exchange of packets from radeapclient are enclose below.
>
> But not the debug output from the server.
>
> <sigh> Is there a huge blinking sign somewhere which says to ignore
> all of the documentation and FAQ?
Some of us are pretty dense.
Here is the debug output from the server.
rad_recv: Access-Request packet from host 127.0.0.1:51644, id=140, length=93
User-Name = "m0999999"
User-Password = "test123"
NAS-IP-Address = 147.133.230.16
Message-Authenticator = 0x820f1368d333bb1f3bab23e9b92325f7
NAS-Port = 0
EAP-Message = 0x02d2000d016d30393939393939
Tue Jun 8 11:16:03 2004 : Debug: Processing the authorize section of radiusd.conf
Tue Jun 8 11:16:03 2004 : Debug: modcall: entering group authorize for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling preprocess
(rlm_preprocess) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from preprocess
(rlm_preprocess) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "preprocess" returns ok
for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling auth_log
(rlm_detail) for request 8
Tue Jun 8 11:16:03 2004 : Debug: radius_xlat:
'/usr/local/var/log/radius/radacct/127.0.0.1/auth-detail-20040608'
Tue Jun 8 11:16:03 2004 : Debug: rlm_detail:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to
/usr/local/var/log/radius/radacct/127.0.0.1/auth-detail-20040608
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from auth_log
(rlm_detail) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "auth_log" returns ok
for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling mschap (rlm_mschap)
for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from mschap
(rlm_mschap) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "mschap" returns noop
for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for
request 8
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: - authorize
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: performing user authorization for m0999999
Tue Jun 8 11:16:03 2004 : Debug: radius_xlat: '(uid=m0999999)'
Tue Jun 8 11:16:03 2004 : Debug: radius_xlat: 'dc=morehead-st,dc=edu'
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: performing search in
dc=morehead-st,dc=edu, with filter (uid=m0999999)
request 10 done
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: looking for check items in directory...
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: Adding class as MSU-Class, value facstaff
& op=21
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: looking for reply items in directory...
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: user m0999999 authorized to use remote
access
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from ldap
(rlm_ldap) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "ldap" returns ok for
request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling eap (rlm_eap) for
request 8
Tue Jun 8 11:16:03 2004 : Debug: rlm_eap: EAP packet type response id 210 length 13
Tue Jun 8 11:16:03 2004 : Debug: rlm_eap: No EAP Start, assuming it's an on-going
EAP conversation
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from eap (rlm_eap)
for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "eap" returns updated
for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling files (rlm_files)
for request 8
Tue Jun 8 11:16:03 2004 : Debug: users: Matched DEFAULT at 10
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from files
(rlm_files) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "files" returns ok for
request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall: group authorize returns updated for request
8
Tue Jun 8 11:16:03 2004 : Debug: rad_check_password: Found Auth-Type LDAP
Tue Jun 8 11:16:03 2004 : Debug: rad_check_password: Found Auth-Type EAP
Tue Jun 8 11:16:03 2004 : Error: Warning: Found 2 auth-types on request for user
'm0999999'
Tue Jun 8 11:16:03 2004 : Debug: auth: type "EAP"
Tue Jun 8 11:16:03 2004 : Debug: Processing the authenticate section of radiusd.conf
Tue Jun 8 11:16:03 2004 : Debug: modcall: entering group authenticate for request 8
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for
request 8
Tue Jun 8 11:16:03 2004 : Debug: rlm_eap: EAP Identity
Tue Jun 8 11:16:03 2004 : Debug: rlm_eap: processing type md5
Tue Jun 8 11:16:03 2004 : Info: rlm_eap_md5: Issuing Challenge
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authenticate]: returned from eap
(rlm_eap) for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall[authenticate]: module "eap" returns
handled for request 8
Tue Jun 8 11:16:03 2004 : Debug: modcall: group authenticate returns handled for
request 8
Sending Access-Challenge of id 140 to 127.0.0.1:51644
Filter-Id = "Enterasys:version=1:mgmt=:policy=Employee"
EAP-Message = 0x01d300160410d04f877ba143667a7185c73e4bf3ad7f
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x6c5d69f98683f70ded4dd0200de8fc08
Tue Jun 8 11:16:03 2004 : Debug: Finished request 8
Tue Jun 8 11:16:03 2004 : Debug: Going to the next request
Tue Jun 8 11:16:03 2004 : Debug: --- Walking the entire request list ---
Tue Jun 8 11:16:03 2004 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:51644, id=141, length=120
User-Name = "m0999999"
User-Password = "test123"
NAS-IP-Address = 147.133.230.16
Message-Authenticator = 0x10f5f0e9c53ed69039033fc480a596ee
NAS-Port = 0
State = 0x6c5d69f98683f70ded4dd0200de8fc08
EAP-Message = 0x02d30016041018a4d1d5d4153463b03f768c3cf3aa66
Tue Jun 8 11:16:03 2004 : Debug: Processing the authorize section of radiusd.conf
Tue Jun 8 11:16:03 2004 : Debug: modcall: entering group authorize for request 9
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling preprocess
(rlm_preprocess) for request 9
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from preprocess
(rlm_preprocess) for request 9
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "preprocess" returns ok
for request 9
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling auth_log
(rlm_detail) for request 9
Tue Jun 8 11:16:03 2004 : Debug: radius_xlat:
'/usr/local/var/log/radius/radacct/127.0.0.1/auth-detail-20040608'
Tue Jun 8 11:16:03 2004 : Debug: rlm_detail:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to
/usr/local/var/log/radius/radacct/127.0.0.1/auth-detail-20040608
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from auth_log
(rlm_detail) for request 9
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "auth_log" returns ok
for request 9
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling mschap (rlm_mschap)
for request 9
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: returned from mschap
(rlm_mschap) for request 9
Tue Jun 8 11:16:03 2004 : Debug: modcall[authorize]: module "mschap" returns noop
for request 9
Tue Jun 8 11:16:03 2004 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for
request 9
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: - authorize
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: performing user authorization for m0999999
Tue Jun 8 11:16:03 2004 : Debug: radius_xlat: '(uid=m0999999)'
Tue Jun 8 11:16:03 2004 : Debug: radius_xlat: 'dc=morehead-st,dc=edu'
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Tue Jun 8 11:16:03 2004 : Debug: rlm_ldap: performing search in
dc=morehead-st,dc=edu, with filter (uid=m0999999)
request 11 done
Tue Jun 8 11:16:04 2004 : Debug: rlm_ldap: looking for check items in directory...
Tue Jun 8 11:16:04 2004 : Debug: rlm_ldap: Adding class as MSU-Class, value facstaff
& op=21
Tue Jun 8 11:16:04 2004 : Debug: rlm_ldap: looking for reply items in directory...
Tue Jun 8 11:16:04 2004 : Debug: rlm_ldap: user m0999999 authorized to use remote
access
Tue Jun 8 11:16:04 2004 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authorize]: returned from ldap
(rlm_ldap) for request 9
Tue Jun 8 11:16:04 2004 : Debug: modcall[authorize]: module "ldap" returns ok for
request 9
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authorize]: calling eap (rlm_eap) for
request 9
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: EAP packet type response id 211 length 22
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: No EAP Start, assuming it's an on-going
EAP conversation
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authorize]: returned from eap (rlm_eap)
for request 9
Tue Jun 8 11:16:04 2004 : Debug: modcall[authorize]: module "eap" returns updated
for request 9
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authorize]: calling files (rlm_files)
for request 9
Tue Jun 8 11:16:04 2004 : Debug: users: Matched DEFAULT at 10
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authorize]: returned from files
(rlm_files) for request 9
Tue Jun 8 11:16:04 2004 : Debug: modcall[authorize]: module "files" returns ok for
request 9
Tue Jun 8 11:16:04 2004 : Debug: modcall: group authorize returns updated for request
9
Tue Jun 8 11:16:04 2004 : Debug: rad_check_password: Found Auth-Type LDAP
Tue Jun 8 11:16:04 2004 : Debug: rad_check_password: Found Auth-Type EAP
Tue Jun 8 11:16:04 2004 : Error: Warning: Found 2 auth-types on request for user
'm0999999'
Tue Jun 8 11:16:04 2004 : Debug: auth: type "EAP"
Tue Jun 8 11:16:04 2004 : Debug: Processing the authenticate section of radiusd.conf
Tue Jun 8 11:16:04 2004 : Debug: modcall: entering group authenticate for request 9
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for
request 9
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: Request found, released from the list
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: EAP/md5
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: processing type md5
Tue Jun 8 11:16:04 2004 : Info: rlm_eap_md5: User-Password is required for EAP-MD5
authentication
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: Handler failed in EAP/md5
Tue Jun 8 11:16:04 2004 : Debug: rlm_eap: Failed in EAP select
Tue Jun 8 11:16:04 2004 : Debug: modsingle[authenticate]: returned from eap
(rlm_eap) for request 9
Tue Jun 8 11:16:04 2004 : Debug: modcall[authenticate]: module "eap" returns
invalid for request 9
Tue Jun 8 11:16:04 2004 : Debug: modcall: group authenticate returns invalid for
request 9
Tue Jun 8 11:16:04 2004 : Debug: auth: Failed to validate the user.
Tue Jun 8 11:16:04 2004 : Debug: Delaying request 9 for 1 seconds
Tue Jun 8 11:16:04 2004 : Debug: Finished request 9
Tue Jun 8 11:16:04 2004 : Debug: Going to the next request
Tue Jun 8 11:16:04 2004 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:51644, id=141, length=120
Sending Access-Reject of id 141 to 127.0.0.1:51644
EAP-Message = 0x04d30004
Message-Authenticator = 0x00000000000000000000000000000000
Tue Jun 8 11:16:06 2004 : Debug: --- Walking the entire request list ---
Tue Jun 8 11:16:06 2004 : Debug: Waking up in 3 seconds...
Tue Jun 8 11:16:09 2004 : Debug: --- Walking the entire request list ---
Tue Jun 8 11:16:09 2004 : Debug: Cleaning up request 8 ID 140 with timestamp 40c5d833
Tue Jun 8 11:16:09 2004 : Debug: Cleaning up request 9 ID 141 with timestamp 40c5d833
Tue Jun 8 11:16:09 2004 : Debug: Nothing to do. Sleeping until we see a request.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
