VPN not starting

Question

Created Mar ’21

Replies 4

Boosts 0

Views 1.1k

Participants 2

While working on a dev version of my custom macOS VPN (Network Extension, Packet Tunnel Provider), I had cases where the VPN was suppose to start, but it didn't.
It's configured with an on-demand rule to always connect, and also to be on the safe side, I called connection.startVPNTunnel()

From the Console logs I see the following:

myClientClient Saving configuration myClient example - myname_mfa.mynameaccount with existing signature {length = 20, bytes = 0x3be5a6633b963d04c5e0a226cccff4c83a799e14}
default 12:33:36.686853+0200 secd myClientClient[8416]/1#11 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-50 "query missing class name" (paramErr: error in user parameter list) UserInfo={numberOfErrorsDeep=0, NSDescription=query missing class name}
default 12:33:36.687705+0200 myClientClient MacOS error: -25304
default 12:33:36.690077+0200 myClientClient MacOS error: -25304
NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]: Received a start command from myClientClient[8416]
default 12:33:36.763724+0200 nesessionmanager Registering session NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]
default 12:33:36.764739+0200 nesessionmanager Received a com.apple.neconfigurationchanged notification with token 23
default 12:33:36.765486+0200 nesessionmanager Clearing E853F1E7-23BD-4F01-915B-65DCBB9D9AB8 from the loaded configurations
default 12:33:36.765604+0200 nesessionmanager Clearing 8A4A1803-C370-42A1-8758-35E3D4337959 from the loaded configurations
default 12:33:36.765717+0200 nesessionmanager Clearing 2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17 from the loaded configurations
nesessionmanager nw_network_agent_open_control_socket Successfully connected netagent socket 8
default 12:33:36.760869+0200 SystemUIServer Received a com.apple.neconfigurationchanged notification with token 48
default 12:33:36.790775+0200 neagent Looking for an extension with identifier com.myClientexample.mac.myClientClient.myClientClientExtension and extension point com.apple.networkextension.packet-tunnel
default 12:33:36.791728+0200 neagent [d <private>] <PKHost:0x7f9bc9c29fb0> Beginning discovery for flags: 0, point: com.apple.networkextension.packet-tunnel
default 12:33:36.794692+0200 pkd Waiting on thread <private> until Launch Services database seeding is complete.
default 12:33:36.783780+0200 nesessionmanager NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]: status changed to connecting
default 12:33:36.811018+0200 neagent [d <private>] <PKHost:0x7f9bc9c29fb0> Completed discovery. Final
of matches: 1
default 12:33:36.762607+0200 myClientClient startToggled
default 12:33:36.811362+0200 nesessionmanager com.myClientexample.mac.myClientClient[743]: disposing
default 12:33:36.811575+0200 nesessionmanager com.myClientexample.mac.myClientClient[743]: Tearing down agent connection
default 12:33:36.811641+0200 nesessionmanager NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]: Plugin is installed
default 12:33:36.763228+0200 myClientClient starting vpn tunnel
default 12:33:36.811729+0200 nesessionmanager NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]: Enabling VPN On Demand
default 12:33:36.811145+0200 neagent Found 1 extension(s) with identifier com.myClientexample.mac.myClientClient.myClientClientExtension and extension point com.apple.networkextension.packet-tunnel
default 12:33:36.813142+0200 nesessionmanager NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]: Matched no on demand rule
default 12:33:36.784619+0200 myClientClient vpnStatusDidChange: Connecting
default 12:33:36.784729+0200 myClientClient display Connecting
default 12:33:36.813445+0200 nesessionmanager NESMVPNSession[Primary Tunnel:myClient example - myname_mfa.mynameaccount:2A6C1B7D-19E8-4EF7-8872-C1D0F8899A17:(null)]: Matched on demand rule
action = connect
interfaceTypeMatch = any

And after that there is a very big amount of
"Received a start command from" and "Skip a start command from " (and I copied only part of the log), but the VPN stays at the 'connecting' phase.
Any idea what's causing it?
Can it happen also on the production version of my app? I never reproduced it at the Store version, but it's not always reproduces anyway..

Boost

Answer 1

roee84 OP

Mar ’21

The console output is attached (I can't edit the original question)

Console output

0

Answer 2

roee84 OP

Mar ’21

Another update - I just found this, which might be the same -
https://developer.apple.com/forums/thread/75118

0

Answer 3

Systems Engineer OP

Apple

Mar ’21

The only thing that sticks out to me here is the Invalid Item error code:

MacOS error: -25304default

Are you grabbing something out of the Keychain to perform authentication with and this is failing?

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

0

Answer 4

roee84 OP

Mar ’21

Are you grabbing something out of the Keychain to perform authentication with and this is failing?

No.
The scenario where it usually reproduces:

I'm trying to connect with some invalid code, so connection fails
Upon this failure I'm updating the VPN configuration (removing on-demand), and save it
After the saving completed, I'm waiting few seconds, entering a correct code and saving the VPN configuration again (and set on-demand). After the saving is completed, I'm trying to start the VPN.

Nothing from keychain here, and I did see the above MacOS error: -25304 error, but even with this error it was able to save the conf, and it did try to trigger the VPN (but then I got the log 'session in state connecting', see Console).

0