HI, Wed Jul 14 10:51:16 2010 : Info: [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=a3492c6411f5548251a05606aa028964d34b69c58e61c7d5 Wed Jul 14 10:51:16 2010 : Debug: Exec-Program output: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:16 2010 : Debug: Exec-Program-Wait: plaintext: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:16 2010 : Debug: Exec-Program: returned: 1 ^^ is that not the problem? -James --On Wednesday, July 14, 2010 11:22:43 -0400 freeradius@corwyn.net wrote:

We're in the process of upgrading from Windows 2003 to 2008 R2. Our Linux systems are CentOS 5.5. Looks like samba won't auth against 2008 r2.

So we upgraded to samba 3x, but that appears to break freeradius. Hrm.

We're using freeradius to auth VPN users that are connecting from a sonicwall firewall, using the windows l2tp client.

freeradius2-2.1.8-2.el5

Here's the output from radiusd -xX

rad_recv: Access-Request packet from host 10.4.1.2 port 2452, id=213, length=124 User-Name = "useraccount" MS-CHAP-Challenge = 0xc527897da16351a24f3a92d91b066df1 MS-CHAP2-Response = 0x0100f3dd5207d539bd0d7e1f7be50178d3820000000000000000a3492c6411f5548251a 05606aa028964d34b69c58e61c7d5 NAS-IP-Address = 10.4.1.2 NAS-Port = 0 Wed Jul 14 10:51:16 2010 : Info: server server_vpn { Wed Jul 14 10:51:16 2010 : Info: +- entering group authorize {...} Wed Jul 14 10:51:16 2010 : Info: ++[preprocess] returns ok Wed Jul 14 10:51:16 2010 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Wed Jul 14 10:51:16 2010 : Info: ++[mschap] returns ok Wed Jul 14 10:51:16 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 10:51:16 2010 : Info: [files] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 10:51:16 2010 : Info: [files] expand: %{Stripped-User-Name} -> Wed Jul 14 10:51:16 2010 : Info: [files] ... expanding second conditional Wed Jul 14 10:51:16 2010 : Info: [files] expand: %{User-Name} -> useraccount Wed Jul 14 10:51:16 2010 : Info: [files] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] attempting LDAP reconnection Wed Jul 14 10:51:16 2010 : Debug: [ldap] (re)connect to int.example.com:389, authentication 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] bind as CN=_sonicwall,OU=Service Accounts,OU=Special User Accounts,OU=Enterprise,DC=int,DC=example,DC=com/wvyjCHCd2LJHcNrmpr0I to int.example.com:389 Wed Jul 14 10:51:16 2010 : Debug: [ldap] waiting for bind result ... Wed Jul 14 10:51:16 2010 : Debug: [ldap] Bind was successful Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:16 2010 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 10:51:16 2010 : Debug: [ldap] object not found Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 10:51:16 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:16 2010 : Info: [files] users: Matched entry DEFAULT at line 11 Wed Jul 14 10:51:16 2010 : Info: ++[files] returns ok Wed Jul 14 10:51:16 2010 : Info: [ldap] performing user authorization for useraccount Wed Jul 14 10:51:16 2010 : Info: [ldap] expand: %{Stripped-User-Name} -> Wed Jul 14 10:51:16 2010 : Info: [ldap] ... expanding second conditional Wed Jul 14 10:51:16 2010 : Info: [ldap] expand: %{User-Name} -> useraccount Wed Jul 14 10:51:16 2010 : Info: [ldap] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:16 2010 : Info: [ldap] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:16 2010 : Info: [ldap] looking for check items in directory... Wed Jul 14 10:51:16 2010 : Info: [ldap] looking for reply items in directory... Wed Jul 14 10:51:16 2010 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Wed Jul 14 10:51:16 2010 : Info: [ldap] user useraccount authorized to use remote access Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:16 2010 : Info: ++[ldap] returns ok Wed Jul 14 10:51:16 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") Wed Jul 14 10:51:16 2010 : Info: ? Evaluating (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 10:51:16 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 10:51:16 2010 : Info: ++- entering if (Huntgroup-Name == "VPN_Huntgroup") {...} Wed Jul 14 10:51:16 2010 : Info: +++? if (Ldap-Group == "VPN_Users") Wed Jul 14 10:51:16 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 10:51:16 2010 : Info: expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 10:51:16 2010 : Info: expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 10:51:16 2010 : Debug: [ldap] object not found Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 10:51:16 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 10:51:16 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 10:51:16 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:16 2010 : Info: ? Evaluating (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 10:51:16 2010 : Info: +++? if (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 10:51:16 2010 : Info: +++- entering if (Ldap-Group == "VPN_Users") {...} Wed Jul 14 10:51:16 2010 : Info: ++++[ok] returns ok Wed Jul 14 10:51:16 2010 : Info: +++- if (Ldap-Group == "VPN_Users") returns ok Wed Jul 14 10:51:16 2010 : Info: +++ ... skipping else for request 0: Preceding "if" was taken Wed Jul 14 10:51:16 2010 : Info: ++- if (Huntgroup-Name == "VPN_Huntgroup") returns ok Wed Jul 14 10:51:16 2010 : Info: Found Auth-Type = MSCHAP Wed Jul 14 10:51:16 2010 : Info: +- entering group MS-CHAP {...} Wed Jul 14 10:51:16 2010 : Info: [mschap] Told to do MS-CHAPv2 for useraccount with NT-Password Wed Jul 14 10:51:16 2010 : Info: [mschap] expand: --username=%{mschap:User-Name} -> --username=useraccount Wed Jul 14 10:51:16 2010 : Info: [mschap] No NT-Domain was found in the User-Name. Wed Jul 14 10:51:16 2010 : Info: [mschap] expand: --domain=%{mschap:NT-Domain:-int.example.com} -> --domain= Wed Jul 14 10:51:16 2010 : Info: [mschap] mschap2: c5 Wed Jul 14 10:51:16 2010 : Info: [mschap] expand: --challenge=%{mschap:Challenge:-00} -> --challenge=a7b7f9db587b6d58 Wed Jul 14 10:51:16 2010 : Info: [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=a3492c6411f5548251a05606aa028964d34b69c58e61c7d5 Wed Jul 14 10:51:16 2010 : Debug: Exec-Program output: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:16 2010 : Debug: Exec-Program-Wait: plaintext: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:16 2010 : Debug: Exec-Program: returned: 1 Wed Jul 14 10:51:16 2010 : Info: [mschap] External script failed. Wed Jul 14 10:51:16 2010 : Info: [mschap] FAILED: MS-CHAP2-Response is incorrect Wed Jul 14 10:51:16 2010 : Info: ++[mschap] returns reject Wed Jul 14 10:51:16 2010 : Info: Failed to authenticate the user. Wed Jul 14 10:51:16 2010 : Auth: Login incorrect: [useraccount] (from client VPN port 0) Wed Jul 14 10:51:16 2010 : Info: } # server server_vpn Wed Jul 14 10:51:16 2010 : Info: Using Post-Auth-Type Reject Wed Jul 14 10:51:16 2010 : Info: +- entering group REJECT {...} Wed Jul 14 10:51:16 2010 : Info: [attr_filter.access_reject] expand: %{User-Name} -> useraccount Wed Jul 14 10:51:16 2010 : Debug: attr_filter: Matched entry DEFAULT at line 11 Wed Jul 14 10:51:16 2010 : Info: ++[attr_filter.access_reject] returns updated Wed Jul 14 10:51:16 2010 : Info: Delaying reject of request 0 for 1 seconds Wed Jul 14 10:51:16 2010 : Debug: Going to the next request Wed Jul 14 10:51:16 2010 : Debug: Waking up in 0.9 seconds. Wed Jul 14 10:51:17 2010 : Info: Sending delayed reject for request 0 Sending Access-Reject of id 213 to 10.4.1.2 port 2452 Reply-Message := "Authorized Users Only" Wed Jul 14 10:51:17 2010 : Debug: Waking up in 4.9 seconds. Wed Jul 14 10:51:22 2010 : Info: Cleaning up request 0 ID 213 with timestamp +52 Wed Jul 14 10:51:22 2010 : Info: Ready to process requests. rad_recv: Access-Request packet from host 10.4.1.2 port 2452, id=214, length=124 User-Name = "useraccount" MS-CHAP-Challenge = 0x74b06b183b08ce9d41907535cafb1ed3 MS-CHAP2-Response = 0x01000bd21f7a41e97a616ca8dd0634f4e5230000000000000000d4c66c9dd3cabae77ed fe564c745de287968a0441d0df3a5 NAS-IP-Address = 10.4.1.2 NAS-Port = 0 Wed Jul 14 10:51:45 2010 : Info: server server_vpn { Wed Jul 14 10:51:45 2010 : Info: +- entering group authorize {...} Wed Jul 14 10:51:45 2010 : Info: ++[preprocess] returns ok Wed Jul 14 10:51:45 2010 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Wed Jul 14 10:51:45 2010 : Info: ++[mschap] returns ok Wed Jul 14 10:51:45 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 10:51:45 2010 : Info: [files] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 10:51:45 2010 : Info: [files] expand: %{Stripped-User-Name} -> Wed Jul 14 10:51:45 2010 : Info: [files] ... expanding second conditional Wed Jul 14 10:51:45 2010 : Info: [files] expand: %{User-Name} -> useraccount Wed Jul 14 10:51:45 2010 : Info: [files] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:45 2010 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 10:51:45 2010 : Debug: [ldap] object not found Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 10:51:45 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:45 2010 : Info: [files] users: Matched entry DEFAULT at line 11 Wed Jul 14 10:51:45 2010 : Info: ++[files] returns ok Wed Jul 14 10:51:45 2010 : Info: [ldap] performing user authorization for useraccount Wed Jul 14 10:51:45 2010 : Info: [ldap] expand: %{Stripped-User-Name} -> Wed Jul 14 10:51:45 2010 : Info: [ldap] ... expanding second conditional Wed Jul 14 10:51:45 2010 : Info: [ldap] expand: %{User-Name} -> useraccount Wed Jul 14 10:51:45 2010 : Info: [ldap] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:45 2010 : Info: [ldap] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 10:51:45 2010 : Info: [ldap] looking for check items in directory... Wed Jul 14 10:51:45 2010 : Info: [ldap] looking for reply items in directory... Wed Jul 14 10:51:45 2010 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Wed Jul 14 10:51:45 2010 : Info: [ldap] user useraccount authorized to use remote access Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:45 2010 : Info: ++[ldap] returns ok Wed Jul 14 10:51:45 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") Wed Jul 14 10:51:45 2010 : Info: ? Evaluating (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 10:51:45 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 10:51:45 2010 : Info: ++- entering if (Huntgroup-Name == "VPN_Huntgroup") {...} Wed Jul 14 10:51:45 2010 : Info: +++? if (Ldap-Group == "VPN_Users") Wed Jul 14 10:51:45 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 10:51:45 2010 : Info: expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 10:51:45 2010 : Info: expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 10:51:45 2010 : Debug: [ldap] object not found Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 10:51:45 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 10:51:45 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 10:51:45 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 10:51:45 2010 : Info: ? Evaluating (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 10:51:45 2010 : Info: +++? if (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 10:51:45 2010 : Info: +++- entering if (Ldap-Group == "VPN_Users") {...} Wed Jul 14 10:51:45 2010 : Info: ++++[ok] returns ok Wed Jul 14 10:51:45 2010 : Info: +++- if (Ldap-Group == "VPN_Users") returns ok Wed Jul 14 10:51:45 2010 : Info: +++ ... skipping else for request 1: Preceding "if" was taken Wed Jul 14 10:51:45 2010 : Info: ++- if (Huntgroup-Name == "VPN_Huntgroup") returns ok Wed Jul 14 10:51:45 2010 : Info: Found Auth-Type = MSCHAP Wed Jul 14 10:51:45 2010 : Info: +- entering group MS-CHAP {...} Wed Jul 14 10:51:45 2010 : Info: [mschap] Told to do MS-CHAPv2 for useraccount with NT-Password Wed Jul 14 10:51:45 2010 : Info: [mschap] expand: --username=%{mschap:User-Name} -> --username=useraccount Wed Jul 14 10:51:45 2010 : Info: [mschap] No NT-Domain was found in the User-Name. Wed Jul 14 10:51:45 2010 : Info: [mschap] expand: --domain=%{mschap:NT-Domain:-int.example.com} -> --domain= Wed Jul 14 10:51:45 2010 : Info: [mschap] mschap2: 74 Wed Jul 14 10:51:45 2010 : Info: [mschap] expand: --challenge=%{mschap:Challenge:-00} -> --challenge=03128051e813c832 Wed Jul 14 10:51:45 2010 : Info: [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=d4c66c9dd3cabae77edfe564c745de287968a0441d0df3a5 Wed Jul 14 10:51:45 2010 : Debug: Exec-Program output: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:45 2010 : Debug: Exec-Program-Wait: plaintext: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:45 2010 : Debug: Exec-Program: returned: 1 Wed Jul 14 10:51:45 2010 : Info: [mschap] External script failed. Wed Jul 14 10:51:45 2010 : Info: [mschap] FAILED: MS-CHAP2-Response is incorrect Wed Jul 14 10:51:45 2010 : Info: ++[mschap] returns reject Wed Jul 14 10:51:45 2010 : Info: Failed to authenticate the user. Wed Jul 14 10:51:45 2010 : Auth: Login incorrect: [useraccount] (from client VPN port 0) Wed Jul 14 10:51:45 2010 : Info: } # server server_vpn Wed Jul 14 10:51:45 2010 : Info: Using Post-Auth-Type Reject Wed Jul 14 10:51:45 2010 : Info: +- entering group REJECT {...} Wed Jul 14 10:51:45 2010 : Info: [attr_filter.access_reject] expand: %{User-Name} -> useraccount Wed Jul 14 10:51:45 2010 : Debug: attr_filter: Matched entry DEFAULT at line 11 Wed Jul 14 10:51:45 2010 : Info: ++[attr_filter.access_reject] returns updated Wed Jul 14 10:51:45 2010 : Info: Delaying reject of request 1 for 1 seconds Wed Jul 14 10:51:45 2010 : Debug: Going to the next request Wed Jul 14 10:51:45 2010 : Debug: Waking up in 0.9 seconds. Wed Jul 14 10:51:46 2010 : Info: Sending delayed reject for request 1 Sending Access-Reject of id 214 to 10.4.1.2 port 2452 Reply-Message := "Authorized Users Only" Wed Jul 14 10:51:46 2010 : Debug: Waking up in 4.9 seconds. Wed Jul 14 10:51:51 2010 : Info: Cleaning up request 1 ID 214 with timestamp +81 Wed Jul 14 10:51:51 2010 : Info: Ready to process requests.

Now, I've seen that problem before of : Wed Jul 14 10:51:45 2010 : Debug: Exec-Program-Wait: plaintext: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022)

whenever I patch samba. And I usually fix it with: chgrp radiusd /var/cache/samba/winbindd_privileged

but with the upgrade to samba3x that doesn't work, because the group is now wbpriv.

So instead I added the radiusd user to the wbpriv group: usermod -a -G wbpriv radiusd

But it still fails, tho noting leaps out oat me from the output: rad_recv: Access-Request packet from host 10.4.1.2 port 2452, id=224, length=124 User-Name = "useraccount" MS-CHAP-Challenge = 0x36ad83e8c48bd67061d4059cd1a5e3a1 MS-CHAP2-Response = 0x01000c60a44ccac150a8d8961f218cfd07b5000000000000000000be3e466ff82a106ee 9e3144e442c6caa1bcb71636031b6 NAS-IP-Address = 10.4.1.2 NAS-Port = 0 Wed Jul 14 11:18:08 2010 : Info: server server_vpn { Wed Jul 14 11:18:08 2010 : Info: +- entering group authorize {...} Wed Jul 14 11:18:08 2010 : Info: ++[preprocess] returns ok Wed Jul 14 11:18:08 2010 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Wed Jul 14 11:18:08 2010 : Info: ++[mschap] returns ok Wed Jul 14 11:18:08 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 11:18:08 2010 : Info: [files] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 11:18:08 2010 : Info: [files] expand: %{Stripped-User-Name} -> Wed Jul 14 11:18:08 2010 : Info: [files] ... expanding second conditional Wed Jul 14 11:18:08 2010 : Info: [files] expand: %{User-Name} -> useraccount Wed Jul 14 11:18:08 2010 : Info: [files] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:08 2010 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 11:18:08 2010 : Debug: [ldap] object not found Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 11:18:08 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:08 2010 : Info: [files] users: Matched entry DEFAULT at line 11 Wed Jul 14 11:18:08 2010 : Info: ++[files] returns ok Wed Jul 14 11:18:08 2010 : Info: [ldap] performing user authorization for useraccount Wed Jul 14 11:18:08 2010 : Info: [ldap] expand: %{Stripped-User-Name} -> Wed Jul 14 11:18:08 2010 : Info: [ldap] ... expanding second conditional Wed Jul 14 11:18:08 2010 : Info: [ldap] expand: %{User-Name} -> useraccount Wed Jul 14 11:18:08 2010 : Info: [ldap] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:08 2010 : Info: [ldap] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:08 2010 : Info: [ldap] looking for check items in directory... Wed Jul 14 11:18:08 2010 : Info: [ldap] looking for reply items in directory... Wed Jul 14 11:18:08 2010 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Wed Jul 14 11:18:08 2010 : Info: [ldap] user useraccount authorized to use remote access Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:08 2010 : Info: ++[ldap] returns ok Wed Jul 14 11:18:08 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") Wed Jul 14 11:18:08 2010 : Info: ? Evaluating (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 11:18:08 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 11:18:08 2010 : Info: ++- entering if (Huntgroup-Name == "VPN_Huntgroup") {...} Wed Jul 14 11:18:08 2010 : Info: +++? if (Ldap-Group == "VPN_Users") Wed Jul 14 11:18:08 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 11:18:08 2010 : Info: expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 11:18:08 2010 : Info: expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 11:18:08 2010 : Debug: [ldap] object not found Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 11:18:08 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 11:18:08 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 11:18:08 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:08 2010 : Info: ? Evaluating (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 11:18:08 2010 : Info: +++? if (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 11:18:08 2010 : Info: +++- entering if (Ldap-Group == "VPN_Users") {...} Wed Jul 14 11:18:08 2010 : Info: ++++[ok] returns ok Wed Jul 14 11:18:08 2010 : Info: +++- if (Ldap-Group == "VPN_Users") returns ok Wed Jul 14 11:18:08 2010 : Info: +++ ... skipping else for request 7: Preceding "if" was taken Wed Jul 14 11:18:08 2010 : Info: ++- if (Huntgroup-Name == "VPN_Huntgroup") returns ok Wed Jul 14 11:18:08 2010 : Info: Found Auth-Type = MSCHAP Wed Jul 14 11:18:08 2010 : Info: +- entering group MS-CHAP {...} Wed Jul 14 11:18:08 2010 : Info: [mschap] Told to do MS-CHAPv2 for useraccount with NT-Password Wed Jul 14 11:18:08 2010 : Info: [mschap] expand: --username=%{mschap:User-Name} -> --username=useraccount Wed Jul 14 11:18:08 2010 : Info: [mschap] No NT-Domain was found in the User-Name. Wed Jul 14 11:18:08 2010 : Info: [mschap] expand: --domain=%{mschap:NT-Domain:-int.example.com} -> --domain= Wed Jul 14 11:18:08 2010 : Info: [mschap] mschap2: 36 Wed Jul 14 11:18:08 2010 : Info: [mschap] expand: --challenge=%{mschap:Challenge:-00} -> --challenge=5826d0d6b7d4ed8f Wed Jul 14 11:18:08 2010 : Info: [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=00be3e466ff82a106ee9e3144e442c6caa1bcb71636031b6 Wed Jul 14 11:18:08 2010 : Debug: Exec-Program output: NT_KEY: 580B07A2801E5E9B5CDD55BC23C38D1F Wed Jul 14 11:18:08 2010 : Debug: Exec-Program-Wait: plaintext: NT_KEY: 580B07A2801E5E9B5CDD55BC23C38D1F Wed Jul 14 11:18:08 2010 : Debug: Exec-Program: returned: 0 Wed Jul 14 11:18:08 2010 : Info: [mschap] adding MS-CHAPv2 MPPE keys Wed Jul 14 11:18:08 2010 : Info: ++[mschap] returns ok Wed Jul 14 11:18:08 2010 : Auth: Login OK: [useraccount] (from client VPN port 0) Wed Jul 14 11:18:08 2010 : Info: +- entering group post-auth {...} Wed Jul 14 11:18:08 2010 : Info: ++[exec] returns noop Wed Jul 14 11:18:08 2010 : Info: } # server server_vpn Sending Access-Accept of id 224 to 10.4.1.2 port 2452 Reply-Message := "Authorized Users Only" MS-CHAP2-Success = 0x01533d45453444463034303730304331303545384245463834323743454544353433303 841303643454530 MS-MPPE-Recv-Key = 0x908aea21b6fbe22426feafd473d29657 MS-MPPE-Send-Key = 0xe2cddf5bd3f2aaa193fbce0410b840e8 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 Wed Jul 14 11:18:08 2010 : Info: Finished request 7. Wed Jul 14 11:18:08 2010 : Debug: Going to the next request Wed Jul 14 11:18:08 2010 : Debug: Waking up in 4.9 seconds. Wed Jul 14 11:18:13 2010 : Info: Cleaning up request 7 ID 224 with timestamp +635 Wed Jul 14 11:18:13 2010 : Info: Ready to process requests. rad_recv: Access-Request packet from host 10.4.1.2 port 2452, id=225, length=124 User-Name = "useraccount" MS-CHAP-Challenge = 0x2693887b8edc90b7c766c9108f14d937 MS-CHAP2-Response = 0x0100af58b67bf00cc423c52b0a65b1f491000000000000000000d59dccc1f4e99c19be1 ded3a3a771e49bfbb14ec62424311 NAS-IP-Address = 10.4.1.2 NAS-Port = 0 Wed Jul 14 11:18:38 2010 : Info: server server_vpn { Wed Jul 14 11:18:38 2010 : Info: +- entering group authorize {...} Wed Jul 14 11:18:38 2010 : Info: ++[preprocess] returns ok Wed Jul 14 11:18:38 2010 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Wed Jul 14 11:18:38 2010 : Info: ++[mschap] returns ok Wed Jul 14 11:18:38 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 11:18:38 2010 : Info: [files] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 11:18:38 2010 : Info: [files] expand: %{Stripped-User-Name} -> Wed Jul 14 11:18:38 2010 : Info: [files] ... expanding second conditional Wed Jul 14 11:18:38 2010 : Info: [files] expand: %{User-Name} -> useraccount Wed Jul 14 11:18:38 2010 : Info: [files] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:38 2010 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 11:18:38 2010 : Debug: [ldap] object not found Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 11:18:38 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:38 2010 : Info: [files] users: Matched entry DEFAULT at line 11 Wed Jul 14 11:18:38 2010 : Info: ++[files] returns ok Wed Jul 14 11:18:38 2010 : Info: [ldap] performing user authorization for useraccount Wed Jul 14 11:18:38 2010 : Info: [ldap] expand: %{Stripped-User-Name} -> Wed Jul 14 11:18:38 2010 : Info: [ldap] ... expanding second conditional Wed Jul 14 11:18:38 2010 : Info: [ldap] expand: %{User-Name} -> useraccount Wed Jul 14 11:18:38 2010 : Info: [ldap] expand: (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) -> (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:38 2010 : Info: [ldap] expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(sAMAccountname=useraccount)(objectClass=person)) Wed Jul 14 11:18:38 2010 : Info: [ldap] looking for check items in directory... Wed Jul 14 11:18:38 2010 : Info: [ldap] looking for reply items in directory... Wed Jul 14 11:18:38 2010 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Wed Jul 14 11:18:38 2010 : Info: [ldap] user useraccount authorized to use remote access Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:38 2010 : Info: ++[ldap] returns ok Wed Jul 14 11:18:38 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") Wed Jul 14 11:18:38 2010 : Info: ? Evaluating (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 11:18:38 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup") -> TRUE Wed Jul 14 11:18:38 2010 : Info: ++- entering if (Huntgroup-Name == "VPN_Huntgroup") {...} Wed Jul 14 11:18:38 2010 : Info: +++? if (Ldap-Group == "VPN_Users") Wed Jul 14 11:18:38 2010 : Debug: [ldap] Entering ldap_groupcmp() Wed Jul 14 11:18:38 2010 : Info: expand: OU=Enterprise,DC=int,DC=example,DC=com -> OU=Enterprise,DC=int,DC=example,DC=com Wed Jul 14 11:18:38 2010 : Info: expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectCl ass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))) Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in OU=Enterprise,DC=int,DC=example,DC=com, with filter (&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexampl e\2cDC\3dcom)))) Wed Jul 14 11:18:38 2010 : Debug: [ldap] object not found Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in CN=User Account,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with filter (objectclass=*) Wed Jul 14 11:18:38 2010 : Debug: [ldap] performing search in CN=VPN_Users,OU=Security Groups,OU=Enterprise,DC=int,DC=example,DC=com, with filter (cn=VPN_Users) Wed Jul 14 11:18:38 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group VPN_Users Wed Jul 14 11:18:38 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Jul 14 11:18:38 2010 : Info: ? Evaluating (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 11:18:38 2010 : Info: +++? if (Ldap-Group == "VPN_Users") -> TRUE Wed Jul 14 11:18:38 2010 : Info: +++- entering if (Ldap-Group == "VPN_Users") {...} Wed Jul 14 11:18:38 2010 : Info: ++++[ok] returns ok Wed Jul 14 11:18:38 2010 : Info: +++- if (Ldap-Group == "VPN_Users") returns ok Wed Jul 14 11:18:38 2010 : Info: +++ ... skipping else for request 8: Preceding "if" was taken Wed Jul 14 11:18:38 2010 : Info: ++- if (Huntgroup-Name == "VPN_Huntgroup") returns ok Wed Jul 14 11:18:38 2010 : Info: Found Auth-Type = MSCHAP Wed Jul 14 11:18:38 2010 : Info: +- entering group MS-CHAP {...} Wed Jul 14 11:18:38 2010 : Info: [mschap] Told to do MS-CHAPv2 for useraccount with NT-Password Wed Jul 14 11:18:38 2010 : Info: [mschap] expand: --username=%{mschap:User-Name} -> --username=useraccount Wed Jul 14 11:18:38 2010 : Info: [mschap] No NT-Domain was found in the User-Name. Wed Jul 14 11:18:38 2010 : Info: [mschap] expand: --domain=%{mschap:NT-Domain:-int.example.com} -> --domain= Wed Jul 14 11:18:38 2010 : Info: [mschap] mschap2: 26 Wed Jul 14 11:18:38 2010 : Info: [mschap] expand: --challenge=%{mschap:Challenge:-00} -> --challenge=6349848fd05003ee Wed Jul 14 11:18:38 2010 : Info: [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=d59dccc1f4e99c19be1ded3a3a771e49bfbb14ec62424311 Wed Jul 14 11:18:38 2010 : Debug: Exec-Program output: NT_KEY: 580B07A2801E5E9B5CDD55BC23C38D1F Wed Jul 14 11:18:38 2010 : Debug: Exec-Program-Wait: plaintext: NT_KEY: 580B07A2801E5E9B5CDD55BC23C38D1F Wed Jul 14 11:18:38 2010 : Debug: Exec-Program: returned: 0 Wed Jul 14 11:18:38 2010 : Info: [mschap] adding MS-CHAPv2 MPPE keys Wed Jul 14 11:18:38 2010 : Info: ++[mschap] returns ok Wed Jul 14 11:18:38 2010 : Auth: Login OK: [useraccount] (from client VPN port 0) Wed Jul 14 11:18:38 2010 : Info: +- entering group post-auth {...} Wed Jul 14 11:18:38 2010 : Info: ++[exec] returns noop Wed Jul 14 11:18:38 2010 : Info: } # server server_vpn Sending Access-Accept of id 225 to 10.4.1.2 port 2452 Reply-Message := "Authorized Users Only" MS-CHAP2-Success = 0x01533d33333944463630393339414534313746383533333841434436324439374137343 844413541313936 MS-MPPE-Recv-Key = 0xd81d386eb6bd95dcd85badccd21036b4 MS-MPPE-Send-Key = 0x1415b0a4e0f2d9063a9b0d0e92e2869b MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 Wed Jul 14 11:18:38 2010 : Info: Finished request 8. Wed Jul 14 11:18:38 2010 : Debug: Going to the next request Wed Jul 14 11:18:38 2010 : Debug: Waking up in 4.9 seconds. Wed Jul 14 11:18:43 2010 : Info: Cleaning up request 8 ID 225 with timestamp +665 Wed Jul 14 11:18:43 2010 : Info: Ready to process requests.

Any ideas?

Here are the complete details of our config:

FreeRadius 2.1.8

Setup, configuration, troubleshooting instructions, on CentOS 5.x Goals: o Authentication telnet sessions for Cisco switches against AD for a specific security group (Infrastructure) o Authentication for VPN users using MSCHAP on a sonicwall firewall using a Windows VPN client with L2TP against AD for a specific security group (VPN_Users)

Assumptions: SELinux is disabled Access is required on (the default of) 1812/udp and 1813/tcp Install The linux site for the rpm download of freeradius2 is:

Create /etc/yum.repos.d/freeradius2.repo:

[freeradius2] name=Freeradius2 baseurl=http://people.redhat.com/jdennis/freeradius-rhel-centos enabled=1 gpgcheck=0

Install freeradius2: yum clean all yum install freeradius2 freeradius2-utils freeradius2-ldap

Enable FreeRadius to start on boot: chkconfig radiusd on

To start the freeRadius service service radiusd start

To run the service in debug mode (which you should be doing until everything works): service radiusd stop radiusd –X Quirks If you get an error from the output of radiusd –X along the lines of:

Exec-Program output: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/cache/samba/winbindd_privileged are set correctly. (0xc0000022)

then the issue is that radiusd doesn't have access to the winbindd_privileged folder. You can fix with:

chgrp radiusd /var/cache/samba/winbindd_privileged usermod -a -G wbpriv radiusd ### not this I don't think chmod g+rw /var/cache/samba/winbindd_privileged Configuration See

Note that the configuring of SAMBA, kerberos, and adding to the domain should already be done as part of the default Linux install, see h:\is\operating system\Linux\Guide_linux.doc Verify that a user in the domain can be authenticated: wbinfo -a user%password Try the same login with the program, which is what FreeRADIUS will be using: ntlm_auth --request-nt-key --domain=MYDOMAIN --username=user --password=password /etc/raddb/radiusd.conf (see Appendix C)

Update max_requests to # users * 256

Add to the end of the auth listen {..} (to permit groups of clients) clients = disambiguate

Add to the end of the acct listen {..} (to permit groups of clients) clients = disambiguate

In log{..}

auth = yes (to log authentication requests) /etc/raddb/huntgroups huntgroups let you restrict which clients are associated with which user. You will need to add each IP of each device that will be using the RADIUS server, and associate it with the correct huntgroup. This will let the /etc/raddb/users file associate the user with the appropriate device:

/etc/radbb/huntgroups: Cisco_Huntgroup NAS-IP-Address == 10.100.0.1 Cisco_Huntgroup NAS-IP-Address == 10.100.0.2 Cisco_Huntgroup NAS-IP-Address == 10.100.0.3 … VPN_Huntgroup NAS-IP-Address == 10.4.1.2

/etc/raddb/modules/ntlm_auth Update the /modules/ntlm_auth module: (to enable ntlm_auth as an authentication method)

exec ntlm_auth { wait = yes program = "/usr/bin/ntlm_auth ntlm_auth --request-nt-key --domain=example.com -username=%{mschap:User-Name} --password=%{User-Password}" } /etc/raddb/modules/ldap If this file is missing, you need to install the RPM for freeradius2-ldap.

This section is one of the biggest pains to configure, as all of your LDAP strings need to be 100% correct, and they will be very specific to the environment. Of course, update server, identify, password, basedn for your own environment.

You will need a user account in AD to permit the bind to LDAP. In this example, that account is in: CN=_useraccount,OU=Service Accounts,OU=Special User Accounts,OU=Enterprise,DC=example,DC=com

In this example, the Security groups are located in (or below): OU=Enterprise,DC=example,DC=com

ldap { server = "example.com" identity = "CN=_useraccount,OU=Service Accounts,OU=Special User Accounts,OU=Enterprise,DC=example,DC=com" password = secretpassword basedn = "OU=Enterprise,DC=example,DC=com" filter = (&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=per son)) groupmembership_attribute = "memberOf" ldap_connections_number = 5 timeout = 4 timelimit = 3 net_timeout = 1 tls { start_tls = no } dictionary_mapping = ${confdir}/ldap.attrmap edir_account_policy_check = no groupname_attribute = cn groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectC lass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn})))" } Configuration of different virtual sites For this you'll have 3 general sites, default (used mostly for testing on 127.0.0.1), server_cisco (used to AAA the Cisco users), and server_vpn (used to AAA the VPN users). These live in /etc/raddb/sites-available/ inner-tunnel Add: ntlm_auth to the end of the authenticate{..} section default Add: ntlm_auth to the end of the authenticate{..} section server_cisco (see Appendix B) We're going to duplicate the default config, and modify it for that particular virtual server:

