Starting `NEPacketTunnelProvider` very rarely gets stuck. How to debug?

Question

Hello,

I have successfully implemented NEPacketTunnelProvider network extension in iOS app which works fine most of the time.

By working fine I mean it starts, stops (it is configured to disconnect on sleep) and handles network traffic as expected.

However I have a few reports that sometimes it doesn't start correctly. It hangs on "Connecting..." when checking the Settings -> VPN.

As far as I can tell even with waiting for minutes, it seems still stuck.

Re-installing either the VPN provider extension or entire app fixes this problem.

What could be causing such random and very rare issues? This doesn't seem to be connected to single iOS version for example.

Network Extension

943

Posted by

nemecek_f

Reply

Add a Comment

Answer 1

What could be causing such random and very rare issues?

I would start by recording the logs in the Console.app when the issue is reproduced to see if they provide any more information. If you do find some interesting logs, please post them here and I can take a look.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

Posted by

meaton

Add a Comment

Answer 2

Finally (and unfortunately) managed to reproduce the issue. VPN stays in the "Connecting..." state indefinitely. It also does not help to try "re-starting" it in the settings. Even when I start tunnel from different app which works fine and attempt to start tunnel for my app, it again gets stuck at "Connecting"

Here are the logs. The bottom three messages keep repeating over and over again.

NESMVPNSession[Primary Tunnel:AppBlock Blocker:EC537A50-9463-4CAA-9A89-B67EE9316BDB:(null)]: status changed to connecting
NESMVPNSession[Primary Tunnel:AppBlock Blocker:EC537A50-9463-4CAA-9A89-B67EE9316BDB:(null)]: got On Demand start message from pid 117
NESMVPNSession[Primary Tunnel:AppBlock Blocker:EC537A50-9463-4CAA-9A89-B67EE9316BDB:(null)]: Received a start command from rapportd[89]
NESMVPNSession[Primary Tunnel:AppBlock Blocker:EC537A50-9463-4CAA-9A89-B67EE9316BDB:(null)]: Skip a start command from rapportd[89]: session in state connecting

Sometimes when "Connecting..." internet does not work at all on the device, sometimes it does

Posted by

nemecek_f

Add a Comment

Answer 3

Sometimes when "Connecting..." internet does not work at all on the device, sometimes it does

NESMVPNSession[Primary Tunnel:AppBlock Blocker:EC537A50-9463-4CAA-9A89-B67EE9316BDB:(null)]: got On Demand start message from pid 117

The tunnel will need an internet connection to at least get off the ground. I would also recommend removing the onDemandRules until you are able to track down what the underlying issue is. For example, sometimes these rules can match to continuously start the tunnel, but there is another condition on the system that is making it not function, like the internet. Decoupling these two things further should make this easier to track down.

Posted by

meaton

Add a Comment

Answer 4

Thanks.

From the above issue, the only way to resolve it is by:

Restarting the device
Deleting the VPN and installing it again
Re-install the entire app

Switching to different VPN does not help, which suggests to me that there is some wrong state that persists?

Posted by

nemecek_f

Add a Comment

Answer 5

which suggests to me that there is some wrong state that persists?

Building upon my previous response to remove your onDemandRules rules, what if you strip your NEPacketTunnelProvider down further into just a provider that starts the tunnel with a basic set of NEPacketTunnelNetworkSettings. It sound not even send traffic over the network, just starts the tunnel. In this situation, are you reliably able to keep the tunnel running? If not then it sounds like you may have an environment issue going on. If so, add some more functionality to your setup incrementally to see if you can narrow down what is causing this issue.

Posted by

meaton

Add a Comment

Starting `NEPacketTunnelProvider` very rarely gets stuck. How to debug?

Replies