LDAP server contacted twice?

Fabio Spelta spelta at gmail.com
Fri Feb 9 14:04:11 CET 2007 

Hello everybody.

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.

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.
Being more specific, when the freeradius server gets an ACCESS-REQUEST from
the NAS, then radiusd does contact the LDAP server three times.
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.
The third time it does grab the password from the user entry in the LDAP
field and add it to the check item list..

So long, so well.

What happens next? Next step is about the ACCESS-CHALLENGE.
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.

Thank you very much in advance.

Here's the radiusd debug log (radiusd -X):
rad_recv: Access-Request packet from host ********:37540, id=1, length=161
        Message-Authenticator = 0x********
        User-Name = "********"
        NAS-IP-Address = ********
        Called-Station-Id = "********"
        NAS-Port = 21001
        NAS-Port-Id = "fe.2.1"
        NAS-Port-Type = Ethernet
        Service-Type = Framed-User
        Calling-Station-Id = "********"
        EAP-Message = 0x********        Framed-MTU = 1300
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
radius_xlat:  '/var/log/radius/radacct/********/auth-detail-20070209'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d
expands to /var/log/radius/radacct/********/auth-detail-20070209
  modcall[authorize]: module "auth_log" returns ok for request 0
  modcall[authorize]: module "chap" returns noop for request 0
  modcall[authorize]: module "mschap" returns noop for request 0
  rlm_eap: EAP packet type response id 1 length 24
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 0
    users: Matched DEFAULT at 8
    users: Matched DEFAULT at 103
    users: Matched DEFAULT at 105
rlm_ldap: Entering ldap_groupcmp()
radius_xlat:  'dc=********,dc=********'
radius_xlat:  '(uid=********)'
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: attempting LDAP reconnection
rlm_ldap: (re)connect to ********:389, authentication 0
rlm_ldap: bind as cn=********,ou=********,dc=********,dc=********/********
to ********:389
rlm_ldap: waiting for bind result ...
rlm_ldap: Bind was successful
rlm_ldap: performing search in dc=********,dc=********, with filter
(uid=********)
rlm_ldap: ldap_release_conn: Release Id: 0
radius_xlat:  '(&(objectClass=GroupOfNames)(member=uid=********, ou=users,
dc=********,dc=********))'
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=********,dc=********, with filter (&(cn=
802.1xwired)(&(objectClass=GroupOfNames)(member=uid=********, ou=users,
dc=********,dc=********)))
rlm_ldap::ldap_groupcmp: User found in group 802.1xwired
rlm_ldap: ldap_release_conn: Release Id: 0
    users: Matched DEFAULT at 121
  modcall[authorize]: module "files" returns ok for request 0
modcall: group authorize returns updated for request 0
  Processing the authorize section of radiusd.conf
modcall: entering group Autz-Type for request 0
rlm_ldap: - authorize
rlm_ldap: performing user authorization for ********
radius_xlat:  '(uid=********)'
radius_xlat:  'dc=********,dc=********'
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=********,dc=********, with filter
(uid=********)
rlm_ldap: Added password a in check items
rlm_ldap: looking for check items in directory...
rlm_ldap: looking for reply items in directory...
rlm_ldap: user ******** authorized to use remote access
rlm_ldap: ldap_release_conn: Release Id: 0
  modcall[authorize]: module "ldap" returns ok for request 0
modcall: group Autz-Type returns ok for request 0
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 0
  rlm_eap: EAP Identity
  rlm_eap: processing type md5
rlm_eap_md5: Issuing Challenge
  modcall[authenticate]: module "eap" returns handled for request 0
modcall: group authenticate returns handled for request 0
Sending Access-Challenge of id 1 to ********:37540
        Framed-IP-Address = 255.255.255.254
        Framed-MTU = 576
        Service-Type = Framed-User
        Framed-Filter-Id = "Enterasys:version=1:mgmt=su:policy=admin"
        EAP-Message = 0x********

        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x********
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host ********:37540, id=2, length=196
        Message-Authenticator = 0x91c3c6cfd386855dc73803c5a3670318
        User-Name = "********"
        State = 0xb9e826259b6a63f5c103fd209ffde50b
        NAS-IP-Address = ********
        Called-Station-Id = "********"
        NAS-Port = 21001
        NAS-Port-Id = "fe.2.1"
        NAS-Port-Type = Ethernet
        Framed-MTU = 1300
        Service-Type = Framed-User
        Calling-Station-Id = "********"
        EAP-Message = 0x********
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
  modcall[authorize]: module "preprocess" returns ok for request 1
radius_xlat:  '/var/log/radius/radacct/********/auth-detail-20070209'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d
expands to /var/log/radius/radacct/********/auth-detail-20070209
  modcall[authorize]: module "auth_log" returns ok for request 1
  modcall[authorize]: module "chap" returns noop for request 1
  modcall[authorize]: module "mschap" returns noop for request 1
  rlm_eap: EAP packet type response id 2 length 41
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 1
    users: Matched DEFAULT at 8
    users: Matched DEFAULT at 103
    users: Matched DEFAULT at 105
