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.