cp /etc/raddb/sites-available/default /etc/raddb/sites-available/server_cisco

Edit server_cisco and change it from server{..} to server server_cisco{..}

Since we're not using any of these methods for the Ciscos, in authenticate{..} disable: chap, mschap, suffix, ntdomain, unix, pap

Add to the end of the authenticate{..} section: ntlm_auth server_vpn (see Appendix A) cp /etc/raddb/sites-available/server_cisco /etc/raddb/sites-available/server_vpn Edit server_vpn and change it from server server_cisco {..} to server server_vpn {..}

To get it to restrict who gets authorized based on the LDAP group, add to authorize {..}: if(Huntgroup-Name == "VPN_Huntgroup") { if(Ldap-Group == "VPN_Users") { ok } else { reject } }

Link sites-enabled to sites-available: chown root:radiusd /etc/raddb/sites-available/server_cisco chown root:radiusd /etc/raddb/sites-available/server_vpn

cd /etc/raddb/sites-enabled ln –s ../sites-available/server_cisco server_cisco ln –s ../sites-available/server_vpn server_vpn /etc/raddb/clients.conf This defines which individual clients connect to which virtual server, letting you differentiate the server config (including the secret) by client

Note: The secret needs to match the secret set on the respective client. Change the secret to an actual secret

