Softethervpn: L2TP VPN do not connect by iphone(ios13.4.1)

Created on 22 Apr 2020  路  19Comments  路  Source: SoftEtherVPN/SoftEtherVPN

SoftEtherVPN Ver: 5.01.9673 has a problem that it cannot connect to L2TP of iPhone.
If you downgrade to Ver: 5.01.9672, you can connect.

Prerequisites

  • [x] Can you reproduce?
  • [x ] Are you running the latest version of SoftEtherVPN?

SoftEther version: 5.01.9673
Component: [Server]
Operating system: [Ubuntu 18.04]
Architecture: [64 bit]

Description

L2TP VPN do not connect by iphone(ios13.4.1)

Expected behavior:
Connected L2TP VPN by iphone.

Actual behavior:
VPN connection fails.

picture akira345

Most helpful comment

@akira345 Should be fixed by #1104, thank you for reporting!

picture metalefty on 26 Apr 2020
🎉2

All 19 comments

Only L2TP is malfunctioning, and OpenVPN connection is possible.

akira345 picture akira345 on 22 Apr 2020

Confirmed. The same for me. Perhaps because of #1072.

Here's the log but not very helpful for me.

2020-04-22 21:45:12.456 IPsec Client 4 (aaa.bbb.ccc.ddd:61324 -> 0.0.0.0:500): A new IPsec client is created.
2020-04-22 21:45:12.456 IPsec IKE Session (IKE SA) 4 (Client: 4) (aaa.bbb.ccc.ddd:61324 -> 0.0.0.0:500): A new IKE SA (Main Mode) is created. Initiator Cookie: 0xE2F238E4405049C9, Responder Cookie: 0x44FC313A5CBA9D6A, DH Group: MODP 2048 (Group 14), Hash Algorithm: SHA-2-256, Cipher Algorithm: AES-CBC, Cipher Key Size: 256 bits, Lifetime: 4294967295 Kbytes or 3600 seconds
2020-04-22 21:45:12.843 IPsec Client 4 (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): The port number information of this client is updated.
2020-04-22 21:45:12.843 IPsec Client 4 (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500):
2020-04-22 21:45:12.843 IPsec IKE Session (IKE SA) 4 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IKE SA is established between the server and the client.
2020-04-22 21:45:13.547 IPsec IKE Session (IKE SA) 4 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): The client initiates a QuickMode negotiation.
2020-04-22 21:45:13.547 IPsec ESP Session (IPsec SA) 7 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): A new IPsec SA (Direction: Client -> Server) is created. SPI: 0x4F9FA442, DH Group: (null), Hash Algorithm: SHA-1, Cipher Algorithm: AES-CBC, Cipher Key Size: 256 bits, Lifetime: 4294967295 Kbytes or 3600 seconds
2020-04-22 21:45:13.547 IPsec ESP Session (IPsec SA) 7 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): A new IPsec SA (Direction: Server -> Client) is created. SPI: 0x49E7CE9, DH Group: (null), Hash Algorithm: SHA-1, Cipher Algorithm: AES-CBC, Cipher Key Size: 256 bits, Lifetime: 4294967295 Kbytes or 3600 seconds
2020-04-22 21:45:13.646 IPsec Client 4 (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): The L2TP Server Module is started.
2020-04-22 21:45:14.845 IPsec IKE Session (IKE SA) 4 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): The server initiates a QuickMode negotiation.
2020-04-22 21:45:14.845 IPsec ESP Session (IPsec SA) 8 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): A new IPsec SA (Direction: Client -> Server) is created. SPI: 0x3108BBE9, DH Group: (null), Hash Algorithm: SHA-1, Cipher Algorithm: AES-CBC, Cipher Key Size: 256 bits, Lifetime: 4294967295 Kbytes or 3600 seconds
2020-04-22 21:45:14.845 IPsec ESP Session (IPsec SA) 8 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): A new IPsec SA (Direction: Server -> Client) is created. SPI: 0x0, DH Group: (null), Hash Algorithm: SHA-1, Cipher Algorithm: AES-CBC, Cipher Key Size: 256 bits, Lifetime: 4294967295 Kbytes or 3600 seconds
2020-04-22 21:45:14.867 L2TP PPP Session [aaa.bbb.ccc.ddd:1701]: A new PPP session (Upper protocol: L2TP) is started. IP Address of PPP Client: aaa.bbb.ccc.ddd (Hostname: "metafone7"), Port Number of PPP Client: 1701, IP Address of PPP Server: 0.0.0.0, Port Number of PPP Server: 1701, Client Software Name: "L2TP VPN Client", IPv4 TCP MSS (Max Segment Size): 1314 bytes
2020-04-22 21:45:14.942 IPsec ESP Session (IPsec SA) 8 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): The SPI which has been pending is now set. New SPI: 0xC7C6635
2020-04-22 21:45:14.942 IPsec ESP Session (IPsec SA) 8 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec SA is established between the server and the client.
2020-04-22 21:45:15.703 IPsec ESP Session (IPsec SA) 7 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec SA is established between the server and the client.
2020-04-22 21:45:45.033 IPsec ESP Session (IPsec SA) 8 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec SA is deleted.
2020-04-22 21:45:45.033 IPsec ESP Session (IPsec SA) 7 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec SA is deleted.
2020-04-22 21:45:45.033 IPsec IKE Session (IKE SA) 4 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IKE SA is deleted.
2020-04-22 21:45:45.033 IPsec ESP Session (IPsec SA) 8 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec SA is deleted.
2020-04-22 21:45:45.033 IPsec ESP Session (IPsec SA) 7 (Client: 4) (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec SA is deleted.
2020-04-22 21:45:45.119 L2TP PPP Session [aaa.bbb.ccc.ddd:1701]: The PPP session is disconnected because the upper-layer protocol "L2TP" has been disconnected.
2020-04-22 21:45:45.119 L2TP PPP Session [aaa.bbb.ccc.ddd:1701]: The PPP session is disconnected.
2020-04-22 21:45:55.463 IPsec Client 4 (aaa.bbb.ccc.ddd:61017 -> 0.0.0.0:4500): This IPsec Client is deleted.
metalefty picture metalefty on 22 Apr 2020

@metalefty , can you please bisect that PR and find particular breaking change ?

chipitsine picture chipitsine on 22 Apr 2020

Also macOS Mojave 10.14.6 fails to connect. Fortunately, macOS L2TP client outputs more helpful logs. Here it is.

Wed Apr 22 21:59:54 2020 : publish_entry SCDSet() failed: Success!
Wed Apr 22 21:59:54 2020 : publish_entry SCDSet() failed: Success!
Wed Apr 22 21:59:54 2020 : l2tp_get_router_address
Wed Apr 22 21:59:54 2020 : l2tp_get_router_address 192.168.24.1 from dict 1
Wed Apr 22 21:59:54 2020 : L2TP connecting to server 'softether-server.vmeta.jp' (aaa.bbb.ccc.ddd)...
Wed Apr 22 21:59:54 2020 : IPSec connection started
Wed Apr 22 21:59:54 2020 : IPSec phase 1 client started
Wed Apr 22 21:59:54 2020 : IPSec phase 1 server replied
Wed Apr 22 21:59:55 2020 : IPSec phase 2 started
Wed Apr 22 21:59:58 2020 : IPSec phase 2 established
Wed Apr 22 21:59:58 2020 : IPSec connection established
Wed Apr 22 21:59:58 2020 : L2TP sent SCCRQ
Wed Apr 22 21:59:59 2020 : L2TP received SCCRP
Wed Apr 22 21:59:59 2020 : L2TP sent SCCCN
Wed Apr 22 21:59:59 2020 : L2TP sent ICRQ
Wed Apr 22 21:59:59 2020 : L2TP received ICRP
Wed Apr 22 21:59:59 2020 : L2TP sent ICCN
Wed Apr 22 21:59:59 2020 : L2TP connection established.
Wed Apr 22 21:59:59 2020 : L2TP set port-mapping for en0, interface: 5, protocol: 0, privatePort: 0
Wed Apr 22 21:59:59 2020 : using link 0
Wed Apr 22 21:59:59 2020 : Using interface ppp0
Wed Apr 22 21:59:59 2020 : Connect: ppp0 <--> socket[34:18]
Wed Apr 22 21:59:59 2020 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xf4bdc91> <pcomp> <accomp>]
Wed Apr 22 21:59:59 2020 : L2TP port-mapping for en0, interfaceIndex: 0, Protocol: None, Private Port: 0, Public Address: 838104a4, Public Port: 0, TTL: 0.
Wed Apr 22 21:59:59 2020 : L2TP port-mapping for en0 inconsistent. is Connected: 1, Previous interface: 5, Current interface 0
Wed Apr 22 21:59:59 2020 : L2TP port-mapping for en0 initialized. is Connected: 1, Previous publicAddress: (0), Current publicAddress 838104a4
Wed Apr 22 21:59:59 2020 : L2TP port-mapping for en0 fully initialized. Flagging up
Wed Apr 22 22:00:02 2020 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xf4bdc91> <pcomp> <accomp>]
Wed Apr 22 22:00:02 2020 : rcvd [LCP ConfRej id=0x1 <asyncmap 0x0> <magic 0xf4bdc91> <pcomp> <accomp>]
Wed Apr 22 22:00:02 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:02 2020 : rcvd [LCP ConfReq id=0x0 <auth chap MS-v2>]
Wed Apr 22 22:00:02 2020 : lcp_reqci: returning CONFACK.
Wed Apr 22 22:00:02 2020 : sent [LCP ConfAck id=0x0 <auth chap MS-v2>]
Wed Apr 22 22:00:02 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 00 00 00 00]
Wed Apr 22 22:00:02 2020 : rcvd [CHAP Challenge id=0x1 <135c36f03379f459fe1cd8588ae8a881>, name = "glory"]
Wed Apr 22 22:00:05 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:07 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 72 79 00 00]
Wed Apr 22 22:00:07 2020 : rcvd [CHAP Challenge id=0x1 <135c36f03379f459fe1cd8588ae8a881>, name = "glory"]
Wed Apr 22 22:00:08 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:11 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:12 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 72 79 00 00]
Wed Apr 22 22:00:13 2020 : rcvd [CHAP Challenge id=0x1 <135c36f03379f459fe1cd8588ae8a881>, name = "glory"]
Wed Apr 22 22:00:14 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:17 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 72 79 00 00]
Wed Apr 22 22:00:18 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:18 2020 : rcvd [CHAP Challenge id=0x1 <135c36f03379f459fe1cd8588ae8a881>, name = "glory"]
Wed Apr 22 22:00:21 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:22 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 72 79 00 00]
Wed Apr 22 22:00:23 2020 : rcvd [CHAP Challenge id=0x1 <135c36f03379f459fe1cd8588ae8a881>, name = "glory"]
Wed Apr 22 22:00:24 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:26 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 72 79 00 00]
Wed Apr 22 22:00:27 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:28 2020 : rcvd [CHAP Challenge id=0x1 <135c36f03379f459fe1cd8588ae8a881>, name = "glory"]
Wed Apr 22 22:00:30 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 22:00:31 2020 : rcvd [LCP EchoReq id=0x0 magic=0x0 42 61 6b 61 20 4d 61 6e 75 6b 65 00 72 79 00 00]
Wed Apr 22 22:00:33 2020 : LCP: timeout sending Config-Requests
Wed Apr 22 22:00:33 2020 : Connection terminated.
Wed Apr 22 22:00:33 2020 : L2TP disconnecting...
Wed Apr 22 22:00:33 2020 : L2TP sent CDN
Wed Apr 22 22:00:33 2020 : L2TP sent StopCCN
Wed Apr 22 22:00:33 2020 : L2TP clearing port-mapping for en0
Wed Apr 22 22:00:33 2020 : L2TP disconnected
metalefty picture metalefty on 22 Apr 2020

