LDAP server contacted twice?

Phil Mayers p.mayers at imperial.ac.uk
Fri Feb 9 15:26:45 CET 2007


Fabio Spelta wrote:
> 
> 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. 

You can use the Autz-Type stanza to only run the LDAP on the inner EAP 
request, like so:

authorize {
   preprocess
   files
   eap
   mschap
   Autz-Type INNER {
     ldap
   }
}

...then in the users file:

DEFAULT	Freeradius-Proxied-To == 127.0.0.1, Autz-Type := INNER

Obviously you won't be able to any LDAP matches in the users file, since 
it won't have run at that point - if you need to, you can defined 
another files module and run it after the ldap module e.g.:

authorize {
   preprocess
   files
   eap
   mschap
   Autz-Type INNER {
     ldap
     files_inner
   }
}


> 
> 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 <http://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 <http://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
> 
> 
> ------------------------------------------------------------------------
> 
> - 
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html




More information about the Freeradius-Users mailing list