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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