@chipitsine Sure, I'll try.

metalefty picture metalefty on 22 Apr 2020

That's exactly what I expected. 9fff38de2bad483e9f99c67556d085ea78464957 is the problem.

Here's the bisect log.

# bad: [bf65ef290a3d48c9f3372c9070689467a81ca5e4] Merge pull request #1098 from chipitsine/master
# good: [3a309c9f6e059c00e0721dfa28ad959b7c52a137] Merge pull request #1041 from chipitsine/master
git bisect start '5.01.9673' '5.01.9672'
# good: [a49219db83ca74ab545866143fdc55489b9ac0c0] Merge branch 'master' of github.com:SoftEtherVPN/SoftEtherVPN into 200101_fix_securenat_ecn
git bisect good a49219db83ca74ab545866143fdc55489b9ac0c0
# good: [60c1e2027dd582ced1c0841e34e94bf343ba68b8] Merge pull request #1082 from metalefty/freebsd-ci
git bisect good 60c1e2027dd582ced1c0841e34e94bf343ba68b8
# bad: [84bd9abb30dddeb26ac614d1ec469afb45b7a2bf] Merge pull request #1072 from Evengard/ppp-ipv6
git bisect bad 84bd9abb30dddeb26ac614d1ec469afb45b7a2bf
# good: [5db21a1dc127e966e1b66cb8b3f0fcbb404a1c78] Merge pull request #1086 from jubnzv/sa-fixes
git bisect good 5db21a1dc127e966e1b66cb8b3f0fcbb404a1c78
# bad: [a6970e3e6161d80f93bb1b353133815180ff3956] Merge branch 'master' into ppp-ipv6
git bisect bad a6970e3e6161d80f93bb1b353133815180ff3956
# bad: [9fff38de2bad483e9f99c67556d085ea78464957] Rewriting PPP stack, preparing for IPv6 support
git bisect bad 9fff38de2bad483e9f99c67556d085ea78464957
# first bad commit: [9fff38de2bad483e9f99c67556d085ea78464957] Rewriting PPP stack, preparing for IPv6 support

