Packet Tunnel Provider can't connect for unknown time after system wake

Hi! We have a product which effectively is a VPN implemented as Packet Tunnel Provider. The one problem we have is strange enough to ask here for help. We have set the disconnectOnSleep to true for our NETunnelProviderProtocol instance, and we are manually reconnecting the tunnel from system did wake callback.

Here we have our problem: immediately in system wake callback(NSWorkspace.didWakeNotification), activation of tunnel fails almost always. It goes to connecting (NEVPNStatus), but just after that it goes to disconnecting, and stays disconnected after that.

I decided, that system just not ready to connect to the VPN right after wake. I've found no other callbacks, so the only decision was to add retry after a small delay. The retry after 1 second delay works fine for us on Big Sur.

Starting with macOS Monterey we have again reports about this problem from our users, now in the logs I can see that it can't reconnect after 1 second of delay, and then even after 5 seconds of delay!

It reconnects fine after some time later (seconds, not minutes), but it is definitely bad behaviour.

So I have questions:

  1. Is my understanding correct, and system can't reactivate VPN tunnel just in the didWake callback, so we need to wait some time?
  2. If (1) is true, how long we should wait? Is there any other callback from system, like "Hey, I'm ready now for VPN connections!"?
  3. If (1) is false, what could I do next to create stable user experience?
Answered by Systems Engineer in 705232022

This TSI was refunded back to your account today because the Bug Report (r. 88977168) you opened already had the correct response on it.

For those following along, your provider disconnected completely because disconnectOnSleep was set to true instead of false and this completely tears down the session.

If this does not solve the issue, please follow back up on your TSI and I will pick it up again.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

Disconnecting on sleep and reconnecting in wake from within the NEPacketTunnelProvider callbacks would be the right move here. Have you tried this instead of using didWakeNotification? The difference here is that these notifications are posted from the provider, where the VPN needs to perform the action from, instead of the container app.

If this does not work then there should be more information in the logs as to what is going wrong.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

Well, I've tried to do this, and I can't confirm that these callbacks are called.

My setup is:

  • macOS Big Sur 11.6.2, mac mini, I've set the Turn display off after 1 minute of inactivity, removed the check to prevent it from sleep in that case.

  • system network extension with Packet Tunnel Provider inside, based on wireguard opensource project

I've added just such lines:

override func sleep(completionHandler: @escaping () -> Void) {
        wg_log(.info, message: "Got sleep from provider")
        completionHandler()
    }

    override func wake() {
        wg_log(.info, message: "Got wake from provider")
    }

And I've never seen such logs after several sleep-wake retries. All other logs from this class are ok, I can see them.

Should I do anything else, except adding these lines to the class to subscribe the sleep/wake notifications?

I've recorded the Console logs, but there are a lot, and nothing I can see related to my issue. Could you please point, what am I looking for?

I can't confirm that these callbacks are called.

That is odd that these callbacks are not hit. This should be happening.

Regarding:

I've recorded the Console logs, but there are a lot

Are there problems in these logs with your provider when the coming out of sleep?

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

No, I can't see anything related after wake.

The nearest thing there before sleep:

NESMVPNSession[Primary Tunnel<my tunnel name>:65B27634-3EBB-403E-98C9-2335A141E5E8:(null)]: status changed to disconnected, last stop reason Device went to sleep

Filtering with my extension bundle id:

default	19:43:33.614140+0200	<my sysext bundle id>	[Extension <my app bundle id>]: Calling stopTunnelWithReason because: Device went to sleep
default	19:43:33.619170+0200	<my sysext bundle id>	container_create_or_lookup_app_group_path_by_app_group_identifier: success
default	19:43:33.619740+0200	<my sysext bundle id>	[Extension <my app bundle id>]: IPC detached
error	19:43:33.623168+0200	<my sysext bundle id>	SIOCGIFMTU failed: Device not configured
error	19:43:33.623229+0200	<my sysext bundle id>	NEVirtualInterfaceAdjustReadBufferSize: interface_get_mtu failed (6), defaulting to max mtu
default	19:43:33.623342+0200	<my sysext bundle id>	[Extension <my app bundle id>]: Session manager connection was invalidated
default	19:43:33.623400+0200	<my sysext bundle id>	[Extension <my app bundle id>]: Deallocating

After wake I can't find any related logs from nesession manager (there are some, but unrelated) or my sysext(there is nothing at all).

The process of my sysext is still running after wake, but just does nothing.

I'm able to manually activate the tunnel from System Preferences - General or from code, but no callbacks hit.

Should I file a bug about it?

My tunnel provider code now looks like:

class PacketTunnelProvider: NEPacketTunnelProvider {
...

override func sleep(completionHandler: @escaping () -> Void) {
        wg_log(.info, message: "Got sleep from provider")
        os_log(.default, "Got sleep from provider")
        completionHandler()
    }

    override func wake() {
        wg_log(.info, message: "Got wake from provider")
        os_log(.default, "Got wake from provider")
    }
}

That is odd. How are you testing this, are you closing the lid on your MacBook and then letting the machine go through the sleep cycle or are you letting the machine naturally go to sleep? Either way I would have thought would trigger this. If you get stuck here you can open a TSI and I can look into this further.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

I'm using mac mini, so I set the energy saver to go to sleep after display is turned off (1 minute), and I'm waiting for it to go to sleep.

I've checked, the manual sleep option (menu - Apple icon - sleep) gives me the same results.

I've created the ticket FB9906942 for now. I'm going to try some more things during this week, and in case it would not help, I'll open a TSI, thanks.

I've submitted a TSI with follow-up id 793923107

I've submitted a TSI with follow-up id 793923107

Thank you. I seen this come through the DTS queue today and and added it to my queue.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com
Accepted Answer

This TSI was refunded back to your account today because the Bug Report (r. 88977168) you opened already had the correct response on it.

For those following along, your provider disconnected completely because disconnectOnSleep was set to true instead of false and this completely tears down the session.

If this does not solve the issue, please follow back up on your TSI and I will pick it up again.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

Thanks Matt! I'll try again with disconnectOnSleep false and post here if it helps.

I can confirm that with disconnectOnSleep = false the sleep and wake callbacks are hit. Thanks!

Could this info be added somewhere in documentation, like here: https://developer.apple.com/documentation/networkextension/nevpnprotocol/1405983-disconnectonsleep or to the comments for wake/sleep methods of NEPacketTunnelProvider?

Packet Tunnel Provider can't connect for unknown time after system wake
 
 
Q