search

nm-l2tp / NetworkManager-l2tp

L2TP and L2TP/IPsec support for NetworkManager
GNU General Public License v2.0
486 stars 83 forks source link

MS-CHAPv2 Success packet is badly formed #144

Closed smulikHakipod closed 3 years ago

smulikHakipod commented 4 years ago

Its working on Mac/Windows. Windows Server VPN. Any idea why? Thanks

Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: Plugin pppol2tp.so loaded.
Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: Plugin /usr/lib/pppd/2.4.7/nm-l2tp-pppd-plugin.so loaded.
Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: pppd 2.4.7 started by root, uid 0
Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: Using interface ppp0
Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: Connect: ppp0 <-->
Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: Overriding mtu 1500 to 1400
Jun 13 09:45:23 yaron-MS-7B09 pppd[9559]: Overriding mru 1500 to mtu value 1400
Jun 13 09:45:23 yaron-MS-7B09 NetworkManager[5769]: <info>  [1592030723.7433] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/8)
Jun 13 09:45:30 yaron-MS-7B09 pppd[9559]: MS-CHAPv2 Success packet is badly formed.
Jun 13 09:45:30 yaron-MS-7B09 pppd[9559]: CHAP authentication failed
Jun 13 09:45:30 yaron-MS-7B09 pppd[9559]: Overriding mtu 1500 to 1400
Jun 13 09:45:30 yaron-MS-7B09 pppd[9559]: Overriding mru 1500 to mtu value 1400
Jun 13 09:45:30 yaron-MS-7B09 pppd[9559]: Connection terminated.
Jun 13 09:45:30 yaron-MS-7B09 charon[9523]: 14[KNL] interface ppp0 deleted
Jun 13 09:45:30 yaron-MS-7B09 NetworkManager[9558]: xl2tpd[9558]: death_handler: Fatal signal 15 received
dkosovic commented 4 years ago

I've never seen the MS-CHAPv2 Success packet is badly formed error before.

Most L2TP PPP issues are either due to the system xl2tpd still running or the blacklisting of the L2TP kernel modules as mentioned in the README.md file.

Looking at pppd's chap_ms.c source code :

The MS-CHAPv2 Success packet is badly formed error message only happens if the packet sent from the server doesn't begin with M= or S=.

As mentioned in the README.md file, you can increase pppd debugging by starting nm-l2tp-service on the command-line with the --debug switch, you will see need to use journalctl to see the debug output. Hopefully the increased debugging will provide some useful hints about what is going wrong.

Although unlikely in this case, it could be an issue with the pppol2tp.so kernel module, you could try using a different kernel to see if it makes a difference.

Doing a Google search for MS-CHAPv2 Success packet is badly formed and limiting the search to the past 5 years only comes up with the following page:

which in turn points to the following page from 2010:

No sure if you are also using a Draytek VPN server, the issues seems to be the packet it returns begins with \001S=... instead of S=, on the above ubuntuforums.org thread, some people modified pppd to swallow the extra bytes before S= to make things work.

smulikHakipod commented 4 years ago

Thanks, I will try with older kernel version and the debug flag. I am running on Ubuntu 20.04 with kernel:

Linux yaron-MS-7B09 5.4.0-37-generic #41-Ubuntu SMP Wed Jun 3 18:57:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

I also tried the google search, which led to to nothing basically. I am 99% percent sure we are using Windows Server VPN.

dkosovic commented 4 years ago

In the PPP options dialog box, could you try disabling MS-CHAPv2 and only leave MS-CHAP enabled and see if that makes a difference?

smulikHakipod commented 4 years ago

Seems like the connection got closed

Jun 13 15:56:45 yaron-MS-7B09 pppd[98641]: Using interface ppp0 Jun 13 15:56:45 yaron-MS-7B09 NetworkManager[1163]: [1592053005.6350] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/106) Jun 13 15:56:45 yaron-MS-7B09 pppd[98641]: Connect: ppp0 <--> Jun 13 15:56:45 yaron-MS-7B09 pppd[98641]: Overriding mtu 1500 to 1400 Jun 13 15:56:45 yaron-MS-7B09 pppd[98641]: Overriding mru 1500 to mtu value 1400 Jun 13 15:56:45 yaron-MS-7B09 NetworkManager[98640]: xl2tpd[98640]: control_finish: Connection closed to , serial 1 () Jun 13 15:56:45 yaron-MS-7B09 NetworkManager[98640]: xl2tpd[98640]: Terminating pppd: sending TERM signal to pid 98641 Jun 13 15:56:45 yaron-MS-7B09 pppd[98641]: Terminating on signal 15 Jun 13 15:56:51 yaron-MS-7B09 pppd[98641]: Connection terminated.

