RE: Problem with LDAP against Active Directory
Hi Dominique There appears to be something wrong with the search base definition for your LDAP search. It looks like you are using the "traditional" LDAP basename which goes "ou=mydepartment, o=mycompany, c=ch". Active Directory uses basenames that look like "dc=ad, dc=ch". Your LDAP server is returning "operations error", so I should look in its log file for more details. By the way, bear in mind that unless you use Microsoft IAS, you can only do RADIUS authentication against AD using PAP (i.e. users send passwords in cleartext), which isn't too secure. Max Caines
-----Original Message----- From: freeradius-users-bounces+max.caines=wlv.ac.uk@lists.freeradius.org [mailto:freeradius-users-bounces+max.caines=wlv.ac.uk@lists.fr eeradius.o rg]On Behalf Of domjullier@rhone.ch Sent: 03 April 2006 10:27 To: freeradius-users@lists.freeradius.org Subject: Problem with LDAP against Active Directory
Hi folks, I want authenticate users from a WLAN with freeradius. The Users are stored in the Active Directory of a Windows 2003 Server.
With some Tutorials from the Internet I have configured freeradius to make that.
Unfortunately the Authentication function not succesfully.
Thats the output from FreeRadius during the Authentication:
rad_recv: Access-Request packet from host 192.168.210.15:4596, id=13, length=100 NAS-Port-Type = Ethernet Service-Type = Login-User User-Name = "ldap" User-Password = "ldap" Called-Station-Id = "00:01:02:ad:64:f7" Calling-Station-Id = "00:c0:49:54:b5:43" NAS-Port = 1 Mon Apr 3 11:12:08 2006 : Debug: Processing the authorize section of radiusd.conf Mon Apr 3 11:12:08 2006 : Debug: modcall: entering group authorize for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 2 Mon Apr 3 11:12:08 2006 : Debug: rlm_realm: No '@' in User-Name = "ldap", looking up realm NULL Mon Apr 3 11:12:08 2006 : Debug: rlm_realm: No such realm "NULL" Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "suffix" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: rlm_eap: No EAP-Message, not doing EAP Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "eap" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "files" returns notfound for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: - authorize Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: performing user authorization for ldap Mon Apr 3 11:12:08 2006 : Debug: radius_xlat: '(uid=ldap)' Mon Apr 3 11:12:08 2006 : Debug: radius_xlat: 'ou=Sion, o=ad.ch' Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: attempting LDAP reconnection Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: closing existing LDAP connection Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: (re)connect to ad.ch:389, authentication 0 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: bind as / to ad.ch:389 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: waiting for bind result ... Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: Bind was successful Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: performing search in ou=Sion, o=ad.ch, with filter (uid=ldap) Mon Apr 3 11:12:18 2006 : Error: rlm_ldap: ldap_search() failed: Operations error Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: search failed Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 2 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "ldap" returns fail for request 2 Mon Apr 3 11:12:18 2006 : Debug: modcall: group authorize returns fail for request 2 Mon Apr 3 11:12:18 2006 : Debug: Finished request 2 Mon Apr 3 11:12:18 2006 : Debug: Going to the next request Mon Apr 3 11:12:18 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:18 2006 : Debug: Waking up in 6 seconds... rad_recv: Access-Request packet from host 192.168.210.15:4596, id=13, length=100 Mon Apr 3 11:12:18 2006 : Debug: Discarding duplicate request from client testnet:4596 - ID: 13 Mon Apr 3 11:12:18 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:18 2006 : Debug: Cleaning up request 2 ID 13 with timestamp 4430e6e8 Mon Apr 3 11:12:18 2006 : Debug: Nothing to do. Sleeping until we see a request. rad_recv: Access-Request packet from host 192.168.210.15:4596, id=13, length=100 NAS-Port-Type = Ethernet Service-Type = Login-User User-Name = "ldap" User-Password = "ldap" Called-Station-Id = "00:01:02:ad:64:f7" Calling-Station-Id = "00:c0:49:54:b5:43" NAS-Port = 1 Mon Apr 3 11:12:18 2006 : Debug: Processing the authorize section of radiusd.conf Mon Apr 3 11:12:18 2006 : Debug: modcall: entering group authorize for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 3 Mon Apr 3 11:12:18 2006 : Debug: rlm_realm: No '@' in User-Name = "ldap", looking up realm NULL Mon Apr 3 11:12:18 2006 : Debug: rlm_realm: No such realm "NULL" Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "suffix" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: rlm_eap: No EAP-Message, not doing EAP Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "eap" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "files" returns notfound for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: - authorize Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: performing user authorization for ldap Mon Apr 3 11:12:18 2006 : Debug: radius_xlat: '(uid=ldap)' Mon Apr 3 11:12:18 2006 : Debug: radius_xlat: 'ou=Sion, o=ad.ch' Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: attempting LDAP reconnection Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: closing existing LDAP connection Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: (re)connect to ad.ch:389, authentication 0 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: bind as / to ad.ch:389 Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: waiting for bind result ... Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: Bind was successful Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: performing search in ou=Sion, o=ad.ch, with filter (uid=ldap) Mon Apr 3 11:12:28 2006 : Error: rlm_ldap: ldap_search() failed: Operations error Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: search failed Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Apr 3 11:12:28 2006 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 3 Mon Apr 3 11:12:28 2006 : Debug: modcall[authorize]: module "ldap" returns fail for request 3 Mon Apr 3 11:12:28 2006 : Debug: modcall: group authorize returns fail for request 3 Mon Apr 3 11:12:28 2006 : Debug: Finished request 3 Mon Apr 3 11:12:28 2006 : Debug: Going to the next request Mon Apr 3 11:12:28 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:28 2006 : Debug: Waking up in 6 seconds... Mon Apr 3 11:12:34 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:34 2006 : Debug: Cleaning up request 3 ID 13 with timestamp 4430e6f2 Mon Apr 3 11:12:34 2006 : Debug: Nothing to do. Sleeping until we see a request.
Where can I fix the misstake which produce this error?
greets
dominique
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hello, Can you say me, which log-file I must control? I use already the other basename and also I use PAP. Greets Dominique PS: Sorry for my bad english! Which log-File Am Montag, den 03.04.2006, 14:42 +0100 schrieb Caines, Max:
Hi Dominique
There appears to be something wrong with the search base definition for your LDAP search. It looks like you are using the "traditional" LDAP
basename which goes "ou=mydepartment, o=mycompany, c=ch". Active Directory uses basenames that look like "dc=ad, dc=ch". Your LDAP server is
returning "operations error", so I should look in its log file for more details.
By the way, bear in mind that unless you use Microsoft IAS, you can only do RADIUS authentication against AD using PAP (i.e. users send passwords
in cleartext), which isn't too secure.
Max Caines
-----Original Message----- From: freeradius-users-bounces+max.caines=wlv.ac.uk@lists.freeradius.org [mailto:freeradius-users-bounces+max.caines=wlv.ac.uk@lists.fr eeradius.o rg]On Behalf Of domjullier@rhone.ch Sent: 03 April 2006 10:27 To: freeradius-users@lists.freeradius.org Subject: Problem with LDAP against Active Directory
Hi folks, I want authenticate users from a WLAN with freeradius. The Users are stored in the Active Directory of a Windows 2003 Server.
With some Tutorials from the Internet I have configured freeradius to make that.
Unfortunately the Authentication function not succesfully.
Thats the output from FreeRadius during the Authentication:
rad_recv: Access-Request packet from host 192.168.210.15:4596, id=13, length=100 NAS-Port-Type = Ethernet Service-Type = Login-User User-Name = "ldap" User-Password = "ldap" Called-Station-Id = "00:01:02:ad:64:f7" Calling-Station-Id = "00:c0:49:54:b5:43" NAS-Port = 1 Mon Apr 3 11:12:08 2006 : Debug: Processing the authorize section of radiusd.conf Mon Apr 3 11:12:08 2006 : Debug: modcall: entering group authorize for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 2 Mon Apr 3 11:12:08 2006 : Debug: rlm_realm: No '@' in User-Name = "ldap", looking up realm NULL Mon Apr 3 11:12:08 2006 : Debug: rlm_realm: No such realm "NULL" Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "suffix" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: rlm_eap: No EAP-Message, not doing EAP Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "eap" returns noop for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 2 Mon Apr 3 11:12:08 2006 : Debug: modcall[authorize]: module "files" returns notfound for request 2 Mon Apr 3 11:12:08 2006 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 2 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: - authorize Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: performing user authorization for ldap Mon Apr 3 11:12:08 2006 : Debug: radius_xlat: '(uid=ldap)' Mon Apr 3 11:12:08 2006 : Debug: radius_xlat: 'ou=Sion, o=ad.ch' Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: attempting LDAP reconnection Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: closing existing LDAP connection Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: (re)connect to ad.ch:389, authentication 0 Mon Apr 3 11:12:08 2006 : Debug: rlm_ldap: bind as / to ad.ch:389 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: waiting for bind result ... Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: Bind was successful Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: performing search in ou=Sion, o=ad.ch, with filter (uid=ldap) Mon Apr 3 11:12:18 2006 : Error: rlm_ldap: ldap_search() failed: Operations error Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: search failed Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 2 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "ldap" returns fail for request 2 Mon Apr 3 11:12:18 2006 : Debug: modcall: group authorize returns fail for request 2 Mon Apr 3 11:12:18 2006 : Debug: Finished request 2 Mon Apr 3 11:12:18 2006 : Debug: Going to the next request Mon Apr 3 11:12:18 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:18 2006 : Debug: Waking up in 6 seconds... rad_recv: Access-Request packet from host 192.168.210.15:4596, id=13, length=100 Mon Apr 3 11:12:18 2006 : Debug: Discarding duplicate request from client testnet:4596 - ID: 13 Mon Apr 3 11:12:18 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:18 2006 : Debug: Cleaning up request 2 ID 13 with timestamp 4430e6e8 Mon Apr 3 11:12:18 2006 : Debug: Nothing to do. Sleeping until we see a request. rad_recv: Access-Request packet from host 192.168.210.15:4596, id=13, length=100 NAS-Port-Type = Ethernet Service-Type = Login-User User-Name = "ldap" User-Password = "ldap" Called-Station-Id = "00:01:02:ad:64:f7" Calling-Station-Id = "00:c0:49:54:b5:43" NAS-Port = 1 Mon Apr 3 11:12:18 2006 : Debug: Processing the authorize section of radiusd.conf Mon Apr 3 11:12:18 2006 : Debug: modcall: entering group authorize for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 3 Mon Apr 3 11:12:18 2006 : Debug: rlm_realm: No '@' in User-Name = "ldap", looking up realm NULL Mon Apr 3 11:12:18 2006 : Debug: rlm_realm: No such realm "NULL" Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "suffix" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: rlm_eap: No EAP-Message, not doing EAP Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "eap" returns noop for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 3 Mon Apr 3 11:12:18 2006 : Debug: modcall[authorize]: module "files" returns notfound for request 3 Mon Apr 3 11:12:18 2006 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 3 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: - authorize Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: performing user authorization for ldap Mon Apr 3 11:12:18 2006 : Debug: radius_xlat: '(uid=ldap)' Mon Apr 3 11:12:18 2006 : Debug: radius_xlat: 'ou=Sion, o=ad.ch' Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: attempting LDAP reconnection Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: closing existing LDAP connection Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: (re)connect to ad.ch:389, authentication 0 Mon Apr 3 11:12:18 2006 : Debug: rlm_ldap: bind as / to ad.ch:389 Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: waiting for bind result ... Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: Bind was successful Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: performing search in ou=Sion, o=ad.ch, with filter (uid=ldap) Mon Apr 3 11:12:28 2006 : Error: rlm_ldap: ldap_search() failed: Operations error Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: search failed Mon Apr 3 11:12:28 2006 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Apr 3 11:12:28 2006 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 3 Mon Apr 3 11:12:28 2006 : Debug: modcall[authorize]: module "ldap" returns fail for request 3 Mon Apr 3 11:12:28 2006 : Debug: modcall: group authorize returns fail for request 3 Mon Apr 3 11:12:28 2006 : Debug: Finished request 3 Mon Apr 3 11:12:28 2006 : Debug: Going to the next request Mon Apr 3 11:12:28 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:28 2006 : Debug: Waking up in 6 seconds... Mon Apr 3 11:12:34 2006 : Debug: --- Walking the entire request list --- Mon Apr 3 11:12:34 2006 : Debug: Cleaning up request 3 ID 13 with timestamp 4430e6f2 Mon Apr 3 11:12:34 2006 : Debug: Nothing to do. Sleeping until we see a request.
Where can I fix the misstake which produce this error?
greets
dominique
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
List: I've been using free radius for about a month and learning as I go. But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd Any idea what could be causing this? Thanks Duane Cox Mon Apr 3 15:02:36 2006 : Auth: Login OK: [intermapper] (from client intermapper port 0) Mon Apr 3 15:03:06 2006 : Auth: Login OK: [intermapper] (from client intermapper port 0) Mon Apr 3 15:03:09 2006 : Error: Dropping conflicting packet from client intermapper:32769 - ID: 81 due to unfinished request 1345 Mon Apr 3 15:03:12 2006 : Error: Dropping conflicting packet from client intermapper:32769 - ID: 81 due to unfinished request 1345 Mon Apr 3 15:03:34 2006 : Error: Dropping conflicting packet from client omnilec2:1647 - ID: 62 due to unfinished request 1346 Mon Apr 3 15:03:38 2006 : Error: WARNING: Unresponsive child (id 32771) for request 1345 Mon Apr 3 15:03:39 2006 : Error: Dropping conflicting packet from client intermapper:32769 - ID: 83 due to unfinished request 1347 Mon Apr 3 15:03:40 2006 : Error: Dropping conflicting packet from client omnilec2:1647 - ID: 62 due to unfinished request 1346 Mon Apr 3 15:03:42 2006 : Error: Dropping conflicting packet from client intermapper:32769 - ID: 83 due to unfinished request 1347 Mon Apr 3 15:03:44 2006 : Error: Discarding duplicate request from client omnilec2:1647 - ID: 177 due to unfinished request 1348 Mon Apr 3 15:03:45 2006 : Error: Dropping conflicting packet from client omnilec2:1647 - ID: 62 due to unfinished request 1346 Mon Apr 3 15:03:49 2006 : Error: Discarding duplicate request from client omnilec2:1647 - ID: 177 due to unfinished request 1348 Mon Apr 3 15:03:50 2006 : Error: Dropping conflicting packet from client omnilec2:1647 - ID: 62 due to unfinished request 1346 Mon Apr 3 15:03:53 2006 : Error: Discarding duplicate request from client omnilec2:1647 - ID: 177 due to unfinished request 1348 Mon Apr 3 15:03:54 2006 : Error: Discarding duplicate request from client omnilec1:1647 - ID: 120 due to unfinished request 1349 Mon Apr 3 15:03:59 2006 : Error: Discarding duplicate request from client omnilec1:1647 - ID: 120 due to unfinished request 1349 Mon Apr 3 15:03:59 2006 : Error: Discarding duplicate request from client omnilec2:1647 - ID: 177 due to unfinished request 1348 Mon Apr 3 15:04:03 2006 : Error: Discarding duplicate request from client omnilec1:1647 - ID: 120 due to unfinished request 1349 Mon Apr 3 15:04:03 2006 : Error: WARNING: Unresponsive child (id 49156) for request 1346 Mon Apr 3 15:04:06 2006 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Mon Apr 3 15:04:09 2006 : Error: Discarding duplicate request from client omnilec1:1647 - ID: 120 due to unfinished request 1349 Mon Apr 3 15:04:09 2006 : Error: WARNING: Unresponsive child (id 16386) for request 1347 Mon Apr 3 15:04:09 2006 : Error: WARNING: Unresponsive child (id 65541) for request 1348
"Duane Cox" <duanec@mail.illicom.net> wrote:
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Usually it's because your database is slow or not responding. Alan DeKok.
This must be right, or on the right track because I have 2 radius servers with identical configuration and both share the same database. Both servers experience this outage at the same time... Thanks Duane Cox ----- Original Message ----- From: "Alan DeKok" <aland@ox.org> To: "Duane Cox" <duanec@mail.illicom.net>; "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Monday, April 03, 2006 3:33 PM Subject: Re: conflicts/duplicates need
"Duane Cox" <duanec@mail.illicom.net> wrote:
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Usually it's because your database is slow or not responding.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Mon 03 Apr 2006 23:08, Duane Cox wrote:
List:
I've been using free radius for about a month and learning as I go.
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Hi Duane Good to see you using FreeRADIUS :-) Probably you have a cron script of some kind running a report or vacuum on your database and it is not responding to RADIUS. Are you using the database for something else as well? -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Well I believe Alan is correct, that it must be related to the database because I have 2 radius servers both sharing the same database, and they both experience this outage at the exact same time. It lasts for about 45 seconds every several hours. I'm using unixODBC and MSSQL database, the database server is running on a dual proc system and 2 gigs of ram. During some of these outages (early morning) no one is using the database, only freeradius. I think I am going to have to check the performance monitors on the MSSQL server to see if there are any spikes or hangs during this time. (I don't think my problem is freeradius, freeradius is just suffering from the condition)
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Hi Duane Good to see you using FreeRADIUS :-) Probably you have a cron script of some kind running a report or vacuum on your database and it is not responding to RADIUS. Are you using the database for something else as well? -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
--- Duane Cox <duanec@mail.illicom.net> wrote:
Well I believe Alan is correct, that it must be related to the database because I have 2 radius servers both sharing the same database, and they both experience this outage at the exact same time. It lasts for about 45 seconds every several hours.
I'm using unixODBC and MSSQL database, the database server is running on a dual proc system and 2 gigs of ram.
During some of these outages (early morning) no one is using the database, only freeradius.
I think I am going to have to check the performance monitors on the MSSQL server to see if there are any spikes or hangs during this time. (I don't think my problem is freeradius, freeradius is just suffering from the condition)
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Hi Duane
Good to see you using FreeRADIUS :-)
Probably you have a cron script of some kind running a report or vacuum on your database and it is not responding to RADIUS. Are you using the database for something else as well?
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
-
Is the "outage" consistent? Is the a DB replication or backup scheduled at the time the outage occurs? Laker __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
No the outage is not consistant and there is not db backup or replication going on. The only thing that is consistant, is that both radius servers, each identical hardware/software/configs, experience the outage at the same time. Thanks Duane ----- Original Message ----- From: "Laker Netman" <laker_netman@yahoo.com> To: "Duane Cox" <duanec@mail.illicom.net>; "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Wednesday, April 05, 2006 12:34 PM Subject: Re: conflicts/duplicates need
--- Duane Cox <duanec@mail.illicom.net> wrote:
Well I believe Alan is correct, that it must be related to the database because I have 2 radius servers both sharing the same database, and they both experience this outage at the exact same time. It lasts for about 45 seconds every several hours.
I'm using unixODBC and MSSQL database, the database server is running on a dual proc system and 2 gigs of ram.
During some of these outages (early morning) no one is using the database, only freeradius.
I think I am going to have to check the performance monitors on the MSSQL server to see if there are any spikes or hangs during this time. (I don't think my problem is freeradius, freeradius is just suffering from the condition)
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Hi Duane
Good to see you using FreeRADIUS :-)
Probably you have a cron script of some kind running a report or vacuum on your database and it is not responding to RADIUS. Are you using the database for something else as well?
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
-
Is the "outage" consistent? Is the a DB replication or backup scheduled at the time the outage occurs?
Laker
__________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
Here is the debug of a packet, there is nothing special about this packet. This packet hits the radius server every 30 seconds to test availability, for monitoring purposes. What hangs is the release of the rlm_sql ... (using sql_unixodbc) Ready to process requests. rad_recv: Access-Request packet from host x.x.x.x:32769, id=253, length=51 User-Name = "intermapper" User-Password = "illicom" Processing the authorize section of radiusd.conf modcall: entering group authorize for request 0 modcall[authorize]: module "preprocess" returns ok for request 0 modcall[authorize]: module "chap" returns noop for request 0 modcall[authorize]: module "mschap" returns noop for request 0 rlm_realm: No '@' in User-Name = "intermapper", skipping NULL due to config. modcall[authorize]: module "domain" returns noop for request 0 rlm_realm: No '\' in User-Name = "intermapper", skipping NULL due to config. modcall[authorize]: module "ntdomain" returns noop for request 0 radius_xlat: 'intermapper' rlm_sql (sql): sql_set_user escaped user --> 'intermapper' radius_xlat: 'select id, username, attribute, value, op from radcheck where username = 'intermapper' order by id' rlm_sql (sql): Reserving sql socket id: 9 radius_xlat: '' radius_xlat: 'select id, username, attribute, value, op from radreply where username = 'intermapper' order by id' radius_xlat: 'select radgroupreply.id, radgroupreply.groupname, radgroupreply.attribute, radgroupreply.value, radgroupreply.op from radgroupreply, usergroup where usergroup.username = 'intermapper' and usergroup.groupname = radgroupreply.groupname order by radgroupreply.id' rlm_sql (sql): Released sql socket id: 9 modcall[authorize]: module "sql" returns ok for request 0 modcall[authorize]: module "files" returns notfound for request 0 modcall: leaving group authorize (returns ok) for request 0 auth: type Local auth: user supplied User-Password matches local User-Password Login OK: [intermapper] (from client intermapper port 0) Processing the post-auth section of radiusd.conf modcall: entering group post-auth for request 0 rlm_sql (sql): Processing sql_postauth radius_xlat: 'intermapper' rlm_sql (sql): sql_set_user escaped user --> 'intermapper' radius_xlat: 'insert into radauth (UserName, Password, RadReply, NASIPAddress, NASIdentifier, NASPort, NASPortType, CalledStationId, CallingStationId) values ('intermapper', 'illicom', 'Access-Accept', 'x.x.x.x', '', '', '', '', '')' rlm_sql (sql) in sql_postauth: query is insert into radauth (UserName, Password, RadReply, NASIPAddress, NASIdentifier, NASPort, NASPortType, CalledStationId, CallingStationId) values ('intermapper', 'illicom', 'Access-Accept', 'x.x.x.x', '', '', '', '', '') rlm_sql (sql): Reserving sql socket id: 8 30 - 45 (sometimes 60) second pause .... then finally... rlm_sql (sql): Released sql socket id: 8 and then radiusd processes packets that apparently it had buffered... During this 30-60 second pause of freeradius, I tested queries to the database with isql and everything returned fine. I also was able to use our billing/accounting client to pull data from the database and it was fine. There is no resource intensive application pulling data from the database when this is happening and all other db clients and communication goes uninterrupted. Any ideas?
I believe I found my answer... The SQL server is "dual homed" and had 2 default routes, one per interface. I have removed one of the default routes and haven't seen the problem. Thanks Duane Cox ----- Original Message ----- From: "Duane Cox" <duanec@mail.illicom.net> To: "Laker Netman" <laker_netman@yahoo.com>; "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Wednesday, April 05, 2006 2:03 PM Subject: Re: conflicts/duplicates need
No the outage is not consistant and there is not db backup or replication going on. The only thing that is consistant, is that both radius servers, each identical hardware/software/configs, experience the outage at the same time.
Thanks Duane
----- Original Message ----- From: "Laker Netman" <laker_netman@yahoo.com> To: "Duane Cox" <duanec@mail.illicom.net>; "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Wednesday, April 05, 2006 12:34 PM Subject: Re: conflicts/duplicates need
--- Duane Cox <duanec@mail.illicom.net> wrote:
Well I believe Alan is correct, that it must be related to the database because I have 2 radius servers both sharing the same database, and they both experience this outage at the exact same time. It lasts for about 45 seconds every several hours.
I'm using unixODBC and MSSQL database, the database server is running on a dual proc system and 2 gigs of ram.
During some of these outages (early morning) no one is using the database, only freeradius.
I think I am going to have to check the performance monitors on the MSSQL server to see if there are any spikes or hangs during this time. (I don't think my problem is freeradius, freeradius is just suffering from the condition)
But I've noticed that I get a period every few hours when freeradius doesn't authenticate. I'm not sure what the problem is, but here is the log as captured in /var/log/radiusd
Any idea what could be causing this?
Hi Duane
Good to see you using FreeRADIUS :-)
Probably you have a cron script of some kind running a report or vacuum on your database and it is not responding to RADIUS. Are you using the database for something else as well?
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
-
Is the "outage" consistent? Is the a DB replication or backup scheduled at the time the outage occurs?
Laker
__________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (6)
-
Alan DeKok -
Caines, Max -
Duane Cox -
Jullier Dominique -
Laker Netman -
Peter Nixon