EDITED:

Note: Windows 10 2004 build 19041.207 's built-in L2TP/IPsec and SSTP clients are both fine to connect.

metalefty picture metalefty on 22 Apr 2020

CC: @Evengard

metalefty picture metalefty on 22 Apr 2020

Just in case, here's the another successful log at 5.01.9672. Client is macOS 10.14.6 built-in L2TP/IPsec client. It looks loke something's going wrong during IPCP address assignment.

Wed Apr 22 23:44:41 2020 : publish_entry SCDSet() failed: Success!
Wed Apr 22 23:44:41 2020 : publish_entry SCDSet() failed: Success!
Wed Apr 22 23:44:41 2020 : l2tp_get_router_address
Wed Apr 22 23:44:41 2020 : l2tp_get_router_address 192.168.24.1 from dict 1
Wed Apr 22 23:44:41 2020 : L2TP connecting to server '192.168.24.5' (192.168.24.5)...
Wed Apr 22 23:44:41 2020 : IPSec connection started
Wed Apr 22 23:44:41 2020 : IPSec phase 1 client started
Wed Apr 22 23:44:41 2020 : IPSec phase 1 server replied
Wed Apr 22 23:44:42 2020 : IPSec phase 2 started
Wed Apr 22 23:44:42 2020 : IPSec phase 2 established
Wed Apr 22 23:44:42 2020 : IPSec connection established
Wed Apr 22 23:44:42 2020 : L2TP sent SCCRQ
Wed Apr 22 23:44:42 2020 : L2TP received SCCRP
Wed Apr 22 23:44:42 2020 : L2TP sent SCCCN
Wed Apr 22 23:44:42 2020 : L2TP sent ICRQ
Wed Apr 22 23:44:42 2020 : L2TP received ICRP
Wed Apr 22 23:44:42 2020 : L2TP sent ICCN
Wed Apr 22 23:44:42 2020 : L2TP connection established.
Wed Apr 22 23:44:42 2020 : L2TP set port-mapping for en0, interface: 5, protocol: 0, privatePort: 0
Wed Apr 22 23:44:42 2020 : using link 0
Wed Apr 22 23:44:42 2020 : Using interface ppp0
Wed Apr 22 23:44:42 2020 : Connect: ppp0 <--> socket[34:18]
Wed Apr 22 23:44:42 2020 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x4e64805> <pcomp> <accomp>]
Wed Apr 22 23:44:42 2020 : L2TP port-mapping for en0, interfaceIndex: 0, Protocol: None, Private Port: 0, Public Address: 838104a4, Public Port: 0, TTL: 0.
Wed Apr 22 23:44:42 2020 : L2TP port-mapping for en0 inconsistent. is Connected: 1, Previous interface: 5, Current interface 0
Wed Apr 22 23:44:42 2020 : L2TP port-mapping for en0 initialized. is Connected: 1, Previous publicAddress: (0), Current publicAddress 838104a4
Wed Apr 22 23:44:42 2020 : L2TP port-mapping for en0 fully initialized. Flagging up
Wed Apr 22 23:44:42 2020 : rcvd [LCP ConfReq id=0x0 <auth pap>]
Wed Apr 22 23:44:42 2020 : lcp_reqci: returning CONFACK.
Wed Apr 22 23:44:42 2020 : sent [LCP ConfAck id=0x0 <auth pap>]
Wed Apr 22 23:44:42 2020 : rcvd [LCP ConfRej id=0x1 <asyncmap 0x0> <magic 0x4e64805> <pcomp> <accomp>]
Wed Apr 22 23:44:42 2020 : sent [LCP ConfReq id=0x2]
Wed Apr 22 23:44:42 2020 : rcvd [LCP ConfAck id=0x2]
Wed Apr 22 23:44:42 2020 : sent [LCP EchoReq id=0x0 magic=0x0]
Wed Apr 22 23:44:42 2020 : sent [PAP AuthReq id=0x1 user="meta" password=<hidden>]
Wed Apr 22 23:44:42 2020 : rcvd [LCP EchoRep id=0x0 magic=0x0]
Wed Apr 22 23:44:42 2020 : rcvd [PAP AuthAck id=0x1]
Wed Apr 22 23:44:42 2020 : pap_rauthack: ignoring missing msg-length.
Wed Apr 22 23:44:42 2020 : PAP authentication succeeded
Wed Apr 22 23:44:42 2020 : sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Wed Apr 22 23:44:42 2020 : sent [IPV6CP ConfReq id=0x1 <addr fe80::a65e:60ff:fec3:1e19>]
Wed Apr 22 23:44:42 2020 : sent [ACSCP ConfReq id=0x1 <route vers 16777216> <domain vers 16777216>]
Wed Apr 22 23:44:42 2020 : rcvd [IPCP ConfReq id=0x1 <addr 192.0.0.8>]
Wed Apr 22 23:44:42 2020 : ipcp: returning Configure-ACK
Wed Apr 22 23:44:42 2020 : sent [IPCP ConfAck id=0x1 <addr 192.0.0.8>]
Wed Apr 22 23:44:42 2020 : rcvd [LCP ProtRej id=0x2 80 57 01 01 00 0e 01 0a a6 5e 60 ff fe c3 1e 19]
Wed Apr 22 23:44:42 2020 : rcvd [LCP ProtRej id=0x3 82 35 01 01 00 10 01 06 00 00 00 01 02 06 00 00 00 01]
Wed Apr 22 23:44:42 2020 : rcvd [IPCP ConfRej id=0x1 <ms-dns3 0.0.0.0>]
Wed Apr 22 23:44:42 2020 : sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0>]
Wed Apr 22 23:44:42 2020 : rcvd [IPCP ConfNak id=0x2 <addr 192.168.30.10> <ms-dns1 192.168.30.1>]
Wed Apr 22 23:44:42 2020 : sent [IPCP ConfReq id=0x3 <addr 192.168.30.10> <ms-dns1 192.168.30.1>]
Wed Apr 22 23:44:42 2020 : rcvd [IPCP ConfAck id=0x3 <addr 192.168.30.10> <ms-dns1 192.168.30.1>]
Wed Apr 22 23:44:42 2020 : ipcp: up
Wed Apr 22 23:44:42 2020 : local  IP address 192.168.30.10
Wed Apr 22 23:44:42 2020 : remote IP address 192.0.0.8
Wed Apr 22 23:44:42 2020 : primary   DNS address 192.168.30.1
Wed Apr 22 23:44:42 2020 : Received protocol dictionaries
Wed Apr 22 23:44:42 2020 : sent [IP data <src addr 192.168.30.10> <dst addr 255.255.255.255> <BOOTP Request> <type INFORM> <client id 0x08000000010000> <parameters = 0x6 0x2c 0x2b 0x1 0xf9 0xf>]
Wed Apr 22 23:44:42 2020 : Received acsp/dhcp dictionaries
Wed Apr 22 23:44:42 2020 : Received acsp/dhcp dictionaries
Wed Apr 22 23:44:42 2020 : l2tp_wait_input: Address added. previous interface setting (name: en0, address: 192.168.24.110), current interface setting (name: ppp0, family: PPP, address: 192.168.30.10, subnet: 255.255.255.0, destination: 192.0.0.8).
Wed Apr 22 23:44:42 2020 : rcvd [IP data <src addr 192.168.30.1> <dst addr 192.168.30.10> <BOOTP Reply> <type ACK> <server id 0xc0a81e01> <subnet mask 255.255.255.0> <option 3> <option 6>]
Wed Apr 22 23:44:42 2020 : Received acsp/dhcp dictionaries
Wed Apr 22 23:44:42 2020 : l2tp_wait_input: Address deleted. previous interface setting (name: en0, address: 192.168.24.110), deleted interface setting (name: ppp0, family: PPP, address: 192.168.30.10, subnet: 255.255.255.0, destination: 192.0.0.8).
Wed Apr 22 23:44:42 2020 : l2tp_wait_input: Address added. previous interface setting (name: en0, address: 192.168.24.110), current interface setting (name: ppp0, family: PPP, address: 192.168.30.10, subnet: 255.255.255.0, destination: 192.0.0.8).
Wed Apr 22 23:44:42 2020 : Committed PPP store on install command
Wed Apr 22 23:44:42 2020 : Committed PPP store on install command
metalefty picture metalefty on 22 Apr 2020