Setting it back to MSCHAPv2 returns the same error, meaning I probably must be in MSCHAPv2. Our sysadmin tell us that as well, and he instructs enabling MSCHAPv2 on windows for example. I will try the debug flag later on. Thanks for the help

dankor commented 3 years ago

I'm facing the same issue (MS-CHAPv2 Success packet is badly formed.): My --debug output after phone approve:

xl2tpd[349861]: "/var/run/nm-l2tp-bad3e8e7-633d-4631-8d09-8d6591e31ee6/ppp-options" 
nm-l2tp[349794] <info>  Terminated xl2tpd daemon with PID 349861.
xl2tpd[349861]: death_handler: Fatal signal 15 received
xl2tpd[349861]: Terminating pppd: sending TERM signal to pid 349862
xl2tpd[349861]: Connection 451 closed to 111.11.111.184, port 1701 (Server closing)
Stopping strongSwan IPsec...
** Message: 11:56:09.892: ipsec shut down
nm-l2tp[349794] <warn>  xl2tpd exited with error code 1
Stopping strongSwan IPsec failed: starter is not running
** Message: 11:56:09.909: ipsec shut down
dkosovic commented 3 years ago

You could try modifying the chapms2_check_success() function in pppd :

by replacing the following code :

if ((len < MS_AUTH_RESPONSE_LENGTH + 2) ||
    strncmp((char *)msg, "S=", 2) != 0) {
    /* Packet does not start with "S=" */
    error("MS-CHAPv2 Success packet is badly formed.");
    return 0;
}
msg += 2;
len -= 2;

with something like the following which eats the extra character:

if ((len >= 3) && !strncmp((char *)msg + 1, "S=", 2)) {
    msg += 3;
    len -= 3;
} else if ((len >= 2) && !strncmp((char *)msg, "S=", 2)) {
    msg += 2;
    len -= 2;
} else if (len) {
    /* Packet has extra text which does not begin "S=" */
    error("MS-CHAPv2 Success packet is badly formed.");
    return 0;
}

and then rebuild pppd.

dankor commented 3 years ago

Same:

LANG=C journalctl -u NetworkManager -r
-- Logs begin at Mon 2020-07-13 23:17:03 EEST, end at Wed 2020-08-05 14:11:02 EEST. --
Aug 05 14:09:45 interhost NetworkManager[368921]: <info>  [1596625785.5542] vpn-connection[0x564b88eb2590,bad3e8e7-633d-4631-8d09-8d6591e31ee6,"VPN1",0]: VPN service disappeared
Aug 05 14:09:45 interhost NetworkManager[368921]: <info>  [1596625785.5334] vpn-connection[0x564b88eb2590,bad3e8e7-633d-4631-8d09-8d6591e31ee6,"VPN1",0]: VPN plugin: state changed: stopped (6)
Aug 05 14:09:45 interhost nm-l2tp-service[369173]: ipsec shut down
Aug 05 14:09:45 interhost ipsec_starter[369195]: ipsec starter stopped
Aug 05 14:09:45 interhost ipsec_starter[369195]: charon stopped after 200 ms
Aug 05 14:09:45 interhost ipsec_starter[369195]: 
Aug 05 14:09:45 interhost ipsec_starter[369195]: child 369196 (charon) has quit (exit code 0)
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] uninstalling bypass policy for 192.168.0.0/24
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] uninstalling bypass policy for ::1/128
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] uninstalling bypass policy for fe80::/64
Aug 05 14:09:45 interhost charon[369196]: 00[NET] sending packet: from 192.168.0.104[4500] to 111.11.111.184[4500] (92 bytes)
Aug 05 14:09:45 interhost charon[369196]: 00[ENC] generating INFORMATIONAL_V1 request 1802311603 [ HASH D ]
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] sending DELETE for IKE_SA bad3e8e7-633d-4631-8d09-8d6591e31ee6[1]
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] deleting IKE_SA bad3e8e7-633d-4631-8d09-8d6591e31ee6[1] between 192.168.0.104[192.168.0.104]...111.11.111.184[192.168.104.184]
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] deleting IKE_SA bad3e8e7-633d-4631-8d09-8d6591e31ee6[1] between 192.168.0.104[192.168.0.104]...111.11.111.184[192.168.104.184]
Aug 05 14:09:45 interhost charon[369196]: 00[NET] sending packet: from 192.168.0.104[4500] to 111.11.111.184[4500] (76 bytes)
Aug 05 14:09:45 interhost charon[369196]: 00[ENC] generating INFORMATIONAL_V1 request 1733723799 [ HASH D ]
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] sending DELETE for ESP CHILD_SA with SPI cd24ee76
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] closing CHILD_SA bad3e8e7-633d-4631-8d09-8d6591e31ee6{1} with SPIs cd24ee76_i (750 bytes) 44d6deac_o (628 bytes) and TS 192.168.0.104/32[udp/l2f] === 161.47.1>
Aug 05 14:09:45 interhost charon[369196]: 00[IKE] closing CHILD_SA bad3e8e7-633d-4631-8d09-8d6591e31ee6{1} with SPIs cd24ee76_i (750 bytes) 44d6deac_o (628 bytes) and TS 192.168.0.104/32[udp/l2f] === 161.47.1>
Aug 05 14:09:45 interhost charon[369196]: 00[DMN] signal of type SIGINT received. Shutting down
Aug 05 14:09:45 interhost NetworkManager[369245]: Stopping strongSwan IPsec...
Aug 05 14:09:45 interhost pppd[369232]: Exit.
Aug 05 14:09:45 interhost NetworkManager[368921]: <info>  [1596625785.3495] vpn-connection[0x564b88eb2590,bad3e8e7-633d-4631-8d09-8d6591e31ee6,"VPN1",0]: VPN plugin: state changed: stopping (5)
Aug 05 14:09:45 interhost NetworkManager[368921]: <warn>  [1596625785.3470] vpn-connection[0x564b88eb2590,bad3e8e7-633d-4631-8d09-8d6591e31ee6,"VPN1",0]: VPN plugin: failed: connect-failed (1)
Aug 05 14:09:45 interhost NetworkManager[369231]: xl2tpd[369231]: Connection 463 closed to 111.11.111.184, port 1701 (Server closing)
Aug 05 14:09:45 interhost NetworkManager[369231]: xl2tpd[369231]: Terminating pppd: sending TERM signal to pid 369232
Aug 05 14:09:45 interhost NetworkManager[369231]: xl2tpd[369231]: death_handler: Fatal signal 15 received
Aug 05 14:09:45 interhost charon[369196]: 10[KNL] interface ppp0 deleted
Aug 05 14:09:45 interhost pppd[369232]: Connection terminated.
Aug 05 14:09:45 interhost pppd[369232]: Overriding mru 1500 to mtu value 1400
Aug 05 14:09:45 interhost pppd[369232]: Overriding mtu 1500 to 1400
Aug 05 14:09:45 interhost pppd[369232]: CHAP authentication failed
Aug 05 14:09:45 interhost pppd[369232]: MS-CHAPv2 Success packet is badly formed.
Aug 05 14:09:38 interhost NetworkManager[368921]: <info>  [1596625778.5974] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/8)
Aug 05 14:09:38 interhost pppd[369232]: Overriding mru 1500 to mtu value 1400
Aug 05 14:09:38 interhost pppd[369232]: Overriding mtu 1500 to 1400
Aug 05 14:09:38 interhost pppd[369232]: Connect: ppp0 <-->
Aug 05 14:09:38 interhost pppd[369232]: Using interface ppp0
Aug 05 14:09:38 interhost pppd[369232]: pppd 2.4.7 started by root, uid 0
Aug 05 14:09:38 interhost pppd[369232]: Plugin /usr/lib/pppd/2.4.7/nm-l2tp-pppd-plugin.so loaded.
Aug 05 14:09:38 interhost pppd[369232]: Plugin pppol2tp.so loaded.
dankor commented 3 years ago

The error is from https://github.com/paulusmack/ppp/blob/master/pppd/chap_ms.c#L428 I inserted another error massage to verify it.

dkosovic commented 3 years ago

Inserting something like the following before that error() line might work to see what was received, assuming there are no non-printable bytes:

dbglog("****  Unexpected packet data = \"%s\"", (char *)msg);
dankor commented 3 years ago

error("**** Unexpected packet data = \"%s\"", (char *)msg); returns:

Aug 05 15:26:17 interhost pppd[392770]: CHAP authentication failed
Aug 05 15:26:17 interhost pppd[392770]: ****  Unexpected packet data = "M=Success. Logging you in..."
dankor commented 3 years ago

