I'm currently using freeradius2-2.1.7-2.el5 on CentOS 5.2 for Cisco and L2TP VPN user authentication (via a Sonicwall firewall), using LDAP back to a AD environment, with the Windows built in VPN client. (for very specific details of that environment see my post of Tue, Dec 1, 2009 at 6:31 PM ) The Cisco environment works flawlessly. Every time I attempt to log in it works. The Windows environment works, with one quirk, if no one has logged in for a while (~15-30 min), the next user gets: Thu Jan 14 19:31:51 2010 : Error: rlm_ldap: ldap_search() failed: LDAP connection lost. Thu Jan 14 19:31:51 2010 : Info: rlm_ldap: Attempting reconnect Thu Jan 14 19:31:51 2010 : Auth: Login OK: [user] (from client VPN port 0) The end user reports that the first attempt to login fails, but the second succeeds. Further attempts will succeed until it's been a while since anyone logged in. That's only true for VPN users, logging into a Cisco never causes the same issue - works every time. Both servers refer to the same ldap module. I only have about 4 VPN users right now, so I'm thinking it's not a load problem. In some respecting I'm thinking it's the reverse of a load problem - that once I have more users on the system there won't be a long period of time where no one has logged in, and so the problem will go away. Thoughts? I'd like for the user to (barring network issues) be able to log on the first time, every time. Thanks Rick
freeradius@corwyn.net wrote:
The Windows environment works, with one quirk, if no one has logged in for a while (~15-30 min), the next user gets:
Thu Jan 14 19:31:51 2010 : Error: rlm_ldap: ldap_search() failed: LDAP connection lost. Thu Jan 14 19:31:51 2010 : Info: rlm_ldap: Attempting reconnect Thu Jan 14 19:31:51 2010 : Auth: Login OK: [user] (from client VPN port 0)
You can change the timeout on the LDAP server. Maybe the LDAP client libraries also support a "keepalive".
The end user reports that the first attempt to login fails, but the second succeeds. Further attempts will succeed until it's been a while since anyone logged in.
If the first one fails, I would suspect it's because the ldap module times out trying to re-connect to the server. i.e. the "new connection" attempt takes 30-40 seconds. Go fix that.
That's only true for VPN users, logging into a Cisco never causes the same issue - works every time. Both servers refer to the same ldap module.
<shrug> Run the server in debugging mode to see why. If you're getting tiny amounts of traffic, this shouldn't be a problem. Alan DeKok.
At 08:33 PM 1/14/2010, freeradius@corwyn.net wrote:
The Windows environment works, with one quirk, if no one has logged in for a while (~15-30 min), the next user gets:
Here's the full log of one of those events (redacted): Two interesting points are noted with "***". The reconnect takes only moments when watching it flow by. rad_recv: Access-Request packet from host 10.4.1.2 port 4734, id=116, length=121 User-Name = "testuser" MS-CHAP-Challenge = 0xe23b19133fb8d89eeaddcea89d9917ee MS-CHAP2-Response = 0x01008875de342e3a72b85b591ede3516972e00000000000000008709a70df8e4f28d3f5d880e9558e580d723bc5d98c4a717 NAS-IP-Address = 10.4.1.2 NAS-Port = 0 server server_vpn { +- entering group authorize {...} ++[preprocess] returns ok [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' ++[mschap] returns ok rlm_ldap: Entering ldap_groupcmp() [files] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com [files] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details [files] expand: (&(sAMAccountname=%{Stripped-User-Name:-%{User-Name}})(objectClass=person)) -> (&(sAMAccountname=testuser)(objectClass=person)) rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=testuser)(objectClass=person)) **** **** rlm_ldap: ldap_search() failed: LDAP connection lost. rlm_ldap: Attempting reconnect rlm_ldap: attempting LDAP reconnection rlm_ldap: closing existing LDAP connection rlm_ldap: (re)connect to int.example.com:389, authentication 0 **** **** rlm_ldap: bind as CN=Admin_account,OU=Service Accounts,OU=Special User Accounts,OU=Enterprise,DC=int,DC=example,DC=com/wvyjCHCd2LJHcNrmpr0I to int.example.com:389 rlm_ldap: waiting for bind result ... rlm_ldap: Bind was successful rlm_ldap: performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=testuser)(objectClass=person)) rlm_ldap: ldap_release_conn: Release Id: 0 [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))) rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom)))) rlm_ldap: object not found rlm_ldap: ldap_release_conn: Release Id: 0 rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in CN=Joe Bob,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) rlm_ldap: performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) rlm_ldap::ldap_groupcmp: User found in group VPN_Users rlm_ldap: ldap_release_conn: Release Id: 0 [files] users: Matched entry DEFAULT at line 11 ++[files] returns ok [ldap] performing user authorization for testuser [ldap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details [ldap] expand: (&(sAMAccountname=%{Stripped-User-Name:-%{User-Name}})(objectClass=person)) -> (&(sAMAccountname=testuser)(objectClass=person)) [ldap] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=testuser)(objectClass=person)) [ldap] looking for check items in directory... [ldap] looking for reply items in directory... ***** ***** WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? [ldap] user testuser authorized to use remote access rlm_ldap: ldap_release_conn: Release Id: 0 ++[ldap] returns ok *** also odd. ++? if (Huntgroup-Name == "VPN_Huntgroup") ? Evaluating (Huntgroup-Name == "VPN_Huntgroup") -> TRUE ++? if (Huntgroup-Name == "VPN_Huntgroup") -> TRUE ++- entering if (Huntgroup-Name == "VPN_Huntgroup") {...} +++? if (Ldap-Group == "VPN_Users") rlm_ldap: Entering ldap_groupcmp() expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))) rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dJoe Bob\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom)))) rlm_ldap: object not found rlm_ldap: ldap_release_conn: Release Id: 0 rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in CN=Joe Bob,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) rlm_ldap: performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) rlm_ldap::ldap_groupcmp: User found in group VPN_Users rlm_ldap: ldap_release_conn: Release Id: 0 ? Evaluating (Ldap-Group == "VPN_Users") -> TRUE +++? if (Ldap-Group == "VPN_Users") -> TRUE +++- entering if (Ldap-Group == "VPN_Users") {...} ++++[ok] returns ok +++- if (Ldap-Group == "VPN_Users") returns ok +++ ... skipping else for request 6: Preceding "if" was taken ++- if (Huntgroup-Name == "VPN_Huntgroup") returns ok Found Auth-Type = MSCHAP +- entering group MS-CHAP {...} [mschap] Told to do MS-CHAPv2 for testuser with NT-Password [mschap] expand: --username=%{mschap:User-Name} -> --username=testuser [mschap] No NT-Domain was found in the User-Name. [mschap] expand: --domain=%{mschap:NT-Domain:-int.example.com} -> --domain=int.example.com [mschap] mschap2: e2 [mschap] expand: --challenge=%{mschap:Challenge:-00} -> --challenge=b80b4d4cbe4d692c [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=8709a70df8e4f28d3f5d880e9558e580d723bc5d98c4a717 Exec-Program output: NT_KEY: ABB81B23774917AE41C16F92C19D6965 Exec-Program-Wait: plaintext: NT_KEY: ABB81B23774917AE41C16F92C19D6965 Exec-Program: returned: 0 [mschap] adding MS-CHAPv2 MPPE keys ++[mschap] returns ok Login OK: [testuser] (from client VPN port 0) +- entering group post-auth {...} ++[exec] returns noop } # server server_vpn Sending Access-Accept of id 116 to 10.4.1.2 port 4734 Reply-Message := "Authorized Users Only" MS-CHAP2-Success = 0x01533d39363842343441374535383843394336413942443632343933444336304343444145313645394238 MS-MPPE-Recv-Key = 0x05ea5717340f74f2af887bf51c3712c6 MS-MPPE-Send-Key = 0x4443176296e087b447a514a7db4b6255 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 Finished request 6. Going to the next request Waking up in 4.9 seconds. Cleaning up request 6 ID 116 with timestamp +9831 Ready to process requests.
At 12:43 AM 1/20/2010, freeradius@corwyn.net wrote:
At 08:33 PM 1/14/2010, freeradius@corwyn.net wrote:
The Windows environment works, with one quirk, if no one has logged in for a while (~15-30 min), the next user gets:
It looks like the only difference (besides MSCHAP strings) between the first try and the second one is: [ldap] attempting LDAP reconnection [ldap] (re)connect to int.invtitle.com:389, authentication 0 [ldap] bind as CN=_sonicwall,OU=Service Accounts,OU=Special User Accounts,OU=Enterprise,DC=int,DC=example,DC=com/xxx to int.example.com:389 [ldap] waiting for bind result ... [ldap] Bind was successful It takes only moments, but still fails the first time. Rick
participants (2)
-
Alan DeKok -
freeradius＠corwyn.net