Freeradius2 and Samba3x

14 Jul 2010

      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 = 
0x0100f3dd5207d539bd0d7e1f7be50178d3820000000000000000a3492c6411f5548251a05606aa028964d34b69c58e61c7d5
         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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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 = 
0x01000bd21f7a41e97a616ca8dd0634f4e5230000000000000000d4c66c9dd3cabae77edfe564c745de287968a0441d0df3a5
         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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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 = 
0x01000c60a44ccac150a8d8961f218cfd07b5000000000000000000be3e466ff82a106ee9e3144e442c6caa1bcb71636031b6
         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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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 = 
0x01533d45453444463034303730304331303545384245463834323743454544353433303841303643454530
         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 = 
0x0100af58b67bf00cc423c52b0a65b1f491000000000000000000d59dccc1f4e99c19be1ded3a3a771e49bfbb14ec62424311
         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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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=person)) 
-> (&(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}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> 
(|(&(objectClass=GroupOfNames)(member=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dUser 
Account\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\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 = 
0x01533d33333944463630393339414534313746383533333841434436324439374137343844413541313936
         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=person)) 
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}))(&(objectClass=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}"
}

Freeradius2 and Samba3x

freeradius＠corwyn.net