oooooook
so we need to find a way how to test that automatically

chipitsine picture chipitsine on 22 Apr 2020

I'll try to look into it on the weekend. Although I don't own any iOS devices, but I can at least try to debug the Android version and analyze the logs.

Evengard picture Evengard on 23 Apr 2020

@Evengard
Don't you have Mac devices?

BTW, could you test also clients other than SoftEtherVPN original? For example, sstp-client (SSTP on Linux) or strongSwan + xl2tpd. They use Linux's ppp stack. As far as I investigated, it looks not working with PPP stack other than Windows.

Here's another log with SSTP on macOS. The log is almost the same as the built-in L2TP/IPsec client. So I assume the root cause is the same.

Apr 24 09:29:46 sstpc[3458]: Server certificated failed verification, ignoring
Apr 24 09:29:46 sstpc[3458]: Sending Connect-Request Message
Apr 24 09:29:46 sstpc[3458]: SEND SSTP CRTL PKT(14)
Apr 24 09:29:46 sstpc[3458]:   TYPE(1): CONNECT REQUEST, ATTR(1):
Apr 24 09:29:46 sstpc[3458]:     ENCAP PROTO(1): 6
Apr 24 09:29:46 sstpc[3458]: RECV SSTP CRTL PKT(48)
Apr 24 09:29:46 sstpc[3458]:   TYPE(2): CONNECT ACK, ATTR(1):
Apr 24 09:29:46 sstpc[3458]:     CRYPTO BIND REQ(4): 40
Apr 24 09:29:46 sstpc[3458]: Started PPP Link Negotiation
Apr 24 09:29:46 sstpc[3458]: SEND SSTP DATA PKT(32)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 1  CONFREQ ASYNCMAP: 00 00 00 00 AUTH: EAP MAGIC: 0x5F1F1D07
Apr 24 09:29:46 sstpc[3458]: RECV SSTP DATA PKT(28)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 1  CONFREJ ASYNCMAP: 00 00 00 00 MAGIC: 0x5F1F1D07
Apr 24 09:29:46 sstpc[3458]: SEND SSTP DATA PKT(16)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 2  CONFREQ AUTH: EAP
Apr 24 09:29:46 sstpc[3458]: RECV SSTP DATA PKT(17)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 0  CONFREQ AUTH: CHAP
Apr 24 09:29:46 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:29:46 sstpc[3458]: SEND SSTP DATA PKT(17)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 0  CONFACK AUTH: CHAP
Apr 24 09:29:46 sstpc[3458]: RECV SSTP DATA PKT(17)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 2  CONFNAK AUTH: CHAP
Apr 24 09:29:46 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:29:46 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:29:46 sstpc[3458]: RECV SSTP DATA PKT(34)
Apr 24 09:29:46 sstpc[3458]:   PPP CHAP ID: 1  ID: 1 CHALLENGE [D275BFD781CEB466CFFF13A5D296F9F1], NAME: glory
Apr 24 09:29:49 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:29:49 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:29:51 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:29:51 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:29:51 sstpc[3458]: RECV SSTP DATA PKT(34)
Apr 24 09:29:51 sstpc[3458]:   PPP CHAP ID: 1  ID: 1 CHALLENGE [D275BFD781CEB466CFFF13A5D296F9F1], NAME: glory
Apr 24 09:29:52 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:29:52 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:29:55 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:29:55 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:29:56 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:29:56 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:29:56 sstpc[3458]: RECV SSTP DATA PKT(34)
Apr 24 09:29:56 sstpc[3458]:   PPP CHAP ID: 1  ID: 1 CHALLENGE [D275BFD781CEB466CFFF13A5D296F9F1], NAME: glory
Apr 24 09:29:58 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:29:58 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:30:00 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:30:00 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:30:01 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:30:01 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:30:01 sstpc[3458]: RECV SSTP DATA PKT(34)
Apr 24 09:30:01 sstpc[3458]:   PPP CHAP ID: 1  ID: 1 CHALLENGE [D275BFD781CEB466CFFF13A5D296F9F1], NAME: glory
Apr 24 09:30:04 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:30:04 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:30:05 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:30:05 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:30:06 sstpc[3458]: RECV SSTP DATA PKT(34)
Apr 24 09:30:06 sstpc[3458]:   PPP CHAP ID: 1  ID: 1 CHALLENGE [D275BFD781CEB466CFFF13A5D296F9F1], NAME: glory
Apr 24 09:30:07 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:30:07 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:30:10 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:30:10 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:30:10 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:30:10 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:30:11 sstpc[3458]: RECV SSTP DATA PKT(34)
Apr 24 09:30:11 sstpc[3458]:   PPP CHAP ID: 1  ID: 1 CHALLENGE [D275BFD781CEB466CFFF13A5D296F9F1], NAME: glory
Apr 24 09:30:13 sstpc[3458]: SEND SSTP DATA PKT(12)
Apr 24 09:30:13 sstpc[3458]:   PPP LCP ID: 3  CONFREQ
Apr 24 09:30:15 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:30:15 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:30:20 sstpc[3458]: RECV SSTP DATA PKT(32)
Apr 24 09:30:20 sstpc[3458]:   PPP LCP ID: 0  ECHOREQ MAGIC: 0x00000000
Apr 24 09:30:20 sstpc[3458]: Could not complete write of frame
Apr 24 09:30:20 sstpc[3458]: Could not forward packet to pppd
Apr 24 09:30:23 sstpc[3458]: RECV SSTP CRTL PKT(8)
Apr 24 09:30:23 sstpc[3458]:   TYPE(5): ABORT, ATTR(0):
Apr 24 09:30:23 sstpc[3458]: Could not parse attributes
Apr 24 09:30:23 sstpc[3458]: Unrecoverable SSL error
Apr 24 09:30:23 sstpc[3458]: Connection was aborted, Reason was not known
metalefty picture metalefty on 24 Apr 2020

