VPN Server on Catalina

Networkvpn

I set up a VPN server on my Mac Mini following the instructions on https://robintiwari.com/post/how-to-set-up-vpn-server-on-macos

Assigning IP adresses from 201 to 216.

The ports are open and forwarded to my Mac Mini (and the problem described below also occurs when trying to connect from within the home network).

When connecting with iOS 13 I get the following entries in /var/log/vpnd.log

When trying to connect I get

2019-11-25 20:53:34 CET Incoming call... Address given to client = 192.168.1.205
Mon Nov 25 20:53:34 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:34 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:34 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:34 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:34 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:34 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:34 2019 : L2TP sent SCCRP
2019-11-25 20:53:34 CET Incoming call... Address given to client = 192.168.1.206
Mon Nov 25 20:53:34 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:34 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:34 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:34 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:34 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:34 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:34 2019 : L2TP sent SCCRP
2019-11-25 20:53:36 CET Incoming call... Address given to client = 192.168.1.207
Mon Nov 25 20:53:36 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:36 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:36 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:36 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:36 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:36 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:36 2019 : L2TP sent SCCRP
2019-11-25 20:53:40 CET Incoming call... Address given to client = 192.168.1.208
Mon Nov 25 20:53:40 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:40 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:40 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:40 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:40 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:40 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:40 2019 : L2TP sent SCCRP
2019-11-25 20:53:44 CET Incoming call... Address given to client = 192.168.1.209
Mon Nov 25 20:53:44 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:44 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:44 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:44 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:44 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:44 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:44 2019 : L2TP sent SCCRP
2019-11-25 20:53:48 CET Incoming call... Address given to client = 192.168.1.210
Mon Nov 25 20:53:48 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:48 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:48 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:48 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:48 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:48 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:48 2019 : L2TP sent SCCRP
2019-11-25 20:53:52 CET Incoming call... Address given to client = 192.168.1.211
Mon Nov 25 20:53:52 2019 : Directory Services Authorization plugin initialized
Mon Nov 25 20:53:52 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:52 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:52 2019 : publish_entry SCDSet() failed: Success!
Mon Nov 25 20:53:52 2019 : L2TP incoming call in progress from '192.168.1.1'...
Mon Nov 25 20:53:52 2019 : L2TP received SCCRQ
Mon Nov 25 20:53:52 2019 : L2TP sent SCCRP
2019-11-25 20:53:54 CET    --> Client with address = 192.168.1.205 has hungup
2019-11-25 20:53:55 CET    --> Client with address = 192.168.1.206 has hungup
2019-11-25 20:53:57 CET    --> Client with address = 192.168.1.207 has hungup
2019-11-25 20:54:01 CET    --> Client with address = 192.168.1.208 has hungup
2019-11-25 20:54:05 CET    --> Client with address = 192.168.1.209 has hungup
2019-11-25 20:54:08 CET    --> Client with address = 192.168.1.210 has hungup
2019-11-25 20:54:12 CET    --> Client with address = 192.168.1.211 has hungup

Any hints?

Edit

These are the logs on the iPhone trying to connect:

default 21:24:46.761882+0100    pppd    NetworkExtension is the controller
default 21:24:46.782624+0100    nesessionmanager    Got a new session client connection from pppd(6313)
default 21:24:46.782721+0100    nesessionmanager    NESMLegacySession[Casa:5FAFF43E-28EA-45E8-8B44-8D6769CCE159]: Adding a connection for client pppd[6313]
default 21:24:46.783978+0100    pppd    publish_entry SCDSet() failed: Success!
default 21:24:46.784915+0100    pppd    publish_entry SCDSet() failed: Success!
default 21:24:46.786506+0100    pppd    pppd 2.4.2 (Apple version 862) started by root, uid 0
default 21:24:46.789427+0100    pppd    l2tp_get_router_address
default 21:24:46.791187+0100    pppd    l2tp_get_router_address 192.168.1.1 from dict 1
default 21:24:46.799911+0100    mDNSResponder   [R107468] DNSServiceCreateConnection START PID[6313](pppd)
default 21:24:46.799971+0100    mDNSResponder   [R107469] DNSServiceQueryRecord(15000, 0, <private>, Addr) START PID[6313](pppd)
default 21:24:46.837876+0100    mDNSResponder   [R107469] DNSServiceQueryRecord(15000, 0, <private>, Addr) STOP PID[6313](pppd)
default 21:24:46.841876+0100    pppd    L2TP connecting to server 'casa.corti.li' (51.154.164.133)...
default 21:24:46.845226+0100    pppd    IPSec connection started
default 21:24:48.066632+0100    pppd    IPSec connection established
default 21:24:51.805555+0100    symptomsd   TCPPP: 0x16182d840 requesting ModeDefault and already in ModeDefault, no-op
default 21:25:08.066077+0100    pppd    L2TP cannot connect to the server
default 21:25:08.072647+0100    mDNSResponder   [R107468] DNSServiceCreateConnection STOP PID[6313](pppd)
default 21:25:08.075906+0100    nesessionmanager    NESMLegacySession[Casa:5FAFF43E-28EA-45E8-8B44-8D6769CCE159]: Removing a connection for client pppd[6313]
default 21:25:12.317658+0100    callservicesd   [FBSSystemAppProxy:0x1051c26b0] Service facility connection invalidated

and (I don't know how to do a filter with an 'or' in the console)

default 21:39:53.074716+0100    racoon  plogsetfile: about to add racoon log file: /var/log/racoon.log
default 21:39:53.126744+0100    racoon  accepted connection on vpn control socket.
default 21:39:53.126813+0100    racoon  received bind command on vpn control socket.
default 21:39:53.134299+0100    racoon  New Phase 2
default 21:39:53.134407+0100    racoon  state changed to: IKEv1 quick I start
default 21:39:53.135343+0100    racoon  IPsec-SA request for 51.154.164.133 queued due to no Phase 1 found.
default 21:39:53.135385+0100    racoon  New Phase 1
default 21:39:53.135497+0100    racoon  state changed to: IKEv1 ident I start
default 21:39:53.135652+0100    racoon  initiate new phase 1 negotiation: 192.168.1.46[500]<=>51.154.164.133[500]
default 21:39:53.135729+0100    racoon  begin Identity Protection mode.
default 21:39:53.135798+0100    racoon  IPSec Phase 1 started (Initiated by me).
default 21:39:53.137267+0100    racoon  Resend Phase 1 packet 6053c723b0e225a8:0000000000000000
default 21:39:53.138278+0100    racoon  state changed to: IKEv1 ident I msg1 sent
default 21:39:53.138328+0100    racoon  >>>>> phase change status = Phase 1 started by us
default 21:39:53.186357+0100    racoon  seen nptype=1(sa)
default 21:39:53.186440+0100    racoon  seen nptype=13(vid)
default 21:39:53.186502+0100    racoon  seen nptype=13(vid)
default 21:39:53.186568+0100    racoon  seen nptype=13(vid)
default 21:39:53.186672+0100    racoon  received Vendor ID: RFC 3947
default 21:39:53.186732+0100    racoon  received Vendor ID: DPD
default 21:39:53.186796+0100    racoon  received broken Microsoft ID: FRAGMENTATION
default 21:39:53.186906+0100    racoon  Selected NAT-T version: RFC 3947
default 21:39:53.187036+0100    racoon  seen nptype=2(prop)
default 21:39:53.187279+0100    racoon  seen nptype=3(trns)
default 21:39:53.189718+0100    racoon  state changed to: IKEv1 ident I msg2 rcvd
default 21:39:53.189769+0100    racoon  >>>>> phase change status = Phase 1 started by peer
default 21:39:53.288840+0100    racoon  Hashing 51.154.164.133[500] with algo #4
default 21:39:53.288944+0100    racoon  Hashing 192.168.1.46[500] with algo #4
default 21:39:53.289167+0100    racoon  Adding remote and local NAT-D payloads.
default 21:39:53.290071+0100    racoon  Resend Phase 1 packet 6053c723b0e225a8:21fbfaa914120f33
default 21:39:53.290121+0100    racoon  state changed to: IKEv1 ident I msg3 sent
default 21:39:53.335052+0100    racoon  seen nptype=4(ke)
default 21:39:53.335105+0100    racoon  seen nptype=10(nonce)
default 21:39:53.335179+0100    racoon  seen nptype=20(nat-d)
default 21:39:53.335263+0100    racoon  seen nptype=20(nat-d)
default 21:39:53.335395+0100    racoon  Hashing 192.168.1.46[500] with algo #4
default 21:39:53.335500+0100    racoon  NAT-D payload #0 doesn't match
default 21:39:53.335551+0100    racoon  Hashing 51.154.164.133[500] with algo #4
default 21:39:53.335650+0100    racoon  NAT-D payload #1 doesn't match
default 21:39:53.335726+0100    racoon  NAT detected: ME PEER
default 21:39:53.335791+0100    racoon  state changed to: IKEv1 ident I msg4 rcvd
default 21:39:53.388371+0100    racoon  added initial-contact payload.
default 21:39:53.389588+0100    racoon  Resend Phase 1 packet 6053c723b0e225a8:21fbfaa914120f33
default 21:39:53.389723+0100    racoon  state changed to: IKEv1 ident I msg5 sent
default 21:39:53.399147+0100    racoon  seen nptype=5(id)
default 21:39:53.399209+0100    racoon  seen nptype=8(hash)
default 21:39:53.399528+0100    racoon  state changed to: IKEv1 ident I msg6 rcvd
default 21:39:53.399712+0100    racoon  state changed to: Phase 1 Established
default 21:39:53.399787+0100    racoon  ISAKMP-SA established spi:6053c723b0e225a8:21fbfaa914120f33
default 21:39:53.399966+0100    racoon  IPSec Phase 1 established (Initiated by me).
default 21:39:54.229617+0100    racoon  initiate new phase 2 negotiation: 192.168.1.46[4500]<=>51.154.164.133[4500]
default 21:39:54.229767+0100    racoon  state changed to: IKEv1 quick I start
default 21:39:54.229914+0100    racoon  IPSec Phase 2 started (Initiated by me).
default 21:39:54.230504+0100    racoon  state changed to: IKEv1 quick I getspi sent
default 21:39:54.231086+0100    racoon  >>>>> phase change status = Phase 2 started
default 21:39:54.232083+0100    racoon  state changed to: IKEv1 quick I getspi done
default 21:39:54.232311+0100    racoon  NAT detected -> UDP encapsulation
default 21:39:54.238396+0100    racoon  Resend Phase 2 packet 6053c723b0e225a8:21fbfaa914120f33:000048f6
default 21:39:54.238620+0100    racoon  state changed to: IKEv1 quick I msg1 sent
default 21:39:54.268136+0100    racoon  seen nptype=8(hash)
default 21:39:54.268294+0100    racoon  seen nptype=1(sa)
default 21:39:54.268444+0100    racoon  seen nptype=10(nonce)
default 21:39:54.268593+0100    racoon  seen nptype=5(id)
default 21:39:54.268739+0100    racoon  seen nptype=5(id)
default 21:39:54.268913+0100    racoon  seen nptype=21(nat-oa)
default 21:39:54.269064+0100    racoon  seen nptype=21(nat-oa)
default 21:39:54.270126+0100    racoon  seen nptype=2(prop)
default 21:39:54.270716+0100    racoon  seen nptype=3(trns)
default 21:39:54.270864+0100    racoon  seen nptype=3(trns)
default 21:39:54.271145+0100    racoon  seen nptype=3(trns)
default 21:39:54.271342+0100    racoon  seen nptype=3(trns)
default 21:39:54.271507+0100    racoon  seen nptype=3(trns)
default 21:39:54.271749+0100    racoon  seen nptype=3(trns)
default 21:39:54.278681+0100    racoon  seen nptype=2(prop)
default 21:39:54.279242+0100    racoon  seen nptype=3(trns)
default 21:39:54.282515+0100    racoon  Adjusting my encmode UDP-Transport(4)->Transport(2)
default 21:39:54.282591+0100    racoon  Adjusting peer's encmode UDP-Transport(4)->Transport(2)
default 21:39:54.282943+0100    racoon  state changed to: IKEv1 quick I msg2 rcvd
default 21:39:54.285733+0100    racoon  state changed to: IKEv1 quick I addsa
default 21:39:54.286814+0100    racoon  IPsec-SA established (update): satype=3 spi=0x2901e7f mode=1
default 21:39:54.286977+0100    racoon  state changed to: Phase 2 established
default 21:39:54.287075+0100    racoon  ike_session_ph2_established: ph2 established, spid 22
default 21:39:54.287151+0100    racoon  IPSec Phase 2 established (Initiated by me).
default 21:39:54.287306+0100    racoon  IPsec-SA established (add): satype=3 spi=0xd19f343 mode=1
default 21:39:54.287547+0100    racoon  >>>>> phase change status = Phase 2 established

Best Answer

The VPN server in Catalina does not work.

There are two enabler apps that I know about:

iVPN says that the server in Catalina does not reliably accept connections and the solution is to wait for Apple to fix it (or use Mojave).

VPN Enabler also says that it does not work in Catalina and the author is trying to develop an easy to use OpenVPN server. In the meantime, use Mojave.

A different approach is to use a firewall product like pfSense running on another device or in a virtual machine and enable its VPN server capability. This is not an easy solution!