Sudden failure to connect - IPCP issue?

Post your questions about SoftEther VPN software here. Please answer questions if you can afford.
Post Reply
logicelf
Posts: 2
Joined: Wed Dec 06, 2017 12:19 pm

Sudden failure to connect - IPCP issue?

Post by logicelf » Wed Dec 06, 2017 12:57 pm

Hi all,

I've been running SoftEther in a jail on a FreeBSD box for a few weeks. It's been flawless up until the last few days. All of a sudden, I can't establish a connection from macOS or iOS. I'm using standard L2TP configs with shared key and a user account.

The connection initiates and completes PAP authentication, and then there seems to be an issue with IPCP and address allocation - but my knowledge falters here.

I've restarted the SoftEther jail, the host box, and the router. I've also set the client IP, mask and gateway manually according to the host LAN, instead of letting PPP assign the IP - no change. I've also made sure that SoftEther is up to date. Nothing else has changed, to my knowledge.

Any pointers gratefully received!

macOS client log excerpt of a typical connection attempt and timeout follows:

Wed Dec 6 12:35:21 2017 : IPSec connection established
Wed Dec 6 12:35:21 2017 : L2TP sent SCCRQ
Wed Dec 6 12:35:41 2017 : L2TP cannot connect to the server
Wed Dec 6 12:35:55 2017 : publish_entry SCDSet() failed: Success!
Wed Dec 6 12:35:55 2017 : publish_entry SCDSet() failed: Success!
Wed Dec 6 12:35:55 2017 : l2tp_get_router_address
Wed Dec 6 12:35:55 2017 : l2tp_get_router_address 192.168.1.1 from dict 1
Wed Dec 6 12:35:55 2017 : L2TP connecting to server 'REDACTED' (REDACTED)...
Wed Dec 6 12:35:55 2017 : IPSec connection started
Wed Dec 6 12:35:56 2017 : IPSec phase 1 client started
Wed Dec 6 12:35:57 2017 : IPSec phase 1 server replied
Wed Dec 6 12:36:00 2017 : IPSec phase 2 started
Wed Dec 6 12:36:01 2017 : IPSec phase 2 established
Wed Dec 6 12:36:01 2017 : IPSec connection established
Wed Dec 6 12:36:01 2017 : L2TP sent SCCRQ
Wed Dec 6 12:36:02 2017 : L2TP received SCCRP
Wed Dec 6 12:36:02 2017 : L2TP sent SCCCN
Wed Dec 6 12:36:02 2017 : L2TP sent ICRQ
Wed Dec 6 12:36:02 2017 : L2TP received ICRP
Wed Dec 6 12:36:02 2017 : L2TP sent ICCN
Wed Dec 6 12:36:02 2017 : L2TP connection established.
Wed Dec 6 12:36:02 2017 : L2TP set port-mapping for en0, interface: 5, protocol: 0, privatePort: 0
Wed Dec 6 12:36:02 2017 : using link 0
Wed Dec 6 12:36:02 2017 : Using interface ppp0
Wed Dec 6 12:36:02 2017 : Connect: ppp0 <--> socket[34:18]
Wed Dec 6 12:36:02 2017 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x676ad00> <pcomp> <accomp>]
Wed Dec 6 12:36:02 2017 : L2TP port-mapping for en0, interfaceIndex: 0, Protocol: None, Private Port: 0, Public Address: 50e5dcd3, Public Port: 0, TTL: 0.
Wed Dec 6 12:36:02 2017 : L2TP port-mapping for en0 inconsistent. is Connected: 1, Previous interface: 5, Current interface 0
Wed Dec 6 12:36:02 2017 : L2TP port-mapping for en0 initialized. is Connected: 1, Previous publicAddress: (0), Current publicAddress 50e5dcd3
Wed Dec 6 12:36:02 2017 : L2TP port-mapping for en0 fully initialized. Flagging up
Wed Dec 6 12:36:03 2017 : rcvd [LCP ConfReq id=0x0 <auth pap>]
Wed Dec 6 12:36:03 2017 : lcp_reqci: returning CONFACK.
Wed Dec 6 12:36:03 2017 : sent [LCP ConfAck id=0x0 <auth pap>]
Wed Dec 6 12:36:03 2017 : rcvd [LCP ConfRej id=0x1 <asyncmap 0x0> <magic 0x676ad00> <pcomp> <accomp>]
Wed Dec 6 12:36:03 2017 : sent [LCP ConfReq id=0x2]
Wed Dec 6 12:36:04 2017 : rcvd [LCP ConfAck id=0x2]
Wed Dec 6 12:36:04 2017 : sent [LCP EchoReq id=0x0 magic=0x0]
Wed Dec 6 12:36:04 2017 : sent [PAP AuthReq id=0x1 user="REDACTED" password=<hidden>]
Wed Dec 6 12:36:04 2017 : rcvd [LCP EchoRep id=0x0 magic=0x0]
Wed Dec 6 12:36:04 2017 : rcvd [PAP AuthAck id=0x1]
Wed Dec 6 12:36:04 2017 : pap_rauthack: ignoring missing msg-length.
Wed Dec 6 12:36:04 2017 : PAP authentication succeeded
Wed Dec 6 12:36:04 2017 : sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Wed Dec 6 12:36:04 2017 : sent [IPV6CP ConfReq id=0x1 <addr fe80::3e15:c2ff:fec8:de08>]
Wed Dec 6 12:36:07 2017 : sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Wed Dec 6 12:36:07 2017 : sent [IPV6CP ConfReq id=0x1 <addr fe80::3e15:c2ff:fec8:de08>]
Wed Dec 6 12:36:10 2017 : rcvd [LCP ProtRej id=0x2 80 57 01 01 00 0e 01 0a 3e 15 c2 ff fe c8 de 08]
Wed Dec 6 12:36:10 2017 : rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Wed Dec 6 12:36:10 2017 : sent [IPCP ConfReq id=0x2 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:10 2017 : rcvd [LCP ProtRej id=0x3 80 57 01 01 00 0e 01 0a 3e 15 c2 ff fe c8 de 08]
Wed Dec 6 12:36:10 2017 : rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Wed Dec 6 12:36:10 2017 : rcvd [IPCP ConfReq id=0x1 <addr 1.0.0.1>]
Wed Dec 6 12:36:10 2017 : ipcp: returning Configure-ACK
Wed Dec 6 12:36:10 2017 : sent [IPCP ConfAck id=0x1 <addr 1.0.0.1>]
Wed Dec 6 12:36:11 2017 : rcvd [IPCP ConfRej id=0x2 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:11 2017 : sent [IPCP ConfReq id=0x3 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:11 2017 : rcvd [IPCP ConfRej id=0x3 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:11 2017 : sent [IPCP ConfReq id=0x4 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:14 2017 : sent [IPCP ConfReq id=0x4 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:15 2017 : rcvd [IPCP ConfRej id=0x4 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:15 2017 : sent [IPCP ConfReq id=0x5 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:15 2017 : rcvd [IPCP ConfRej id=0x5 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:15 2017 : sent [IPCP ConfReq id=0x6 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:16 2017 : rcvd [IPCP ConfRej id=0x6 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:16 2017 : sent [IPCP ConfReq id=0x7 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:16 2017 : rcvd [IPCP ConfRej id=0x7 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:16 2017 : sent [IPCP ConfReq id=0x8 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:17 2017 : rcvd [IPCP ConfRej id=0x8 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:17 2017 : sent [IPCP ConfReq id=0x9 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:18 2017 : rcvd [IPCP ConfRej id=0x9 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:36:18 2017 : sent [IPCP ConfReq id=0xa <addrs 0.0.0.0 0.0.0.0>]

... more of the same ...

Wed Dec 6 12:37:35 2017 : rcvd [IPCP ConfRej id=0x69 <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:35 2017 : sent [IPCP ConfReq id=0x6a <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:36 2017 : rcvd [IPCP ConfRej id=0x6a <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:36 2017 : sent [IPCP ConfReq id=0x6b <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:37 2017 : rcvd [IPCP ConfRej id=0x6b <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:37 2017 : sent [IPCP ConfReq id=0x6c <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:37 2017 : rcvd [IPCP ConfRej id=0x6c <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:37 2017 : sent [IPCP ConfReq id=0x6d <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:38 2017 : rcvd [IPCP ConfRej id=0x6d <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:38 2017 : sent [IPCP ConfReq id=0x6e <addrs 0.0.0.0 0.0.0.0>]
Wed Dec 6 12:37:40 2017 : [TERMINATE]
Wed Dec 6 12:37:40 2017 : Terminating on signal 15.
Wed Dec 6 12:37:40 2017 : sent [LCP TermReq id=0x3 "User request"]
Wed Dec 6 12:37:40 2017 : Connection terminated.
Wed Dec 6 12:37:40 2017 : L2TP disconnecting...
Wed Dec 6 12:37:40 2017 : L2TP sent CDN
Wed Dec 6 12:37:40 2017 : L2TP sent StopCCN
Wed Dec 6 12:37:40 2017 : L2TP clearing port-mapping for en0
Wed Dec 6 12:37:40 2017 : L2TP disconnected

thisjun
Posts: 2458
Joined: Mon Feb 24, 2014 11:03 am

Re: Sudden failure to connect - IPCP issue?

Post by thisjun » Wed Dec 20, 2017 4:46 am

Could you show the server side log?

logicelf
Posts: 2
Joined: Wed Dec 06, 2017 12:19 pm

Re: Sudden failure to connect - IPCP issue?

Post by logicelf » Wed Dec 20, 2017 9:06 am

Thanks, but I've just had another look at it and solved it by turning on the NAT and DHCP options. Why it is now failing to pass DHCP to the physical router is a bit of a mystery, but I don't particularly care as long as it can hand out LAN IPs ...

Post Reply