Nope, I don't have any Mac devices. I do have Linux devices though.

Judging by theese logs it seems like the server for some reason struggles answering the MS-CHAP handshake. Just to test, does the connection work with PAP?

Also it should be noted that MS-CHAP and just CHAP are two different protocols. SoftEther VPN never supported just CHAP (it's old and vulnerable anyway).

Evengard picture Evengard on 24 Apr 2020

I was able to reproduce the problem on Linux sstp-client. Luckily, enabling debug mode on pppd shows extended logs.
The culprit seems that I changed the priority from the less secure PAP to the more secure MS-CHAP. The problem is that the client refuses to process the sent by the server MS-CHAP challenge until at least some other LCP packet gets accepted (in the logs it is defined by the lines PPP LCP ID: 1 CONFREQ ASYNCMAP: 00 00 00 00 AUTH: EAP MAGIC: 0x5F1F1D07 or sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x4e64805> <pcomp> <accomp>]). On my machine I get a message like this: Discarded non-LCP packet when LCP not open. When I added to the pppd options "mru 1400" (which got accepted by the server, because it recognized the mru LCP) - swoosh and MS-CHAP suddenly starts working and we then are trying to get the IPCP configuration going.

It seems like I will need to implement at least some other LCP packet just to make the client happy and start processing MS-CHAP (I guess "magic" should be easy enough to implement).

Now there is some kind of apparent trouble with IPCP negotiation as well, but I will need to dig into it after I fix the authentication...

UPD: after reading logs more attentively, it seems like after being rejected the client sends an LCP request with an EMPTY OPTIONS list! That's the culprit here, having an empty LCP options list is kinda unexpected for the server, so it seems to just discard the packet. If I fix just that I won't need to use arcane techniques of "trying to make happy".

Evengard picture Evengard on 25 Apr 2020

I was able to fix the Discarded non-LCP packet when LCP not open bug by ACKing an empty LCP options list (https://github.com/Evengard/SoftEtherVPN/commit/b9109211d32027f7e8704996075f26694baa4546). Now with IPCP the server tells me that it fails to acquire the IP address from DHCP (which is weird because other clients are able to obtain such information without any problems). I'll dig into it a bit later, but even with this fix static configuration MIGHT work.

Evengard picture Evengard on 25 Apr 2020

Now with IPCP. That's a more subtle matter here. In the Windows world, when the client requests an IP address via DHCP, it _zeroes out_ the IP address in the IPCP IP-Address option. It seems to be not the case of the Linux world, as it seems to still send an IP address of one of his interfaces (usually the one it actually used to connect to the server) - as if requesting a static IP address configuration.

Now there's a trick. It is still using DHCP to request additional information (ie DNS servers and stuff). And the embedded into SoftEtherVPN DHCP server actually accepts any client IP address without any trouble, supplying with any additional information requested.

Now there it gets more tricky. In my setup I do not use the SoftEtherVPN DHCP server, I use DNSMasq instead. And DNSMasq actually rejects the client IP address (because this address isn't in his configured range of allowed ones). SoftEtherVPN just relays it back to the client and the connection fails, which is totally logical.

Now the thing is that after the rejection the Linux client sends once again ANOTHER IPCP request. And... Yes, you probably guessed right. Another one EMPTY IPCP request. Which once again (exactly like with the LCP above) confuses the server and discards it.

Luckily it shouldn't be too hard to fix it up too! Just treating an empty IPCP request as a request with a zeroed out IP-Address option should probably do the trick.

Evengard picture Evengard on 25 Apr 2020

And yep, it worked. Except that I also needed to reset the static IP flag as well set during the failing static address assignement.
https://github.com/Evengard/SoftEtherVPN/commit/f6d42ab22e0ffe0fec698994c7fb8dc171007032

Now Linux, Windows, VPN Client for Android all connects. I do need tests from Mac OS and/or iOS though as I don't have access to theese devices.

I will do a pull request shortly.

Evengard picture Evengard on 25 Apr 2020

1104 works for me with macOS client.

Sun Apr 26 19:36:50 2020 : publish_entry SCDSet() failed: Success!
Sun Apr 26 19:36:50 2020 : publish_entry SCDSet() failed: Success!
Sun Apr 26 19:36:50 2020 : l2tp_get_router_address
Sun Apr 26 19:36:50 2020 : l2tp_get_router_address 192.168.24.1 from dict 1
Sun Apr 26 19:36:50 2020 : L2TP connecting to server '192.168.24.5' (192.168.24.5)...
Sun Apr 26 19:36:50 2020 : IPSec connection started
Sun Apr 26 19:36:50 2020 : IPSec phase 1 client started
Sun Apr 26 19:36:50 2020 : IPSec phase 1 server replied
Sun Apr 26 19:36:51 2020 : IPSec phase 2 started
Sun Apr 26 19:36:51 2020 : IPSec phase 2 established
Sun Apr 26 19:36:51 2020 : IPSec connection established
Sun Apr 26 19:36:51 2020 : L2TP sent SCCRQ
Sun Apr 26 19:36:51 2020 : L2TP received SCCRP
Sun Apr 26 19:36:51 2020 : L2TP sent SCCCN
Sun Apr 26 19:36:51 2020 : L2TP sent ICRQ
Sun Apr 26 19:36:51 2020 : L2TP received ICRP
Sun Apr 26 19:36:51 2020 : L2TP sent ICCN
Sun Apr 26 19:36:51 2020 : L2TP connection established.
Sun Apr 26 19:36:51 2020 : L2TP set port-mapping for en0, interface: 5, protocol: 0, privatePort: 0
Sun Apr 26 19:36:51 2020 : using link 0
Sun Apr 26 19:36:51 2020 : Using interface ppp0
Sun Apr 26 19:36:51 2020 : Connect: ppp0 <--> socket[34:18]
Sun Apr 26 19:36:51 2020 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x5878a0d2> <pcomp> <accomp>]
Sun Apr 26 19:36:51 2020 : L2TP port-mapping for en0, interfaceIndex: 0, Protocol: None, Private Port: 0, Public Address: 838104a4, Public Port: 0, TTL: 0.
Sun Apr 26 19:36:51 2020 : L2TP port-mapping for en0 inconsistent. is Connected: 1, Previous interface: 5, Current interface 0
Sun Apr 26 19:36:51 2020 : L2TP port-mapping for en0 initialized. is Connected: 1, Previous publicAddress: (0), Current publicAddress 838104a4
Sun Apr 26 19:36:51 2020 : L2TP port-mapping for en0 fully initialized. Flagging up
Sun Apr 26 19:36:51 2020 : rcvd [LCP ConfReq id=0x0 <auth pap>]
Sun Apr 26 19:36:51 2020 : lcp_reqci: returning CONFACK.
Sun Apr 26 19:36:51 2020 : sent [LCP ConfAck id=0x0 <auth pap>]
Sun Apr 26 19:36:51 2020 : rcvd [LCP ConfRej id=0x1 <asyncmap 0x0> <magic 0x5878a0d2> <pcomp> <accomp>]
Sun Apr 26 19:36:51 2020 : sent [LCP ConfReq id=0x2]
Sun Apr 26 19:36:51 2020 : rcvd [LCP ConfAck id=0x2]
Sun Apr 26 19:36:51 2020 : sent [LCP EchoReq id=0x0 magic=0x0]
Sun Apr 26 19:36:51 2020 : sent [PAP AuthReq id=0x1 user="meta" password=<hidden>]
Sun Apr 26 19:36:51 2020 : rcvd [LCP EchoRep id=0x0 magic=0x0]
Sun Apr 26 19:36:51 2020 : rcvd [PAP AuthAck id=0x1]
Sun Apr 26 19:36:51 2020 : pap_rauthack: ignoring missing msg-length.
Sun Apr 26 19:36:51 2020 : PAP authentication succeeded
Sun Apr 26 19:36:51 2020 : sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Sun Apr 26 19:36:51 2020 : sent [IPV6CP ConfReq id=0x1 <addr fe80::a65e:60ff:fec3:1e19>]
Sun Apr 26 19:36:51 2020 : sent [ACSCP ConfReq id=0x1 <route vers 16777216> <domain vers 16777216>]
Sun Apr 26 19:36:51 2020 : rcvd [IPCP ConfReq id=0x1 <addr 192.0.0.8>]
Sun Apr 26 19:36:51 2020 : ipcp: returning Configure-ACK
Sun Apr 26 19:36:51 2020 : sent [IPCP ConfAck id=0x1 <addr 192.0.0.8>]
Sun Apr 26 19:36:51 2020 : rcvd [LCP ProtRej id=0x2 80 57 01 01 00 0e 01 0a a6 5e 60 ff fe c3 1e 19]
Sun Apr 26 19:36:51 2020 : rcvd [LCP ProtRej id=0x3 82 35 01 01 00 10 01 06 00 00 00 01 02 06 00 00 00 01]
Sun Apr 26 19:36:51 2020 : rcvd [IPCP ConfRej id=0x1 <ms-dns3 0.0.0.0>]
Sun Apr 26 19:36:51 2020 : sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0>]
Sun Apr 26 19:36:51 2020 : rcvd [IPCP ConfNak id=0x2 <addr 192.168.30.10> <ms-dns1 192.168.30.1>]
Sun Apr 26 19:36:51 2020 : sent [IPCP ConfReq id=0x3 <addr 192.168.30.10> <ms-dns1 192.168.30.1>]
Sun Apr 26 19:36:51 2020 : rcvd [IPCP ConfAck id=0x3 <addr 192.168.30.10> <ms-dns1 192.168.30.1>]
Sun Apr 26 19:36:51 2020 : ipcp: up
Sun Apr 26 19:36:51 2020 : local  IP address 192.168.30.10
Sun Apr 26 19:36:51 2020 : remote IP address 192.0.0.8
Sun Apr 26 19:36:51 2020 : primary   DNS address 192.168.30.1
Sun Apr 26 19:36:51 2020 : Received protocol dictionaries
Sun Apr 26 19:36:51 2020 : sent [IP data <src addr 192.168.30.10> <dst addr 255.255.255.255> <BOOTP Request> <type INFORM> <client id 0x08000000010000> <parameters = 0x6 0x2c 0x2b 0x1 0xf9 0xf>]
Sun Apr 26 19:36:51 2020 : Received acsp/dhcp dictionaries
Sun Apr 26 19:36:51 2020 : Received acsp/dhcp dictionaries
Sun Apr 26 19:36:51 2020 : l2tp_wait_input: Address added. previous interface setting (name: en0, address: 192.168.24.110), current interface setting (name: ppp0, family: PPP, address: 192.168.30.10, subnet: 255.255.255.0, destination: 192.0.0.8).
Sun Apr 26 19:36:51 2020 : rcvd [IP data <src addr 192.168.30.1> <dst addr 192.168.30.10> <BOOTP Reply> <type ACK> <server id 0xc0a81e01> <subnet mask 255.255.255.0> <option 3> <option 6>]
Sun Apr 26 19:36:51 2020 : Received acsp/dhcp dictionaries
Sun Apr 26 19:36:51 2020 : l2tp_wait_input: Address deleted. previous interface setting (name: en0, address: 192.168.24.110), deleted interface setting (name: ppp0, family: PPP, address: 192.168.30.10, subnet: 255.255.255.0, destination: 192.0.0.8).
Sun Apr 26 19:36:51 2020 : l2tp_wait_input: Address added. previous interface setting (name: en0, address: 192.168.24.110), current interface setting (name: ppp0, family: PPP, address: 192.168.30.10, subnet: 255.255.255.0, destination: 192.0.0.8).
Sun Apr 26 19:36:51 2020 : Committed PPP store on install command
Sun Apr 26 19:36:51 2020 : Committed PPP store on install command
Sun Apr 26 19:36:51 2020 : Committed PPP store on install command
metalefty picture metalefty on 26 Apr 2020
👍1

@akira345 Should be fixed by #1104, thank you for reporting!

metalefty picture metalefty on 26 Apr 2020
🎉2

I'm closing. Thanks to @Evengard
feel free to open if is still relevant

we will release soon

chipitsine picture chipitsine on 26 Apr 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

yurivict picture yurivict  路  7Comments
paskal picture paskal  路  12Comments
GlennMatthys picture GlennMatthys  路  6Comments
gulbuhar picture gulbuhar  路  9Comments
vampywiz17 picture vampywiz17  路  11Comments