Replacing 0 with 1 in does the trick here: https://github.com/paulusmack/ppp/blob/master/pppd/chap_ms.c#L429 Should I report the issue to ppp?

dkosovic commented 3 years ago

I think the following code:

    if ((len >= 3) && !strncmp((char *)msg, " M=", 3)) {
        msg += 3; /* Eat the delimiter */
    } else if (len) {
        /* Packet has extra text which does not begin " M=" */
        error("MS-CHAPv2 Success packet is badly formed.");
        return 0;
    }

should be :

    if ((len >= 3) && !strncmp((char *)msg, " M=", 3)) {
        msg += 3; /* Eat the delimiter */
    } else if ((len >= 2) && !strncmp((char *)msg, "M=", 2)) {
        msg += 2; /* Eat the delimiter */
    } else if (len) {
        /* Packet has extra text which does not begin " M=" */
        error("MS-CHAPv2 Success packet is badly formed.");
        return 0;
    }

As the pppd on the VPN server isn't prepending a space before M= as expected. It should still return 0 for other cases where it is an error.

dkosovic commented 3 years ago

Just curious, do you know what the VPN server is? e.g. vendor, manufacturer or whatever.

The PPP implementation on the server side might not be pppd, but the bug is definitely on the server side as it is generating the success packet, unless the PPP standard(s) say it is okay to not have a space before the M=. Extract from RFC 2759 (https://tools.ietf.org/html/rfc2759) :

The format of the message field is illustrated below.

"S=\<auth_string> M=\<message>"

Seems to imply there is supposed to be a space before M=.

But glad to see it is working with a workaround on the client side.

dankor commented 3 years ago

The vendor is Microsoft, they are known for messing up with standarts. Probably, it may be an incorrect server configuration, but MacOS works just fine via L2TP over IPSec. I'll ask my server team regarding this extra space issue. Thanks!

dkosovic commented 3 years ago

Looks like macOS does handle the missing space before M=, extract from :

    //we'll allow the missing-space case from the server, even though
    //it's non-conforming to spec!
    dbglog("Rcvd non-conforming MSCHAPv2 Success packet, len=%d", len);
    if(len >= 2 && !strncmp((char*)msg, "M=", 2))
        msg += 2;
    else
    {
        error("MS-CHAPv2 Success packet is badly formed.");
        return 0;
    }
dankor commented 3 years ago

Wow, it makes sense then. Thank you for the investigation! Can we patch ppp as well in order to make a life for end-user easier?

dkosovic commented 3 years ago

I noticed you have submitted a PR to the upstream ppp which handles the missing-space , but not the case when the space isn't missing.

I think the code should be like the following which handles both the missing and not missing space before M=, Compared to my previous code replacement example, I just added an extra dbglog() line that is the same as the Apple debug output (except it doesn't show the remaining length, which isn't of much use) :

    if ((len >= 3) && !strncmp((char *)msg, " M=", 3)) {
        msg += 3; /* Eat the delimiter */
    } else if ((len >= 2) && !strncmp((char *)msg, "M=", 2)) {
        msg += 2; /* Eat the delimiter */
        dbglog("Rcvd non-conforming MSCHAPv2 Success packet");
    } else if (len) {
        /* Packet has extra text which does not begin " M=" */
        error("MS-CHAPv2 Success packet is badly formed.");
        return 0;
    }

Linux distros often ship with ppp packages that have a considerable number of patches as there is a very long gap between upstream ppp releases. e.g.:

Fedora ppp patches: https://src.fedoraproject.org/rpms/ppp/tree/master

Debian/ubuntu ppp patches : https://salsa.debian.org/debian/ppp/-/tree/master/debian/patches

so it might be worthwhile submitting the patch to your Linux distro.

I use a Microsoft Server 2019 VPN server as one of my L2TP/IPsec test servers and have never encountered this issue. I vaguely remember a Windows update that broke RAS PPP on Microsoft Servers but can't remember which version and no idea if it is related to this issue.

dankor commented 3 years ago

No rush, I'm not a big fan of downstream patches. Let ppp maintainers decide.

dankor commented 3 years ago

https://github.com/paulusmack/ppp/pull/156 seems to be fixed upstream. Thanks!

dkosovic commented 3 years ago

That's awesome news that it was fixed upstream! It looks identical to my first attempt to fix the missing space before the M=. I might post the corresponding patch to a few linux distros: