VPN start fail (some devices, sometimes)

APP start VPN process code:

BOOL suc = [self.providerManager.connection startVPNTunnelWithOptions:options andReturnError:&startError];
 if (startError) {
  SLTunWarn(@"start tun error %@ %@", startError, startError.localizedDescription);
  SLAPPError *err = (SLAPPError *)[SLAPPError fromSystemError:startError];
  callback(err);
  return;
 }
 SLTunInfo(@"call startTunnelWithOptions success, start wait tun status");

startVPNTunnelWithOptions return success, and then the app log is

[TUN] system notify: [Disconnect]
[TUN] sys tun status [1]=>[2]
[TUN] system notify: [Connecting]
[TUN] system notify: [Connecting]
[TUN] system notify: [Connecting]
[TUN] sys tun status [2]=>[1]

can see that VPN state changed, from disconnect to connecting and finally disconnect

VPN Process Code:

- (instancetype)init
{
 self = [super init];
 if (self) {
  [[SLEGlobalData shared] onLaunch];
  NSLog(@"PacketTunnelProvider init");
  self.wormhole = [SLEWormhole shared];
 }
 NSLog(@"init end");
 return self;
}

the log "PacketTunnelProvider init" in init func shows, but not any other logs. So near certain startTunnelWithOptions not be called.

And app process did not receive any errors.

this problem occur occasionally。 Most of the time, VPN process start successfully.

So Any suggestions?

the log "PacketTunnelProvider init" in init func shows, but not any other logs. So near certain startTunnelWithOptions not be called.

this problem occur occasionally。 Most of the time, VPN process start successfully.

This typically means that there was an issue connecting or authenticating with your remote server, especially if this only happens some of the time. The other alternative would be a routing configuration issue on the device. I would check your server side logs first, if that all checks out then try setting your packet tunnel to claim the default route. If you start getting traffic then, I would look into routing issues on your tunnel.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

Could you tell me, what the program do between NEPacketTunnelProvider init and startTunnelWithOptions

Between the time the container app starts the connection for your VPN tunnel with startVPNTunnel, and then calls startTunnelWithOptions the OS registers, verifies, and loads the NEPacketTunnelProvider as an extension and then initiates it. After the initiation step, is when startTunnelWithOptions is called and your tunnel configures the routing settings.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

the full log is :

Nov 25 09:40:47 nesessionmanager[194] <Notice>: <NESMServer: 0x100a04550>: Register Enterprise VPN Session: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Successfully registered

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: status changed to connecting

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)] in state NESMVPNSessionStateIdle: received start message

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Leaving state NESMVPNSessionStateIdle

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Entering state NESMVPNSessionStatePreparingNetwork

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Leaving state NESMVPNSessionStatePreparingNetwork

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Entering state NESMVPNSessionStateStarting

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)] in state NESMVPNSessionStateStarting: plugin NEVPNTunnelPlugin(com.wangsu.securelink[inactive]) started with PID 0 error (null)

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Leaving state NESMVPNSessionStateStarting

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Entering state NESMVPNSessionStateStopping, timeout 20 seconds

Nov 25 09:40:47 nesessionmanager[194] <Notice>: <NESMServer: 0x100a04550>: Request to uninstall session: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: status changed to disconnecting

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Updated network agent (inactive, compulsory, not-user-activiated, not-kernel-activated)

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Leaving state NESMVPNSessionStateStopping

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Entering state NESMVPNSessionStateDisposing, timeout 5 seconds

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)] in state NESMVPNSessionStateDisposing: plugin NEVPNTunnelPlugin(com.wangsu.securelink[inactive]) dispose complete

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)] in state NESMVPNSessionStateDisposing: all plugins have disposed

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Leaving state NESMVPNSessionStateDisposing

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: Entering state NESMVPNSessionStateIdle

Nov 25 09:40:47 nesessionmanager[194] <Notice>: NESMVPNSession[Primary Tunnel:SecureLink:28390857-B967-4AC2-BEDC-8EC6198F0A43:(null)]: status changed to disconnected, last stop reason Plugin failed

The iOS version is 14.0.1, and most of the device has this problem is 14.0.1

And this the system log about VPN:

Nov 25 15:31:27 mediaserverd(AudioToolbox)[33] <Notice>: SSServerImp.cpp:1242:SystemSoundServerKillSoundsForPID: pid 361(PacketTunnelApp)
Nov 25 15:31:27 mediaserverd(AudioToolbox)[33] <Notice>: SSServerImp.cpp:1242:SystemSoundServerKillSoundsForPID: pid 361(PacketTunnelApp)
Nov 25 15:31:27 ReportCrash[352] <Notice>: osa_update: Pid 361 'PacketTunnelApp' CORPSE: Parsing KCData
Nov 25 15:31:27 osanalyticshelper(OSAnalytics)[283] <Notice>: Process PacketTunnelApp [361] killed by jetsam reason per-process-limit
Nov 25 15:31:27 ReportCrash[352] <Notice>: osa_update: Pid 361 'PacketTunnelApp' CORPSE: Extracting
Nov 25 15:31:27 ReportCrash[352] <Notice>: osa_update: Pid 361 'PacketTunnelApp' CORPSE: Capture Complete
Nov 25 15:31:27 ReportCrash[352] <Notice>: Formulating fatal report for corpse[361] PacketTunnelApp

Finally, I fix this problem. After delete some Third-party libraries and remove some unnecessary classes, The IPA from the testflight work find ( this bug won't show by debug mode or local install IPA) Could you tell me, is there any way to avoid this problem happen again( like how many OC classes in VPN process is safe, or should keep the VPN pack below a specific size)。

The IPA from the testflight work find ( this bug won't show by debug mode or local install IPA) Could you tell me, is there any way to avoid this problem happen again( like how many OC classes in VPN process is safe, or should keep the VPN pack below a specific size)。

Glad you were able to narrow down the issue. It sounds like you should start debugging what is happening in your 3rd party libraries as a first step.

For example:

Nov 25 15:31:27 mediaserverd(AudioToolbox)[33] : SSServerImp.cpp:1242:SystemSoundServerKillSoundsForPID: pid 361(PacketTunnelApp) Nov 25 15:31:27 mediaserverd(AudioToolbox)[33] : SSServerImp.cpp:1242:SystemSoundServerKillSoundsForPID: pid 361(PacketTunnelApp)

Are you by chance playing audio in your PacketTunnelApp? Did you mean to do this and is this being done from a 3rd party framework?

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

The term jetsam refers to an iOS subsystem that’s responsible for enforcing memory policy. For the basics, see Diagnosing Issues Using Crash Reports and Device Logs.

The term reason per-process-limit means that your provider exceeded its (very strict) memory limit. This limit isn’t officially documented but you can get a rough idea from this post.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

VPN start fail (some devices, sometimes)
 
 
Q