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