VPN issue: stuck in connecting state since 16.5 update

Question

monsino OP

Created Jun ’23

Replies 4

Boosts 0

Views 1.6k

Participants 5

Hello everyone,

we have reports of VPN issues on iOS devices after updating the OS version to 16.5. The VPN is stuck in connecting state and this applies to both WiFi and cellular interfaces. The users are not able to route the internet by any means.

From the provided sysdiagnose we have found out that our PacketTunnelProvider was initialized but the startTunnel method was never called. VPN is in the enabled state and should be launched by onDemand connect rules. We don't have steps to reproduce so it's quite hard to find what went wrong.

Some of the sysdiagnose's suspicious logs happening:

default	2023-06-05 11:19:49.737504 +0100	nesessionmanager	Received a network changed event
default	2023-06-05 11:19:49.738185 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Plugin is installed
default	2023-06-05 11:19:49.738219 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Enabling VPN On Demand
default	2023-06-05 11:19:49.738550 +0100	nesessionmanager	-[NESMVPNSession unsetDefaultDropAll]: VPN setting IP Drop-All to 0 (Non-Persistent)
default	2023-06-05 11:19:49.738636 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Handling a configuration changed event
default	2023-06-05 11:19:49.738641 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Resetting VPN On Demand 
...
default	2023-06-05 11:19:49.734220 +0100	UserEventAgent	File Handle Maintainer listening for readable events on Network Agent Registration socket (55) EFF7F93A-63FF-4248-9AE4-93B808D76FF8 6C71BB18-F1DE-4B10-B018-65891D0291A0 5 (null) agent flags 0x2
default	2023-06-05 11:19:49.734311 +0100	nesessionmanager	Found 0 (0 active) registrations for com.jamf.trust.ne-dnsPlus (com.apple.networkextension.packet-tunnel)
...
default	2023-06-05 11:19:51.312153 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: status changed to connecting
default	2023-06-05 11:19:51.313139 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Leaving state NESMVPNSessionStateIdle
default	2023-06-05 11:19:51.313153 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Entering state NESMVPNSessionStatePreparingNetwork
default	2023-06-05 11:19:51.313512 +0100	nesessionmanager	Found 0 (0 active) registrations for com.jamf.trust.ne-dnsPlus (com.apple.networkextension.packet-tunnel)
default	2023-06-05 11:19:51.313980 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Leaving state NESMVPNSessionStatePreparingNetwork
default	2023-06-05 11:19:51.313992 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Entering state NESMVPNSessionStateStarting, timeout 60 seconds
...
default	2023-06-05 14:47:46.895380 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Skip a start command from cloudd[129]: session in state connecting
default	2023-06-05 14:47:46.907613 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Skip a start command from cloudd[129]: session in state connecting
default	2023-06-05 14:47:47.043272 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Skip a start command from cloudd[129]: session in state connecting
default	2023-06-05 14:47:47.432713 +0100	nesessionmanager	NESMVPNSession[Primary Tunnel:Secure Access Layer:16F102D3-A4E9-4E00-9478-235298D3E83B:(null)]: Skip a start command from TunnelExtension[254]: session in state connecting

Has someone gotten into a similar VPN issue? I would be really grateful if someone has any suggestions or advice on how to fix this behavior. Thank you!

Answered by callmepali in 756973022

We have identified this issue to be present in 3rd party library included in our implementation rendering this post invalid.

This issue is resolved. Apologies.

Boost

Answer 1

YuanCan OP

Jun ’23

I have seen many similar situations on the forum, but there seems to be no solution。

0

Answer 2

Systems Engineer OP

Apple

Jun ’23

There's not a lot to go on here, so I think it would be best if you took a look at Quinn's post for Debugging a Network Extension Provider, this has a bunch of handy info on how to debug this further.

0

Answer 3

callmepali OP

Jun ’23

Hey everyone.

We have taken the advice and added logs from Quinn's post and we have submitted an issue in Feedback Assistant FB12354531 hopefully with everything needed. Normally we could see the init from start to finish would take less than a second. However in the scenario described in STRs below it would take several minutes (basically it would finish the init after unlocking the device for the first time), which lead to system never calling startTunnel.

It is only reproducible on devices with passcode set and what is more interesting is that having a SIM with PIN set would prevent this issue as well. Maybe some kind of network reset was happening after entering the PIN.

Steps to Reproduce:

have a device with iOS 16.5
have a device with custom VPN (NEPacketTunnelProvider)
device needs to have passcode set
turn device OFF
turn device ON
wait for at least 2-3 minutes before first unlock (the wait is crucial because unlocking the device immediately does not cause the issue)
unlock the device and see VPN stuck in connecting state

error	2023-06-15 10:44:07.728569 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] first light - start of init
error	2023-06-15 10:44:07.758136 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] End of init
error	2023-06-15 10:44:07.765028 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] startTunnel called
default	2023-06-15 10:48:21.506808 +0200	kernel	memorystatus_set_process_is_freezable: disabling freeze for pid 234 [DnsPlusTunnelExtension]
error	2023-06-15 10:48:21.564663 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] first light - start of init
error	2023-06-15 10:50:40.616033 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] End of init <- device was unlocked at this time
default	2023-06-15 10:52:05.028110 +0200	kernel	memorystatus_set_process_is_freezable: disabling freeze for pid 363 [DnsPlusTunnelExtension]
error	2023-06-15 10:52:05.053658 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] first light - start of init <- manually turning the VPN off
error	2023-06-15 10:52:05.095438 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] End of init
error	2023-06-15 10:52:05.107599 +0200	DnsPlusTunnelExtension	[DnsPlusTunnelExtension] startTunnel called

0

Answer 4

callmepali OP

Jun ’23

Accepted Answer

We have identified this issue to be present in 3rd party library included in our implementation rendering this post invalid.

This issue is resolved. Apologies.

1