clients disambiguate { client localhost { ipaddr = 127.0.0.1 secret = testing123 require_message_authenticator = no } client VPN { ipaddr = 10.4.1.2 secret = secret virtual_server = server_vpn }

client Cisco { ipaddr = 10.100.0.0 netmask = 16 secret = secret virtual_server = server_cisco nastype = cisco }} /etc/raddb/users This file determines which AAA is done against which device and associates the defined huntgroups with the type of AAA

# testuser Huntgroup-Name == Cisco_Huntgroup, # Cleartext-Password:="testpass" # Service-Type:=NAS-Prompt-User,cisco-avpair:="shell:priv-lvl=15" DEFAULT Huntgroup-Name == Cisco_Huntgroup, Auth-Type:=ntlm_auth, Ldap-Group == "Infrastructure" Service-Type:=NAS-Prompt-User,cisco-avpair:="shell:priv-lvl=15" DEFAULT Huntgroup-Name == VPN_Huntgroup, Ldap-Group == "VPN_Users" /etc/raddb/modules/mschap mschap { ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --username=%{mschap:User-Name} --domain=%{mschap:NT-Domain:-example.com} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}" }

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

-- James J J Hooper Network Specialist Information Services University of Bristol +44 (0)117 331 7080 (17080 internal) --

freeradius@corwyn.net wrote:

So we upgraded to samba 3x, but that appears to break freeradius. Hrm.

The upgrade screwed up the file permissions. See the debug output.

We're using freeradius to auth VPN users that are connecting from a sonicwall firewall, using the windows l2tp client.

freeradius2-2.1.8-2.el5

Here's the output from radiusd -xX

The FAQ, "man" page, etc., all say "radiusd -X". The first step to solving a problem is following documentation. ...

Wed Jul 14 10:51:16 2010 : Debug: Exec-Program output: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022) Wed Jul 14 10:51:16 2010 : Debug: Exec-Program-Wait: plaintext: winbind client not authorized to use winbindd_pam_auth_crap. Ensure permissions on /var/lib/samba/winbindd_privileged are set correctly. (0xc0000022)

While that message is buried in lots of debug output, the following few lines help:

Wed Jul 14 10:51:16 2010 : Debug: Exec-Program: returned: 1 Wed Jul 14 10:51:16 2010 : Info: [mschap] External script failed. Wed Jul 14 10:51:16 2010 : Info: [mschap] FAILED: MS-CHAP2-Response is incorrect

If you read the debug output looking *only* for WARNING, ERROR, Failed, or Reject, you will almost always find a message describing the problem. As with this one, the message often says how to fix it, too. And another authentication request yields:

