NEPacketTunnelProvider: Problem with presence of framework

Question

Created Apr ’17

Replies 2

Boosts 0

Views 1.4k

Participants 2

In late 2015/early 2016 we were working on a Network Extension VPN (censorship circumvention tool) that was sort of working, but we coudn't get past the 5MB memory limit (rdar://27660401). We want to try it out again with the new memory limit, but we can't get it working even to the degree that it was before.

Here's the code: https://github.com/adam-p/psiphon-ios-PoC/tree/master/Psiphon

The really odd thing (to me) is that the problem seems to be presence of our framework in the network extension (PsiphonTunnel.framework in the above repo). ("Presence" because the same failure occurs even if all calls to the framework are removed. Fully removing the framework is necessary.)

Here's the framework source, in case it's relevant:

https://github.com/Psiphon-Labs/psiphon-tunnel-core/tree/ios-beta/MobileLibrary/iOS/PsiphonTunnel

"Allow app extension API only" is enabled for the framework, but doesn't seem to make a difference.

Here's some successful-er log output with the framework removed:

Apr  5 14:30:14 iPhone7 mediaserverd(AudioToolbox)[27] <Notice>: 879: aqmeio@0x10393e570, device 0xc0 (VirtualAudioDevice_Actuator), AudioDeviceStart (err 0)
Apr  5 14:30:15 iPhone7 Psiphon(libswiftFoundation.dylib)[453] <Notice>: startVPN: call targetManager.connection.startVPNTunnel()
Apr  5 14:30:15 iPhone7 Psiphon(libswiftFoundation.dylib)[453] <Notice>: startVPN: startVPNTunnel success
Apr  5 14:30:15 iPhone7 mediaserverd(AudioToolbox)[27] <Notice>: 79: client ID 0x1000035 state 1 => 2
Apr  5 14:30:15 iPhone7 SpringBoard(UIKit)[53] <Notice>: feedback engine <_UIFeedbackHapticEngine: 0x1704c1d50: state=3, numberOfClients=0, prewarmCount=0, _isSuspended=0> state changed: Activating -> Running
Apr  5 14:30:15 iPhone7 SpringBoard(AudioToolbox)[53] <Notice>: 431: clientID: 0x1000035
Apr  5 14:30:15 iPhone7 SpringBoard(UIKit)[53] <Notice>: feedback engine <_UIFeedbackHapticEngine: 0x1704c1d50: state=4, numberOfClients=0, prewarmCount=0, _isSuspended=0> state changed: Running -> Inactive
Apr  5 14:30:15 iPhone7 mediaserverd(AudioToolbox)[27] <Notice>: 79: client ID 0x1000035 state 2 => 1
Apr  5 14:30:15 iPhone7 nesessionmanager(NetworkExtension)[300] <Notice>: NESMVPNSession[Psiphon:E18074F8-614A-4DDF-826B-ED0E763E886A]: Received a start command from Psiphon[453]
Apr  5 14:30:15 iPhone7 mediaserverd(AudioToolbox)[27] <Notice>: 349: Stopping synth and clearing command list
Apr  5 14:30:15 iPhone7 mediaserverd(AudioToolbox)[27] <Notice>: 376: AQME device AQDefaultDevice: client stopping: <SynthNodeClient@0x1008c5408 mHaptic 0>; running count now 0
Apr  5 14:30:15 iPhone7 nesessionmanager(NetworkExtension)[300] <Notice>: NESMVPNSession[Psiphon:E18074F8-614A-4DDF-826B-ED0E763E886A]: status changed to connecting
Apr  5 14:30:15 iPhone7 mediaserverd(VirtualAudio)[27] <Notice>: 751: Client request to stop IO proc ID 0x1038227f0 on VAD 173.
Apr  5 14:30:15 iPhone7 mediaserverd(VirtualAudio)[27] <Notice>: 735: Stopping IO type 0 on AggregateDevice 146.
Apr  5 14:30:15 iPhone7 mediaserverd(CoreAudio)[27] <Notice>: HALS_IOContext.cpp:855:StopIOProcID:  HALS_IOContext::StopIOProcID: 150 Speaker (VAD [vdef] AggDev 1):
Apr  5 14:30:15 iPhone7 mediaserverd(CoreAudio)[27] <Notice>: HALS_IOContext.cpp:861:StopIOProcID:  HALS_IOContext::StopIOProcID: stopping 0x21 state: Prewarm: 0 Play: 1 State: Running IOProc 0x21: yes
Apr  5 14:30:15 iPhone7 mediaserverd(VirtualAudio)[27] <Notice>: 352: IOProc (AggregateDevice 146, IO type NonNullIOProc) running state is now not running.
Apr  5 14:30:15 iPhone7 mediaserverd(CoreMotion)[27] <Notice>: Stopping orientation detection.
Apr  5 14:30:15 iPhone7 configd(IPConfiguration)[32] <Notice>: siocprotodetach(pdp_ip0) failed, Resource busy (16)
Apr  5 14:30:15 iPhone7 kernel[0] <Notice>: SIOCPROTODETACH_IN6: pdp_ip3 error=6
Apr  5 14:30:15 iPhone7 neagent(Foundation)[301] <Notice>: calling plugIn beginUsing:
Apr  5 14:30:15 iPhone7 pkd[107] <Notice>: allowing host 301 <private> to use plug-in <private>(<private>) uuid=920DCC85-A160-4D2F-8F84-06FB94468B2F at <private>
Apr  5 14:30:15 iPhone7 configd[32] <Notice>: IPv6 over pdp_ip0 demoted: not primary for IPv4
Apr  5 14:30:15 iPhone7 configd[32] <Notice>: network changed
Apr  5 14:30:15 iPhone7 CommCenter[74] <Notice>: #I Flushing queued mms messages due to low memory warning
Apr  5 14:30:15 iPhone7 CommCenter[74] <Notice>: #I Flushing queued mms messages due to low memory warning
Apr  5 14:30:15 iPhone7 CommCenter[74] <Notice>: #I Flushing queued mms messages due to low memory warning
Apr  5 14:30:15 iPhone7 kernel(AppleEmbeddedAudio)[0] <Notice>: Speaker: off
Apr  5 14:30:15 iPhone7 kernel(AppleAE2Audio)[0] <Notice>: mca1: rx overflow
Apr  5 14:30:15 iPhone7 mediaserverd(VirtualAudio)[27] <Notice>: 751: Client request to stop IO proc ID 0x103889640 on VAD 192.
Apr  5 14:30:15 iPhone7 mediaserverd(VirtualAudio)[27] <Notice>: 735: Stopping IO type 0 on AggregateDevice 160.
Apr  5 14:30:15 iPhone7 mediaserverd(CoreAudio)[27] <Notice>: HALS_IOContext.cpp:855:StopIOProcID:  HALS_IOContext::StopIOProcID: 163 Actuator (VAD [vzzz] AggDev 4):
Apr  5 14:30:15 iPhone7 mediaserverd(CoreAudio)[27] <Notice>: HALS_IOContext.cpp:861:StopIOProcID:  HALS_IOContext::StopIOProcID: stopping 0x21 state: Prewarm: 0 Play: 1 State: Running IOProc 0x21: yes
Apr  5 14:30:15 iPhone7 mediaserverd(VirtualAudio)[27] <Notice>: 352: IOProc (AggregateDevice 160, IO type NonNullIOProc) running state is now not running.
Apr  5 14:30:15 iPhone7 CommCenter[74] <Notice>: #I Flushing queued mms messages due to low memory warning
Apr  5 14:30:15 iPhone7 CommCenter[74] <Notice>: #I Flushing queued mms messages due to low memory warning
Apr  5 14:30:15 iPhone7 amfid(Security)[136] <Notice>: could not enable test hierarchy: ApplePinningAllowTestCertsiPhoneApplicationSigning not true
Apr  5 14:30:15 iPhone7 securityd[96] <Notice>: cert[0]: SubjectCommonName =(leaf)[]> 0
Apr  5 14:30:15 iPhone7 securityd[96] <Notice>: cert[0]: CheckLeafMarkerOid =(leaf)[]> 0
Apr  5 14:30:15 iPhone7 securityd[96] <Notice>: cert[0]: IssuerCommonName =(path)[]> 0
Apr  5 14:30:15 iPhone7 amfid(Security)[136] <Notice>:  [leaf CheckLeafMarkerOid IssuerCommonName SubjectCommonName]
Apr  5 14:30:15 iPhone7 kernel(AppleEmbeddedAudio)[0] <Notice>: Actuator: off
Apr  5 14:30:15 iPhone7 neagent(Foundation)[301] <Notice>: completed calling plugIn beginUsing: for pid: 454
Apr  5 14:30:15 iPhone7 mediaserverd(CoreMedia)[27] <Notice>: -CMSessionMgr- cmsmHandleApplicationStateChange: CMSession: Client ca.psiphon.Psiphon.PsiphonVPN with pid '454' is now Foreground Running. Background entitlement: NO
Apr  5 14:30:15 iPhone7 PsiphonVPN(Foundation)[454] <Notice>: in _willPerformHostCallback: block
Apr  5 14:30:15 iPhone7 PsiphonVPN(libswiftFoundation.dylib)[454] <Notice>: startTunnelWithOptions called

And here's the same log neighbourhood with the framework present:

Apr  5 14:57:43 iPhone7 Psiphon(libswiftFoundation.dylib)[470] <Notice>: startVPN: call targetManager.connection.startVPNTunnel()
Apr  5 14:57:43 iPhone7 Psiphon(libswiftFoundation.dylib)[470] <Notice>: startVPN: startVPNTunnel success
Apr  5 14:57:43 iPhone7 nesessionmanager(NetworkExtension)[300] <Notice>: NESMVPNSession[Psiphon:9657EBFD-B5FC-476E-AB9A-6D046D8B4872]: Received a start command from Psiphon[470]
Apr  5 14:57:43 iPhone7 configd(IPConfiguration)[32] <Notice>: siocprotodetach(pdp_ip0) failed, Resource busy (16)
Apr  5 14:57:43 iPhone7 nesessionmanager(NetworkExtension)[300] <Notice>: NESMVPNSession[Psiphon:9657EBFD-B5FC-476E-AB9A-6D046D8B4872]: status changed to connecting
Apr  5 14:57:43 iPhone7 kernel[0] <Notice>: SIOCPROTODETACH_IN6: pdp_ip3 error=6
Apr  5 14:57:43 iPhone7 kernel(AppleEmbeddedAudio)[0] <Notice>: Actuator: off
Apr  5 14:57:43 iPhone7 configd[32] <Notice>: IPv6 over pdp_ip0 demoted: not primary for IPv4
Apr  5 14:57:43 iPhone7 configd[32] <Notice>: network changed
Apr  5 14:57:43 iPhone7 neagent(Foundation)[301] <Notice>: calling plugIn beginUsing:
Apr  5 14:57:43 iPhone7 pkd[107] <Notice>: allowing host 301 <private> to use plug-in <private>(<private>) uuid=ED479D0C-4128-4157-A940-D2B064A1371E at <private>
Apr  5 14:57:43 iPhone7 amfid(Security)[136] <Notice>: could not enable test hierarchy: ApplePinningAllowTestCertsiPhoneApplicationSigning not true
Apr  5 14:57:43 iPhone7 securityd[96] <Notice>: cert[0]: SubjectCommonName =(leaf)[]> 0
Apr  5 14:57:43 iPhone7 securityd[96] <Notice>: cert[0]: CheckLeafMarkerOid =(leaf)[]> 0
Apr  5 14:57:43 iPhone7 securityd[96] <Notice>: cert[0]: IssuerCommonName =(path)[]> 0
Apr  5 14:57:43 iPhone7 amfid(Security)[136] <Notice>:  [leaf CheckLeafMarkerOid IssuerCommonName SubjectCommonName]
Apr  5 14:57:43 iPhone7 neagent(PlugInKit)[301] <Notice>: connection to plug-in <private>(ED479D0C-4128-4157-A940-D2B064A1371E) lost
Apr  5 14:57:43 iPhone7 neagent(PlugInKit)[301] <Error>: Hub connection error Error Domain=NSCocoaErrorDomain Code=4097 "connection to service named ca.psiphon.Psiphon.PsiphonVPN" UserInfo={NSDebugDescription=connection to service named ca.psiphon.Psiphon.PsiphonVPN}
Apr  5 14:57:43 iPhone7 neagent(Foundation)[301] <Notice>: PlugInKit error in beginUsing:
Apr  5 14:57:43 iPhone7 neagent(NetworkExtension)[301] <Error>: Failed to start extension ca.psiphon.Psiphon.PsiphonVPN: Error Domain=NSCocoaErrorDomain Code=4097 "connection to service named ca.psiphon.Psiphon.PsiphonVPN" UserInfo={NSDebugDescription=connection to service named ca.psiphon.Psiphon.PsiphonVPN}
Apr  5 14:57:43 iPhone7 neagent(Foundation)[301] <Notice>: killing invalid plugIn
Apr  5 14:57:43 iPhone7 neagent(libxpc.dylib)[301] <Notice>: Could not signal service ca.psiphon.Psiphon.PsiphonVPN: 113: Could not find specified service
Apr  5 14:57:43 iPhone7 neagent(Foundation)[301] <Notice>: completed calling plugIn beginUsing: for pid: 0
Apr  5 14:57:43 iPhone7 nesessionmanager(NetworkExtension)[300] <Notice>: NESMVPNSession[Psiphon:9657EBFD-B5FC-476E-AB9A-6D046D8B4872]: status changed to disconnecting
Apr  5 14:57:43 iPhone7 nesessionmanager(NetworkExtension)[300] <Notice>: NESMVPNSession[Psiphon:9657EBFD-B5FC-476E-AB9A-6D046D8B4872]: status changed to disconnected, last stop reason Plugin failed

You can see in the error log that `startTunnelWithOptions` isn't even getting called.

Any suggestions would be greatly appreciated.

Adam Pritchard

Boost

Answer 1

DTS Engineer OP

Apple

Apr ’17

It seems likely that this is caused by a failure to launch in your app extension, possibly because the framework wasn’t found or possibly because of a code signing problem. Do you get a crash report for the app extension?

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

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

0

Answer 2

adamfromtoronto OP

Apr ’17

It turns out it was because there was still an x86-simulator slice in the framework. (Which there wouldn't have been if I'd followed the framework instructions... which I wrote.)

Thanks/sorry.

0