Can't start NE app-extension via startTunnelWithOptions:

I am implementing a custom SSL VPN App using NE and for some not well known reason I am not able to properly start my app-extension (NEPacketTunnelProvider) by invoking NETunnelProviderSession.startTunnelWithOptions: in the containing app. My device is running iOS 10.3.2 and I am using the latest XCode.


This is the interesting part of the log about the attempt to start the app-extension, but without success:


May 18 00:24:57 Robins-nest MyApp[526] <Notice>: Saving profile before attempting connection...
May 18 00:24:57 Robins-nest neagent(Foundation)[288] <Notice>: calling plugIn beginUsing:
May 18 00:24:57 Robins-nest pkd[137] <Notice>: allowing host 288 <private> to use plug-in <private>(<private>) uuid=D54BA293-CD8D-482A-AFE6-3BCBAF639397 at <private>
May 18 00:24:57 Robins-nest MyApp(NetworkExtension)[526] <Notice>: The configuration was not saved because it was unchanged from the previously saved version
May 18 00:24:57 Robins-nest nesessionmanager(NetworkExtension)[287] <Notice>: NESMVPNSession[host.com/host:A1454C48-6E12-4B11-860B-66B531F88CC6]: Received a start command from MyApp[526]
May 18 00:24:57 Robins-nest nesessionmanager(NetworkExtension)[287] <Notice>: NESMVPNSession[host.com/host:A1454C48-6E12-4B11-860B-66B531F88CC6]: status changed to connecting
May 18 00:24:57 Robins-nest neagent(PlugInKit)[288] <Notice>: connection to plug-in <private>(D54BA293-CD8D-482A-AFE6-3BCBAF639397) lost
May 18 00:24:57 Robins-nest neagent(PlugInKit)[288] <Error>: Hub connection error Error Domain=NSCocoaErrorDomain Code=4097 "connection to service named net.domain.cat.app.ext" UserInfo={NSDebugDescription=connection to service named net.domain.cat.app.ext}
May 18 00:24:57 Robins-nest neagent(Foundation)[288] <Notice>: PlugInKit error in beginUsing:
May 18 00:24:57 Robins-nest neagent(NetworkExtension)[288] <Error>: Failed to start extension net.domain.cat.app.ext: Error Domain=NSCocoaErrorDomain Code=4097 "connection to service named net.domain.cat.app.ext" UserInfo={NSDebugDescription=connection to service named net.domain.cat.app.ext}
May 18 00:24:57 Robins-nest neagent(Foundation)[288] <Notice>: killing invalid plugIn
May 18 00:24:57 Robins-nest neagent(libxpc.dylib)[288] <Notice>: Could not signal service net.domain.cat.app.ext: 113: Could not find specified service
May 18 00:24:57 Robins-nest neagent(Foundation)[288] <Notice>: completed calling plugIn beginUsing: for pid: 0


I know this is a problem that has been discussed in several threads already, however, I couldn't find any useful hint in any of them.


I checked the entitlements and NE seems to be properly setup in both the containing App and the app-extension.

The NETunnelProviderManager is loaded and then saved before attempting to start the tunnel.

What else could I check? Or is there any way to increase the verbosity of the neagent process in order to retrieve some more information?

Accepted Reply

Quinn,

I managed to make it work.

I restarted from scratch, with a clean project: just one simple provider and a class implementing the manager side. After some tweaking it worked. I then recreated the provider target on my original project (trying to make sure it had all the options set as the new one) and eventually it worked.


I think there are quite some building settings that can affect the provider and if something is screwed, then the provider just won't be found or won't load.

Anyway, now it seems to be working as expected and I can continue my development.


Thanks a lot for your time!

Replies

On iOS problems like this almost always boil down to one of two things.

Entitlements

You wrote:

I checked the entitlements and NE seems to be properly setup in both the containing App and the app-extension.

Did you check the entitlements of the built binaries or just the

.entitlements
file? You must check do the former, because that’s what the system looks at. The
.entitlements
file is just one input to the code signing machinery, as I explain in my Debugging Entitlement Issues post.

Info.plist

You should double check that your provider’s

Info.plist
is set up correctly. Specifically, check that the
NSExtension
property is set up like this:
<key>NSExtension</key>
<dict>
    <key>NSExtensionPointIdentifier</key>
    <string>com.apple.networkextension.packet-tunnel</string>
    <key>NSExtensionPrincipalClass</key>
    <string>Module.Provider</string>
</dict>

where:

  • Module
    is your Swift module name (if you’re using Objective-C, remove both the
    Module
    and the
    .
    )
  • Provider
    is the name of your NEPacketTunnelProvider subclass

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Hi eskimo and thanks for your answer! I thoroughfully followed your guide before opening this thread and I confirmed that the entitlements "within" the signed apps are ok. Specifically, this is the app-extension (provider):


<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-/
<plist version="1.0">
<dict>
  <key>application-identifier</key>
  <string>XXXXXXXX.net.domain.cat.app.ext</string>
  <key>com.apple.developer.networking.networkextension</key>
  <array>
  <string>app-proxy-provider</string>
  <string>content-filter-provider</string>
  <string>packet-tunnel-provider</string>
  </array>
  <key>com.apple.developer.team-identifier</key>
  <string>XXXXXXXX</string>
  <key>com.apple.networking.vpn.configuration</key>
  <array>
  <string>net.domain.cat.app.vpnplugin</string>
  </array>
  <key>get-task-allow</key>
  <true/>
</dict>
</plist>


I haven't found how to remove the old com.apple.networking.vpn.configuration entitlement yet (it does not appear in my entitlement file in XCode), but I am guessing it should not affect NE.


And this is the containing App:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-/
<plist version="1.0">
<dict>
  <key>application-identifier</key>
  <string>XXXXXXXX.net.domain.cat.app</string>
  <key>com.apple.developer.networking.networkextension</key>
  <array>
  <string>app-proxy-provider</string>
  <string>content-filter-provider</string>
  <string>packet-tunnel-provider</string>
  </array>
  <key>com.apple.developer.team-identifier</key>
  <string>XXXXXXXX</string>
  <key>com.apple.networking.vpn.configuration</key>
  <array>
  <string>net.domain.cat.app.vpnplugin</string>
  </array>
  <key>get-task-allow</key>
  <true/>
</dict>
</plist>


This is a snippet of the provider's Info.plist:

  <key>NSExtension</key>
  <dict>
  <key>NSExtensionPointIdentifier</key>
  <string>com.apple.networkextension.packet-tunnel</string>
  <key>NSExtensionPrincipalClass</key>
  <string>ProviderClassName</string>
  </dict>


(I am using Objective-C)

The

com.apple.networking.vpn.configuration
entitlement is coming from your provisioning profile. It means that at some point in the post your were granted access by Apple to the semi-private VPN plug-in mechanism. It sounds like you’re not using that any more, in which case it may make sense to remove it.

IMPORTANT I say “may” because it might also makes sense to keep it. If you have legacy VPN plug-in configurations deployed in the field, the presence of this entitlement will allow the system to migrate those configurations from your legacy VPN plug-in to your replacement Network Extension provider.

If you do want to remove this entitlement you can do so by:

  1. Enabling Network Extension on your App ID

  2. Creating a new provisioning profile based on that App ID

  3. Not enabling the template that adds the special entitlement to your profile

For more background on this whole issue Network Extension Framework Entitlements.

Notwithstanding all the above, you’re correct that the presence of

com.apple.networking.vpn.configuration
shouldn’t trigger this error. The log you posted clearly indicates that the system is trying to load your NE provider, not your legacy VPN plug-in.

Are you seeing any crash reports generated during the load attempt? That’s the next most common cause of a problem like this (that is, the system tries to load your provider but it either fails to load due to a dyld problem or crashes early during the load sequence).

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

You are correct, in the past we were using the private API and we are now migrating to NE. Thanks for your suggestion about the entitlement - I'll see what's best for our case and act accordingly.


Going back to the Provider issue: the only thing close to a crash that I can see in my device log is the following. It appears a few seconds after the log snippet I previously posted (not sure it is really related):


May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x10340d820> in call back event handler
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x10340d820> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888aea00 <redacted> + 116
  2   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  3   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  4   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  5   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  6   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  7   libdispatch.dylib                   0x00000001849d22cc <redacted> + 884
  8   libdispatch.dylib                   0x00000001849dea50 <redacted> + 540
  9   libdispatch.dylib                   0x00000001849de7d0 <redacted> + 124
  10  libsystem_pthread.dylib             0x0000000184bd7100 _pthread_wqthread + 1096
  11  libsystem_pthread.dylib             0x0000000184bd6<\M-b\M^@\M-&>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x10340d820> performing call back
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.syncdefaultsd.backgroundtask: SimpleTimer <PCSimpleTimer: 0x1002d1750> has fired
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.syncdefaultsd.backgroundtask: Invalidating simple timer <PCSimpleTimer: 0x1002d1750>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003a5060> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888acaac <redacted> + 292
  2   PersistentConnection                0x00000001888ad744 <redacted> + 268
  3   PersistentConnection                0x00000001888aebc8 <redacted> + 184
  4   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  5   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  6   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  7   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  8   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  9   libdispatch.dylib                   0x00000001849d22cc <redacted> + 884
  10  libdispatch.dylib                   0x00000001849dea50 <redacted> + 540
  11  libdispatch.dylib                   0x00000001849de7d0 <red<\M-b\M^@\M-&>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003a5060> dealloced
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x10340d820> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888acac8 <redacted> + 320
  2   PersistentConnection                0x00000001888ad744 <redacted> + 268
  3   PersistentConnection                0x00000001888aebc8 <redacted> + 184
  4   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  5   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  6   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  7   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  8   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  9   libdispatch.dylib                   0x00000001849d22cc <redacted> + 884
  10  libdispatch.dylib                   0x00000001849dea50 <redacted> + 540
  11  libdispatch.dylib                   0x00000001849de7d0 <red<\M-b\M^@\M-&>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x10340d820> performed call back on target <PCSimpleTimer: 0x1002d1750> selector _fireTimerFired
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: Disabling power monitoring for <PCSimpleTimer: 0x1002d1750> - 1 timers
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.syncdefaultsd.backgroundtask: Started simple timer <PCSimpleTimer: 0x100298c60> with fire date [2017-05-19 17:24:36 +0800]
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f9370> initialized with target <PCSimpleTimer: 0x100298c60> selector _preventSleepFired timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> initialized with target <PCSimpleTimer: 0x100298c60> selector _fireTimerFired timerSource <OS_dispatch_source: 0x1002b1fd0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.syncdefaultsd.backgroundtask: <PCSimpleTimer: 0x100298c60> created preventSleepTimer <PCDispatchTimer: 0x1003f9370> and fireTimer <PCDispatchTimer: 0x1002c9d00> on queue <OS_dispatch_queue: PCSimpleTimer-timerQ[0x1003a8830]>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> start with target <CUTWeakReference: 0x1002b1940> selector _fireTimerFired firetime 18446744073709551615 timerSource <OS_dispatch_source: 0x1002b1fd0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f9370> start with target <CUTWeakReference: 0x1003629d0> selector _preventSleepFired firetime 18446744073709551615 timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f9370> setFireDate 4001-01-01 00:00:00 +0000 and start with target <PCSimpleTimer: 0x100298c60> selector _preventSleepFired fireTime 18446744073709551615 deltaNanosec 2309-08-29 17:11:53 +0800 timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: Enabling power monitoring for <PCSimpleTimer: 0x100298c60> - 2 timers
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> setFireDate 2017-05-19 09:24:36 +0000 and start with target <PCSimpleTimer: 0x100298c60> selector _fireTimerFired fireTime 2138212295069 deltaNanosec 2017-05-19 17:24:36 +0800 timerSource <OS_dispatch_source: 0x1002b1fd0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> in call back event handler
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888aea00 <redacted> + 116
  2   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  3   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  4   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  5   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  6   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  7   libdispatch.dylib                   0x00000001849d22cc <redacted> + 884
  8   libdispatch.dylib                   0x00000001849dea50 <redacted> + 540
  9   libdispatch.dylib                   0x00000001849de7d0 <redacted> + 124
  10  libsystem_pthread.dylib             0x0000000184bd7100 _pthread_wqthread + 1096
  11  libsystem_pthread.dylib             0x0000000184bd6<\M-b\M^@\M-&>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> performing call back
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.syncdefaultsd.backgroundtask: SimpleTimer <PCSimpleTimer: 0x100298c60> has fired
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.syncdefaultsd.backgroundtask: Invalidating simple timer <PCSimpleTimer: 0x100298c60>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f9370> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888acaac <redacted> + 292
  2   PersistentConnection                0x00000001888ad744 <redacted> + 268
  3   PersistentConnection                0x00000001888aebc8 <redacted> + 184
  4   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  5   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  6   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  7   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  8   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  9   libdispatch.dylib                   0x00000001849d22cc <redacted> + 884
  10  libdispatch.dylib                   0x00000001849dea50 <redacted> + 540
  11  libdispatch.dylib                   0x00000001849de7d0 <red<\M-b\M^@\M-&>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f9370> dealloced
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x10340d820> dealloced
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888acac8 <redacted> + 320
  2   PersistentConnection                0x00000001888ad744 <redacted> + 268
  3   PersistentConnection                0x00000001888aebc8 <redacted> + 184
  4   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  5   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  6   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  7   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  8   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  9   libdispatch.dylib                   0x00000001849d22cc <redacted> + 884
  10  libdispatch.dylib                   0x00000001849dea50 <redacted> + 540
  11  libdispatch.dylib                   0x00000001849de7d0 <red<\M-b\M^@\M-&>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> performed call back on target <PCSimpleTimer: 0x100298c60> selector _fireTimerFired
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: Disabling power monitoring for <PCSimpleTimer: 0x100298c60> - 1 timers
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1002c9d00> dealloced
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.timed: Started simple timer <PCSimpleTimer: 0x1003f3960> with fire date [2017-05-19 17:39:05 +0800]
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x103417ae0> initialized with target <PCSimpleTimer: 0x1003f3960> selector _preventSleepFired timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003d04d0> initialized with target <PCSimpleTimer: 0x1003f3960> selector _fireTimerFired timerSource <OS_dispatch_source: 0x100391ac0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20] BTA-com.apple.timed: <PCSimpleTimer: 0x1003f3960> created preventSleepTimer <PCDispatchTimer: 0x103417ae0> and fireTimer <PCDispatchTimer: 0x1003d04d0> on queue <OS_dispatch_queue: PCSimpleTimer-timerQ[0x1003a8830]>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003d04d0> start with target <CUTWeakReference: 0x1003a0380> selector _fireTimerFired firetime 18446744073709551615 timerSource <OS_dispatch_source: 0x100391ac0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x103417ae0> start with target <CUTWeakReference: 0x10031feb0> selector _preventSleepFired firetime 18446744073709551615 timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: Enabling power monitoring for <PCSimpleTimer: 0x1003f3960> - 2 timers
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x103417ae0> setFireDate 4001-01-01 00:00:00 +0000 and start with target <PCSimpleTimer: 0x1003f3960> selector _preventSleepFired fireTime 18446744073709551615 deltaNanosec 2309-08-29 17:11:53 +0800 timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:24:36 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:24:36 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003d04d0> setFireDate 2017-05-19 09:39:05 +0000 and start with target <PCSimpleTimer: 0x1003f3960> selector _fireTimerFired fireTime 2159065140141 deltaNanosec 2017-05-19 17:39:05 +0800 timerSource <OS_dispatch_source: 0x100391ac0>


I don't see NE mentioned anywhere - maybe this is just a crash happening at a lower layer ?

There is another similar log some time later:

May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20] BTA-com.apple.timed: Invalidating simple timer <PCSimpleTimer: 0x1003f3960>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x103417ae0> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888acaac <redacted> + 292
  2   com.apple.BackgroundTaskAgentPlugin 0x0000000100763b68 com.apple.BackgroundTaskAgentPlugin + 15208
  3   com.apple.BackgroundTaskAgentPlugin 0x0000000100762dbc com.apple.BackgroundTaskAgentPlugin + 11708
  4   com.apple.BackgroundTaskAgentPlugin 0x00000001007629a8 com.apple.BackgroundTaskAgentPlugin + 10664
  5   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  6   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  7   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  8   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  9   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  10  libdispatch.dylib                   0x00000001849d22cc <\M-b\M^@\M-&>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x103417ae0> dealloced
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003d04d0> is invalidated
Callstack (
  0   PersistentConnection                0x00000001888af0cc <redacted> + 116
  1   PersistentConnection                0x00000001888acac8 <redacted> + 320
  2   com.apple.BackgroundTaskAgentPlugin 0x0000000100763b68 com.apple.BackgroundTaskAgentPlugin + 15208
  3   com.apple.BackgroundTaskAgentPlugin 0x0000000100762dbc com.apple.BackgroundTaskAgentPlugin + 11708
  4   com.apple.BackgroundTaskAgentPlugin 0x00000001007629a8 com.apple.BackgroundTaskAgentPlugin + 10664
  5   libdispatch.dylib                   0x00000001849ce9a0 <redacted> + 16
  6   libdispatch.dylib                   0x00000001849db604 <redacted> + 448
  7   libdispatch.dylib                   0x00000001849e7c1c <redacted> + 204
  8   libdispatch.dylib                   0x00000001849d08a0 <redacted> + 804
  9   libdispatch.dylib                   0x00000001849dc964 <redacted> + 560
  10  libdispatch.dylib                   0x00000001849d22cc <\M-b\M^@\M-&>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003d04d0> dealloced
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20] BTA-com.apple.timed: Started simple timer <PCSimpleTimer: 0x10028b9f0> with fire date [2017-05-19 17:39:05 +0800]
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: Disabling power monitoring for <PCSimpleTimer: 0x1003f3960> - 1 timers
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1034181e0> initialized with target <PCSimpleTimer: 0x10028b9f0> selector _preventSleepFired timerSource <OS_dispatch_source: 0x100391ac0>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f6830> initialized with target <PCSimpleTimer: 0x10028b9f0> selector _fireTimerFired timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20] BTA-com.apple.timed: <PCSimpleTimer: 0x10028b9f0> created preventSleepTimer <PCDispatchTimer: 0x1034181e0> and fireTimer <PCDispatchTimer: 0x1003f6830> on queue <OS_dispatch_queue: PCSimpleTimer-timerQ[0x1003a8830]>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f6830> start with target <CUTWeakReference: 0x1003e9980> selector _fireTimerFired firetime 18446744073709551615 timerSource <OS_dispatch_source: 0x1034051e0>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1034181e0> start with target <CUTWeakReference: 0x1003a2e50> selector _preventSleepFired firetime 18446744073709551615 timerSource <OS_dispatch_source: 0x100391ac0>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: Enabling power monitoring for <PCSimpleTimer: 0x10028b9f0> - 2 timers
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1034181e0> setFireDate 4001-01-01 00:00:00 +0000 and start with target <PCSimpleTimer: 0x10028b9f0> selector _preventSleepFired fireTime 18446744073709551615 deltaNanosec 2309-08-29 17:13:57 +0800 timerSource <OS_dispatch_source: 0x100391ac0>
May 19 17:26:40 Robins-nest UserEventAgent(PersistentConnection)[20] <Notice>: 2017-05-19 17:26:40 +0800 UserEventAgent[20]: <PCDispatchTimer: 0x1003f6830> setFireDate 2017-05-19 09:39:05 +0000 and start with target <PCSimpleTimer: 0x10028b9f0> selector _fireTimerFired fireTime 2159065188970 deltaNanosec 2017-05-19 17:39:05 +0800 timerSource <OS_dispatch_source: 0x1034051e0>



What do you think?

Thanks a lot for the great help so far.


EDIT:

this piece of log does not appear everytime I try to start the plugin therefore I think it is totally unrelated.

this piece of log does not appear everytime I try to start the plugin therefore I think it is totally unrelated.

Right.

I’m not sure what’s causing the failure your seeing. The next step would be to enable deeper VPN logging to see if that turns up anything. There’s info on doing that on our Bug Reporting > Profiles and Logs page.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

WWDC runs Mon, 5 Jun through to Fri, 9 Jun. During that time all of DTS will be at the conference, helping folks out face-to-face. http://developer.apple.com/wwdc/

I have tried that last week, but I did not see anything else other than the messages I posted already.

Anyway, I'll try once again, in case I missed something.


As a side note: do I need to enable the "App Groups" capability as well in order to allow manager and provider to talk to each other?


Thanks!


EDIT:

I take this back. App Groups does not seem to be needed.

Unfortunately even the log extracted with sysdiagnose is not able to reveal much more. Actually the snippet of log around the plugin error is exactly the same. There are some more messages during the preparation phase, but when pluginkit kicks in the messages are exacly the same as before.

Quinn, any chance I can send you a PM? I don't want to flood this thread with log files.

I take this back. App Groups does not seem to be needed.

Correct.

Quinn, any chance I can send you a PM?

DevForums does not support personal messages, alas.

That probably wouldn’t help much anyway; there’s a limit to how much time I can spend investigating stuff in the context of DevForums. I recommend that you open a DTS tech support incident so I can look at your issue in depth.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

WWDC runs Mon, 5 Jun through to Fri, 9 Jun. During that time all of DTS will be at the conference, helping folks out face-to-face. http://developer.apple.com/wwdc/

Quinn,

I managed to make it work.

I restarted from scratch, with a clean project: just one simple provider and a class implementing the manager side. After some tweaking it worked. I then recreated the provider target on my original project (trying to make sure it had all the options set as the new one) and eventually it worked.


I think there are quite some building settings that can affect the provider and if something is screwed, then the provider just won't be found or won't load.

Anyway, now it seems to be working as expected and I can continue my development.


Thanks a lot for your time!