Wed Jul 14 11:18:08 2010 : Info: [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=00be3e466ff82a106ee9e3144e442c6caa1bcb71636031b6 Wed Jul 14 11:18:08 2010 : Debug: Exec-Program output: NT_KEY: 580B07A2801E5E9B5CDD55BC23C38D1F Wed Jul 14 11:18:08 2010 : Debug: Exec-Program-Wait: plaintext: NT_KEY: 580B07A2801E5E9B5CDD55BC23C38D1F Wed Jul 14 11:18:08 2010 : Debug: Exec-Program: returned: 0 ... Sending Access-Accept of id 224 to 10.4.1.2 port 2452 Reply-Message := "Authorized Users Only" MS-CHAP2-Success = 0x01533d45453444463034303730304331303545384245463834323743454544353433303841303643454530

MS-MPPE-Recv-Key = 0x908aea21b6fbe22426feafd473d29657 MS-MPPE-Send-Key = 0xe2cddf5bd3f2aaa193fbce0410b840e8 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006

OK... so what's the problem? MS-CHAP works...

Any ideas?

Read the debug output. Post the debug output for *one* authentication request, not 3-4.

Here are the complete details of our config:

Which the documentation does not ask for. The "radiusd -X" output is all that's necessary. Alan DeKok.

Sending Access-Accept of id 225 to 10.4.1.2 port 2452 Reply-Message := "Authorized Users Only" MS-CHAP2-Success = 0x01533d3333394446363039333941453431374638353333384143443632443 9374137343844413541313936 MS-MPPE-Recv-Key = 0xd81d386eb6bd95dcd85badccd21036b4 MS-MPPE-Send-Key = 0x1415b0a4e0f2d9063a9b0d0e92e2869b MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 Wed Jul 14 11:18:38 2010 : Info: Finished request 8. Wed Jul 14 11:18:38 2010 : Debug: Going to the next request Wed Jul 14 11:18:38 2010 : Debug: Waking up in 4.9 seconds. Wed Jul 14 11:18:43 2010 : Info: Cleaning up request 8 ID 225 with timestamp +665 Wed Jul 14 11:18:43 2010 : Info: Ready to process requests.

Any ideas?

Any ideas about what - the server returned Access-Accept?? Is this not what you wanted? What problem are you trying to solve?