MSCHAP vs MSCHAPv2 for VPN

freeradius at corwyn.net freeradius at corwyn.net
Wed Oct 13 20:58:52 CEST 2010 


Using freeradius 2.1.8, I have a sonicwall firewall that 
authenticates VPN users against the freeradius server. The VPN 
clients are the native MSFT VPN client.

When the client is configured for L2TP, MS-CHAP, the client connects. 
When the client is configured for L2TP MSChapv2, the client fails to 
connect with an error "It was not possible to verify the identity of 
the server"

As I understand it, the difference between mschapv1 and v2 is that 
the server sends back an authentication response. Seems like that 
handshake isn't working out? I know I've missed something somewhere. . .


radiusd -xX:
rad_recv: Access-Request packet from host 192.168.104.1 port 3873, 
id=22, length=124
         User-Name = "rsteeves"
         MS-CHAP-Challenge = 0x68dd158c5082247cfe49fecd9520386a
         MS-CHAP2-Response = 
0x010005edd3135eca19372073504d57f8a4b30000000000000000ab31aff8b876e703bb4141ddc19afff921f6a358cd80b94b
         NAS-IP-Address = x.x.x.x
         NAS-Port = 0
Wed Oct 13 14:50:57 2010 : Info: server server_vpn {
Wed Oct 13 14:50:57 2010 : Info: +- entering group authorize {...}
Wed Oct 13 14:50:57 2010 : Info: ++[preprocess] returns ok
Wed Oct 13 14:50:57 2010 : Info: [mschap] Found MS-CHAP 
attributes.  Setting 'Auth-Type  = mschap'
Wed Oct 13 14:50:57 2010 : Info: ++[mschap] returns ok
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] Entering ldap_groupcmp()
Wed Oct 13 14:50:57 2010 : Info: [files]        expand: 
OU=Enterprise,DC=int,DC=example,DC=com -> 
OU=Enterprise,DC=int,DC=example,DC=com
Wed Oct 13 14:50:57 2010 : Info: [files]        expand: 
%{Stripped-User-Name} ->
Wed Oct 13 14:50:57 2010 : Info: [files]        ... expanding second 
conditional
Wed Oct 13 14:50:57 2010 : Info: [files]        expand: %{User-Name} 
-> rsteeves
Wed Oct 13 14:50:57 2010 : Info: [files]        expand: 
(&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=person)) 
-> (&(sAMAccountname=rsteeves)(objectClass=person))
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
OU=Enterprise,DC=int,DC=example,DC=com, with filter 
(&(sAMAccountname=rsteeves)(objectClass=person))
Wed Oct 13 14:50:57 2010 : Error:   [ldap] ldap_search() failed: LDAP 
connection lost.
Wed Oct 13 14:50:57 2010 : Info:   [ldap] Attempting reconnect
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] attempting LDAP reconnection
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] closing existing LDAP connection
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] (re)connect to 
dc.int.example.com:389, authentication 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] bind as 
CN=_UserID,OU=Service Accounts,OU=Special User 
Accounts,OU=Enterprise,DC=int,DC=example,DC=com/wvyjCHCd2LJHcNrmpr0I 
to dc.int.example.com:389
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] waiting for bind result ...
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] Bind was successful
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
OU=Enterprise,DC=int,DC=example,DC=com, with filter 
(&(sAMAccountname=rsteeves)(objectClass=person))
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Oct 13 14:50:57 2010 : Info: [files]        expand: 
(|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> (|(&(objectClass=GroupOfNames)(member=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom)))
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
OU=Enterprise,DC=int,DC=example,DC=com, with filter 
(&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))))
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] object not found
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
CN=Rick 
Steeves,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with 
filter (objectclass=*)
Wed Oct 13 14:50:57 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 Oct 13 14:50:57 2010 : Debug: rlm_ldap::ldap_groupcmp: User found 
in group VPN_Users
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Oct 13 14:50:57 2010 : Info: [files] users: Matched entry DEFAULT 
at line 11
Wed Oct 13 14:50:57 2010 : Info: ++[files] returns ok
Wed Oct 13 14:50:57 2010 : Info: [ldap] performing user authorization 
for rsteeves
Wed Oct 13 14:50:57 2010 : Info: [ldap]         expand: 
%{Stripped-User-Name} ->
Wed Oct 13 14:50:57 2010 : Info: [ldap]         ... expanding second 
conditional
Wed Oct 13 14:50:57 2010 : Info: [ldap]         expand: %{User-Name} 
-> rsteeves
Wed Oct 13 14:50:57 2010 : Info: [ldap]         expand: 
(&(sAMAccountname=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=person)) 
-> (&(sAMAccountname=rsteeves)(objectClass=person))
Wed Oct 13 14:50:57 2010 : Info: [ldap]         expand: 
OU=Enterprise,DC=int,DC=example,DC=com -> 
OU=Enterprise,DC=int,DC=example,DC=com
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
OU=Enterprise,DC=int,DC=example,DC=com, with filter 
(&(sAMAccountname=rsteeves)(objectClass=person))
Wed Oct 13 14:50:57 2010 : Info: [ldap] looking for check items in directory...
Wed Oct 13 14:50:57 2010 : Info: [ldap] looking for reply items in directory...
Wed Oct 13 14:50:57 2010 : Debug: WARNING: No "known good" password 
was found in LDAP.  Are you sure that the user is configured correctly?
Wed Oct 13 14:50:57 2010 : Info: [ldap] user rsteeves authorized to 
use remote access
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Oct 13 14:50:57 2010 : Info: ++[ldap] returns ok
Wed Oct 13 14:50:57 2010 : Info: ++? if (Huntgroup-Name == "VPN_Huntgroup")
Wed Oct 13 14:50:57 2010 : Info: ? Evaluating (Huntgroup-Name == 
"VPN_Huntgroup") -> TRUE
Wed Oct 13 14:50:57 2010 : Info: ++? if (Huntgroup-Name == 
"VPN_Huntgroup") -> TRUE
Wed Oct 13 14:50:57 2010 : Info: ++- entering if (Huntgroup-Name == 
"VPN_Huntgroup") {...}
Wed Oct 13 14:50:57 2010 : Info: +++? if (Ldap-Group == "VPN_Users")
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] Entering ldap_groupcmp()
Wed Oct 13 14:50:57 2010 : Info:        expand: 
OU=Enterprise,DC=int,DC=example,DC=com -> 
OU=Enterprise,DC=int,DC=example,DC=com
Wed Oct 13 14:50:57 2010 : Info:        expand: 
(|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) 
-> (|(&(objectClass=GroupOfNames)(member=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom)))
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
OU=Enterprise,DC=int,DC=example,DC=com, with filter 
(&(cn=VPN_Users)(|(&(objectClass=GroupOfNames)(member=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))(&(objectClass=GroupOfUniqueNames)(uniquemember=CN\3dRick 
Steeves\2cOU\3dIS\2cOU\3dUsers\2cOU\3dEnterprise\2cDC\3dint\2cDC\3dexample\2cDC\3dcom))))
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] object not found
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] performing search in 
CN=Rick 
Steeves,OU=IS,OU=Users,OU=Enterprise,DC=int,DC=example,DC=com, with 
filter (objectclass=*)
Wed Oct 13 14:50:57 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 Oct 13 14:50:57 2010 : Debug: rlm_ldap::ldap_groupcmp: User found 
in group VPN_Users
Wed Oct 13 14:50:57 2010 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Oct 13 14:50:57 2010 : Info: ? Evaluating (Ldap-Group == 
"VPN_Users") -> TRUE
Wed Oct 13 14:50:57 2010 : Info: +++? if (Ldap-Group == "VPN_Users") -> TRUE
Wed Oct 13 14:50:57 2010 : Info: +++- entering if (Ldap-Group == 
"VPN_Users") {...}
Wed Oct 13 14:50:57 2010 : Info: ++++[ok] returns ok
Wed Oct 13 14:50:57 2010 : Info: +++- if (Ldap-Group == "VPN_Users") returns ok
Wed Oct 13 14:50:57 2010 : Info: +++ ... skipping else for request 2: 
Preceding "if" was taken
Wed Oct 13 14:50:57 2010 : Info: ++- if (Huntgroup-Name == 
"VPN_Huntgroup") returns ok
Wed Oct 13 14:50:57 2010 : Info: Found Auth-Type = MSCHAP
Wed Oct 13 14:50:57 2010 : Info: +- entering group MS-CHAP {...}
Wed Oct 13 14:50:57 2010 : Info: [mschap] Told to do MS-CHAPv2 for 
rsteeves with NT-Password
Wed Oct 13 14:50:57 2010 : Info: [mschap]       expand: 
--username=%{mschap:User-Name} -> --username=rsteeves
Wed Oct 13 14:50:57 2010 : Info: [mschap] No NT-Domain was found in 
the User-Name.
Wed Oct 13 14:50:57 2010 : Info: [mschap]       expand: 
--domain=%{mschap:NT-Domain:-int.example.com} -> --domain=
Wed Oct 13 14:50:57 2010 : Info: [mschap]  mschap2: 68
Wed Oct 13 14:50:57 2010 : Info: [mschap]       expand: 
--challenge=%{mschap:Challenge:-00} -> --challenge=39232bda5539ec44
Wed Oct 13 14:50:57 2010 : Info: [mschap]       expand: 
--nt-response=%{mschap:NT-Response:-00} -> 
--nt-response=ab31aff8b876e703bb4141ddc19afff921f6a358cd80b94b
Wed Oct 13 14:50:57 2010 : Debug: Exec-Program output: NT_KEY: 
DDE9BB9EA12ED17BE5F358CB53EE6A8F
Wed Oct 13 14:50:57 2010 : Debug: Exec-Program-Wait: plaintext: 
NT_KEY: DDE9BB9EA12ED17BE5F358CB53EE6A8F
Wed Oct 13 14:50:57 2010 : Debug: Exec-Program: returned: 0
Wed Oct 13 14:50:57 2010 : Info: [mschap] adding MS-CHAPv2 MPPE keys
Wed Oct 13 14:50:57 2010 : Info: ++[mschap] returns ok
Wed Oct 13 14:50:57 2010 : Auth: Login OK: [rsteeves] (from client 
VPN_Fay port 0)
Wed Oct 13 14:50:57 2010 : Info: +- entering group post-auth {...}
Wed Oct 13 14:50:57 2010 : Info: ++[exec] returns noop
Wed Oct 13 14:50:57 2010 : Info: } # server server_vpn
Sending Access-Accept of id 22 to 192.168.104.1 port 3873
         Reply-Message := "Authorized Users Only"
         MS-CHAP2-Success = 
0x01533d39353639333834444241444635364135383445383643433543433231384234303431383736343144
         MS-MPPE-Recv-Key = 0x18fe4b2752e2b4ff2cc2f0d951f26c42
         MS-MPPE-Send-Key = 0xe25177ef572676aa3f9883443c93fbc1
         MS-MPPE-Encryption-Policy = 0x00000001
         MS-MPPE-Encryption-Types = 0x00000006
Wed Oct 13 14:50:57 2010 : Info: Finished request 2.
Wed Oct 13 14:50:57 2010 : Debug: Going to the next request
Wed Oct 13 14:50:57 2010 : Debug: Waking up in 4.9 seconds.
Wed Oct 13 14:51:02 2010 : Info: Cleaning up request 2 ID 22 with 
timestamp +991
Wed Oct 13 14:51:02 2010 : Info: Ready to process requests.



Rick Steeves
http://www.sinister.net

In reality nothing is more damaging to the adventurous spirit within 
a man than a secure future -  Alexander Supertramp

More information about the Freeradius-Users mailing list