<span class="q">Hello everybody.<br><br>We got a setup which does work
in authenticating 812.1x users over a wired network by using EAP-MD5,
checking authorization and authentication of the supplicant over a LDAP
directory.<br><br>What
we do find strange (and pretty annoying, indeed) is that the we feel
that the LDAP server does get contacted more than necessary, read:
twice.
<br>Being more specific, when the freeradius server gets an
ACCESS-REQUEST from the NAS, then radiusd does contact the LDAP server
three times. <br>The first time it does check for the existance of the
user authenticating. The second, it checks if the users belong to a
certain group specified with the Ldap-Group option.
<br></span>The third time it does grab the password from the user entry in the LDAP field and add it to the check item list..<span class="q"><br><br>So long, so well.<br><br>What happens next? Next step is about the ACCESS-CHALLENGE.
<br></span>When radiusd is about to send it, it first checks the LDAP
again. The same three times. Check for the users in the whole
directory, check the belonging to the group, check the password again
to calculate the hash. That results in six LDAP queries, we suspect
that those can be reduced down to half but we can't find the point
out.
<br><br>Thank you very much in advance.<br><br><span class="q" id="q_110a68dc33b60e32_1"><span>Here's the radiusd debug log (radiusd -X):<br>rad_recv: Access-Request packet from host ********:37540, id=1, length=161<br>
</span> Message-Authenticator = 0x********</span><br><div><div><span class="q" id="q_110a68dc33b60e32_3"><span> User-Name = "********"<br> NAS-IP-Address = ********<br> Called-Station-Id = "********"
<br> NAS-Port = 21001<br> NAS-Port-Id = "fe.2.1"<br> NAS-Port-Type = Ethernet
<br> Service-Type = Framed-User<br> Calling-Station-Id = "********"<br></span> EAP-Message = 0x********<div><span> Framed-MTU = 1300<br> Processing the authorize section of
radiusd.conf<br>modcall: entering group authorize for request 0<br> modcall[authorize]: module "preprocess" returns ok for request 0<br>radius_xlat: '/var/log/radius/radacct/********/auth-detail-20070209'
<br>rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/********/auth-detail-20070209<br> modcall[authorize]: module "auth_log" returns ok for request 0
<br> modcall[authorize]: module "chap" returns noop for request 0<br> modcall[authorize]: module "mschap" returns noop for request 0<br> rlm_eap: EAP packet type response id 1 length 24<br> rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
<br> modcall[authorize]: module "eap" returns updated for request 0<br> users: Matched DEFAULT at 8<br> users: Matched DEFAULT at 103<br> users: Matched DEFAULT at 105<br>rlm_ldap: Entering ldap_groupcmp()
<br>radius_xlat: 'dc=********,dc=********'<br>radius_xlat: '(uid=********)'<br>rlm_ldap: ldap_get_conn: Checking Id: 0<br>rlm_ldap: ldap_get_conn: Got Id: 0<br>rlm_ldap: attempting LDAP reconnection<br>
rlm_ldap: (re)connect to ********:389, authentication 0
<br>rlm_ldap: bind as cn=********,ou=********,dc=********,dc=********/******** to ********:389<br>rlm_ldap: waiting for bind result ...<br>rlm_ldap: Bind was successful<br>rlm_ldap: performing search in dc=********,dc=********, with filter (uid=********)
<br>rlm_ldap: ldap_release_conn: Release Id: 0<br>radius_xlat: '(&(objectClass=GroupOfNames)(member=uid=********, ou=users, dc=********,dc=********))'<br>rlm_ldap: ldap_get_conn: Checking Id: 0<br>rlm_ldap: ldap_get_conn: Got Id: 0
<br>rlm_ldap: performing search in dc=********,dc=********, with filter (&(cn=802.1xwired)(&(objectClass=GroupOfNames)(member=uid=********, ou=users, dc=********,dc=********)))<br>rlm_ldap::ldap_groupcmp: User found in group
802.1xwired<br>rlm_ldap: ldap_release_conn: Release Id: 0<br> users: Matched DEFAULT at 121<br> modcall[authorize]: module "files" returns ok for request 0<br>modcall: group authorize returns updated for request 0
<br> Processing the authorize section of radiusd.conf<br>modcall: entering group Autz-Type for request 0<br>rlm_ldap: - authorize<br>rlm_ldap: performing user authorization for ********<br>radius_xlat: '(uid=********)'
<br>radius_xlat: 'dc=********,dc=********'<br>rlm_ldap: ldap_get_conn: Checking Id: 0<br>rlm_ldap: ldap_get_conn: Got Id: 0<br>rlm_ldap: performing search in dc=********,dc=********, with filter (uid=********)<br>
rlm_ldap: Added password a in check items<br>rlm_ldap: looking for check items in directory...<br>rlm_ldap: looking for reply items in directory...<br>rlm_ldap: user ******** authorized to use remote access<br>rlm_ldap: ldap_release_conn: Release Id: 0
<br> modcall[authorize]: module "ldap" returns ok for request 0<br>modcall: group Autz-Type returns ok for request 0<br> rad_check_password: Found Auth-Type EAP<br>auth: type "EAP"<br> Processing the authenticate section of
radiusd.conf<br>modcall: entering group authenticate for request 0<br> rlm_eap: EAP Identity<br> rlm_eap: processing type md5<br>rlm_eap_md5: Issuing Challenge<br> modcall[authenticate]: module "eap" returns handled for request 0
<br>modcall: group authenticate returns handled for request 0<br>Sending Access-Challenge of id 1 to ********:37540<br> Framed-IP-Address = <a href="http://255.255.255.254/" target="_blank" onclick="return top.js.OpenExtLink(window,event,this)">
255.255.255.254</a><br> Framed-MTU = 576
<br> Service-Type = Framed-User<br> Framed-Filter-Id = "Enterasys:version=1:mgmt=su:policy=admin"<br></span></div> EAP-Message = 0x********</span></div><span><br> Message-Authenticator = 0x00000000000000000000000000000000
<br> State = 0x</span>********<br><div><span class="q" id="q_110a68dc33b60e32_5"><span>Finished request 0<br>Going to the next request<br>--- Walking the entire request list ---<br>Waking up in 6 seconds...<br>rad_recv: Access-Request packet from host ********:37540, id=2, length=196
<br> Message-Authenticator = 0x91c3c6cfd386855dc73803c5a3670318<br> User-Name = "********"<br> State = 0xb9e826259b6a63f5c103fd209ffde50b<br> NAS-IP-Address = ********<br> Called-Station-Id = "********"
<br> NAS-Port = 21001<br> NAS-Port-Id = "fe.2.1"<br> NAS-Port-Type = Ethernet<br> Framed-MTU = 1300<br> Service-Type = Framed-User<br> Calling-Station-Id = "********"
<br></span> EAP-Message = 0x********<div><span><br> Processing the authorize section of radiusd.conf<br>modcall: entering group authorize for request 1<br> modcall[authorize]: module "preprocess" returns ok for request 1
<br>radius_xlat: '/var/log/radius/radacct/********/auth-detail-20070209'<br>rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/********/auth-detail-20070209
<br> modcall[authorize]: module "auth_log" returns ok for request 1<br> modcall[authorize]: module "chap" returns noop for request 1<br> modcall[authorize]: module "mschap" returns noop for request 1
<br> rlm_eap: EAP packet type response id 2 length 41<br> rlm_eap: No EAP Start, assuming it's an on-going EAP conversation<br> modcall[authorize]: module "eap" returns updated for request 1<br> users: Matched DEFAULT at 8
<br> users: Matched DEFAULT at 103<br> users: Matched DEFAULT at 105<br>rlm_ldap: Entering ldap_groupcmp()<br>radius_xlat: 'dc=********,dc=********'<br>radius_xlat: '(uid=********)'<br>rlm_ldap: ldap_get_conn: Checking Id: 0
<br>rlm_ldap: ldap_get_conn: Got Id: 0<br>rlm_ldap: performing search in dc=********,dc=********, with filter (uid=********)<br>rlm_ldap: ldap_release_conn: Release Id: 0<br>radius_xlat: '(&(objectClass=GroupOfNames)(member=uid=********, ou=users, dc=********,dc=********))'
<br>rlm_ldap: ldap_get_conn: Checking Id: 0<br>rlm_ldap: ldap_get_conn: Got Id: 0<br>rlm_ldap: performing search in dc=********,dc=********, with filter (&(cn=802.1xwired)(&(objectClass=GroupOfNames)(member=uid=********, ou=users, dc=********,dc=********)))
<br>rlm_ldap::ldap_groupcmp: User found in group 802.1xwired<br>rlm_ldap: ldap_release_conn: Release Id: 0<br> users: Matched DEFAULT at 121<br> modcall[authorize]: module "files" returns ok for request 1<br>
modcall: group authorize returns updated for request 1<br> Processing the authorize section of radiusd.conf<br>modcall: entering group Autz-Type for request 1<br>rlm_ldap: - authorize<br>rlm_ldap: performing user authorization for ********
<br>radius_xlat: '(uid=********)'<br>radius_xlat: 'dc=********,dc=********'<br>rlm_ldap: ldap_get_conn: Checking Id: 0<br>rlm_ldap: ldap_get_conn: Got Id: 0<br>rlm_ldap: performing search in dc=********,dc=********, with filter (uid=********)
<br>rlm_ldap: Added password a in check items<br>rlm_ldap: looking for check items in directory...<br>rlm_ldap: looking for reply items in directory...<br>rlm_ldap: user ******** authorized to use remote access<br>rlm_ldap: ldap_release_conn: Release Id: 0
<br> modcall[authorize]: module "ldap" returns ok for request 1<br>modcall: group Autz-Type returns ok for request 1<br> rad_check_password: Found Auth-Type EAP<br>auth: type "EAP"<br> Processing the authenticate section of
radiusd.conf<br>modcall: entering group authenticate for request 1<br> rlm_eap: Request found, released from the list<br> rlm_eap: EAP/md5<br> rlm_eap: processing type md5<br> rlm_eap: Freeing handler<br> modcall[authenticate]: module "eap" returns ok for request 1
<br>modcall: group authenticate returns ok for request 1<br> Processing the post-auth section of radiusd.conf<br>modcall: entering group post-auth for request 1<br>radius_xlat: '/var/log/radius/radacct/********/reply-detail-20070209'
<br>rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /var/log/radius/radacct/********/reply-detail-20070209<br> modcall[post-auth]: module "reply_log" returns ok for request 1
<br>rlm_sql (sql): Processing sql_postauth<br>radius_xlat: '********'<br>rlm_sql (sql): sql_set_user escaped user --> '********'<br>radius_xlat:
'INSERT into radpostauth (id, user, pass, reply, date) values ('',
'********', 'Chap-Password', 'Access-Accept', NOW())'
<br>rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth
(id, user, pass, reply, date) values ('', '********', 'Chap-Password',
'Access-Accept', NOW())<br>rlm_sql (sql): Reserving sql socket id: 4
<br>rlm_sql (sql): Released sql socket id: 4<br> modcall[post-auth]: module "sql" returns ok for request 1<br>modcall: group post-auth returns ok for request 1<br>Sending Access-Accept of id 2 to ********:37540
<br> Framed-IP-Address = <a href="http://255.255.255.254/" target="_blank" onclick="return top.js.OpenExtLink(window,event,this)">255.255.255.254</a><br> Framed-MTU = 576<br> Service-Type = Framed-User
<br> Framed-Filter-Id = "Enterasys:version=1:mgmt=su:policy=admin"
<br></span></div> EAP-Message = 0x********<div><span> Message-Authenticator = 0x00000000000000000000000000000000<br> User-Name = "********"<br>Finished request 1
<br>Going to the next request<br>--- Walking the entire request list ---
<br>Cleaning up request 0 ID 1 with timestamp 45cc6700<br>Waking up in 6 seconds...<br>rad_recv: Accounting-Request packet from host ********:37541, id=1, length=100<br> Acct-Status-Type = Start<br> User-Name = "********"
<br> Calling-Station-Id = "********"<br> NAS-IP-Address = ********<br> NAS-Port = 21001<br> Acct-Delay-Time = 0<br> Acct-Session-Id = "1000004F"<br> Acct-Authentic = RADIUS
<br> Processing the preacct section of radiusd.conf<br>modcall: entering group preacct for request 2<br> modcall[preacct]: module "preprocess" returns noop for request 2<br>rlm_acct_unique:
Hashing 'NAS-Port = 21001,Client-IP-Address = ********,NAS-IP-Address =
********,Acct-Session-Id = "1000004F",User-Name = "********"'
<br>rlm_acct_unique: Acct-Unique-Session-ID = "3974eb0b2b9f763c".<br> modcall[preacct]: module "acct_unique" returns ok for request 2<br> rlm_realm: Looking up realm "********" for User-Name = "********"
<br> rlm_realm: No such realm "********"<br> modcall[preacct]: module "suffix" returns noop for request 2<br> acct_users: Matched DEFAULT at 7<br> modcall[preacct]: module "files" returns ok for request 2
<br>modcall: group preacct returns ok for request 2<br> Processing the accounting section of radiusd.conf<br>modcall: entering group accounting for request 2<br> modcall[accounting]: module "acct_unique" returns noop for request 2
<br>radius_xlat: '/var/log/radius/radacct/********/detail-20070209'<br>rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/********/detail-20070209<br> modcall[accounting]: module "detail" returns ok for request 2
<br> modcall[accounting]: module "unix" returns ok for request 2<br>radius_xlat: '/var/log/radius/radutmp'<br>radius_xlat: ********'<br> modcall[accounting]: module "radutmp" returns ok for request 2
<br>radius_xlat: '********'<br>rlm_sql (sql): sql_set_user escaped user --> '********'<br>radius_xlat: 'INSERT into radacct *****************<br>rlm_sql (sql): Reserving sql socket id: 3<br>rlm_sql (sql): Released sql socket id: 3
<br> modcall[accounting]: module "sql" returns ok for request 2<br>modcall: group accounting returns ok for request 2<br>Sending Accounting-Response of id 1 to ********:37541<br>Finished request 2</span></div>
</span></div></div><br><br>-- <br>Fabio