rlm_ldap: Entering ldap_groupcmp()
radius_xlat:  'dc=********,dc=********'
radius_xlat:  '(uid=********)'
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=********,dc=********, with filter
(uid=********)
rlm_ldap: ldap_release_conn: Release Id: 0
radius_xlat:  '(&(objectClass=GroupOfNames)(member=uid=********, ou=users,
dc=********,dc=********))'
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=********,dc=********, with filter (&(cn=
802.1xwired)(&(objectClass=GroupOfNames)(member=uid=********, ou=users,
dc=********,dc=********)))
rlm_ldap::ldap_groupcmp: User found in group 802.1xwired
rlm_ldap: ldap_release_conn: Release Id: 0
    users: Matched DEFAULT at 121
  modcall[authorize]: module "files" returns ok for request 1
modcall: group authorize returns updated for request 1
  Processing the authorize section of radiusd.conf
modcall: entering group Autz-Type for request 1
rlm_ldap: - authorize
rlm_ldap: performing user authorization for ********
radius_xlat:  '(uid=********)'
radius_xlat:  'dc=********,dc=********'
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=********,dc=********, with filter
(uid=********)
rlm_ldap: Added password a in check items
rlm_ldap: looking for check items in directory...
rlm_ldap: looking for reply items in directory...
rlm_ldap: user ******** authorized to use remote access
rlm_ldap: ldap_release_conn: Release Id: 0
  modcall[authorize]: module "ldap" returns ok for request 1
modcall: group Autz-Type returns ok for request 1
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 1
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/md5
  rlm_eap: processing type md5
  rlm_eap: Freeing handler
  modcall[authenticate]: module "eap" returns ok for request 1
modcall: group authenticate returns ok for request 1
  Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 1
radius_xlat:  '/var/log/radius/radacct/********/reply-detail-20070209'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d
expands to /var/log/radius/radacct/********/reply-detail-20070209
  modcall[post-auth]: module "reply_log" returns ok for request 1
rlm_sql (sql): Processing sql_postauth
radius_xlat:  '********'
rlm_sql (sql): sql_set_user escaped user --> '********'
radius_xlat:  'INSERT into radpostauth (id, user, pass, reply, date) values
('', '********', 'Chap-Password', 'Access-Accept', NOW())'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (id, user,
pass, reply, date) values ('', '********', 'Chap-Password', 'Access-Accept',
NOW())
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
  modcall[post-auth]: module "sql" returns ok for request 1
modcall: group post-auth returns ok for request 1
Sending Access-Accept of id 2 to ********:37540
        Framed-IP-Address = 255.255.255.254
        Framed-MTU = 576
        Service-Type = Framed-User
        Framed-Filter-Id = "Enterasys:version=1:mgmt=su:policy=admin"
        EAP-Message = 0x********        Message-Authenticator =
0x00000000000000000000000000000000
        User-Name = "********"
Finished request 1
Going to the next request
--- Walking the entire request list ---
Cleaning up request 0 ID 1 with timestamp 45cc6700
Waking up in 6 seconds...
rad_recv: Accounting-Request packet from host ********:37541, id=1,
length=100
        Acct-Status-Type = Start
        User-Name = "********"
        Calling-Station-Id = "********"
        NAS-IP-Address = ********
        NAS-Port = 21001
        Acct-Delay-Time = 0
        Acct-Session-Id = "1000004F"
        Acct-Authentic = RADIUS
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 2
  modcall[preacct]: module "preprocess" returns noop for request 2
rlm_acct_unique: Hashing 'NAS-Port = 21001,Client-IP-Address =
********,NAS-IP-Address = ********,Acct-Session-Id = "1000004F",User-Name =
"********"'
rlm_acct_unique: Acct-Unique-Session-ID = "3974eb0b2b9f763c".
  modcall[preacct]: module "acct_unique" returns ok for request 2
    rlm_realm: Looking up realm "********" for User-Name = "********"
    rlm_realm: No such realm "********"
  modcall[preacct]: module "suffix" returns noop for request 2
    acct_users: Matched DEFAULT at 7
  modcall[preacct]: module "files" returns ok for request 2
modcall: group preacct returns ok for request 2
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 2
  modcall[accounting]: module "acct_unique" returns noop for request 2
radius_xlat:  '/var/log/radius/radacct/********/detail-20070209'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d
expands to /var/log/radius/radacct/********/detail-20070209
  modcall[accounting]: module "detail" returns ok for request 2
  modcall[accounting]: module "unix" returns ok for request 2
radius_xlat:  '/var/log/radius/radutmp'
radius_xlat:  ********'
  modcall[accounting]: module "radutmp" returns ok for request 2
radius_xlat:  '********'
rlm_sql (sql): sql_set_user escaped user --> '********'
radius_xlat:  'INSERT into radacct *****************
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
  modcall[accounting]: module "sql" returns ok for request 2
modcall: group accounting returns ok for request 2
Sending Accounting-Response of id 1 to ********:37541
Finished request 2


-- 
Fabio
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20070209/2bc9b191/attachment.html>

More information about the Freeradius-Users mailing list