Network Extension Calling stop completion handler with error (null)

1 info 2020-12-03 11:17:07.114964 -0500 nesessionmanager NESMVPNSession[Primary Tunnel:Connect:966CA0C0-ADD2-4AD8-B179-A331B23C718F:(null)]: timed out while waiting for network configuration to change (pending flags = 0x2)

2 default 2020-12-03 11:17:07.115413 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel [Extension com.weavernetworks.sdvn.Wire42]: Calling stopTunnelWithReason because: Stop command received

3 info 2020-12-03 11:17:07.115415 -0500 nesessionmanager NESMVPNSession[Primary Tunnel:Connect:966CA0C0-ADD2-4AD8-B179-A331B23C718F:(null)]: Request to clear network agent from all interfaces

4 default 2020-12-03 11:17:07.115484 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel vtc Stop tunnel is getting called!!!

5 info 2020-12-03 11:17:07.115516 -0500 configd NetBIOS name (network configuration) = USER-MACBOOK

6 default 2020-12-03 11:17:07.115530 -0500 nesessionmanager nwnetworkagentremovefrominterface Successfully removed agent from "utun2"

7 info 2020-12-03 11:17:07.115571 -0500 nesessionmanager NESMVPNSession[Primary Tunnel:Connect:966CA0C0-ADD2-4AD8-B179-A331B23C718F:(null)]: Removed network agent from utun2

8 default 2020-12-03 11:17:07.115582 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel [C1 FAE1F1AF-2EF1-4825-97AF-B2D448C23F02 100.64.0.100:1234 udp] cancel

9 info 2020-12-03 11:17:07.115621 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel <comweavernetworkssdvnWire42PacketTunnel.PacketTunnelProvider: 0x7f7fd0d0deb0>: Stopping with reason 1

10 default 2020-12-03 11:17:07.115634 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel [Extension com.weavernetworks.sdvn.Wire42]: IPC detached

11 default 2020-12-03 11:17:07.115662 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel [C1 FAE1F1AF-2EF1-4825-97AF-B2D448C23F02 100.64.0.100:1234 udp] cancelled

12 [C1 75908BA5-85B7-47D5-B854-5C249EEF695F 192.168.1.18:57672<->100.64.0.100:1234]

13 Connected Path: satisfied (Path is satisfied), viable, interface: en0, scoped, ipv4, ipv6, dns

14 Duration: 82.844s, UDP @0.001s took 0.000s

15 bytes in/out: 0/0, packets in/out: 0/0, rtt: 0.000s, retransmitted bytes: 0, out-of-order bytes: 0

16 info 2020-12-03 11:17:07.115677 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel [Extension com.weavernetworks.sdvn.Wire42]: Calling stop completion handler with error (null)

17 info 2020-12-03 11:17:07.115725 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel nwendpointhandlercancel [C1 100.64.0.100:1234 ready socket-flow (satisfied (Path is satisfied), viable, interface: en0, scoped, ipv4, ipv6, dns)]

18 info 2020-12-03 11:17:07.115740 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel nwassociationscheduledeactivation <nwassociation 100.64.0.100:1234> will become dormant after 10 seconds of inactivity

19 default 2020-12-03 11:17:07.115746 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel nwflowdisconnected [C1 100.64.0.100:1234 cancelled socket-flow ((null))] Output protocol disconnected

20 default 2020-12-03 11:17:07.115756 -0500 com.weavernetworks.sdvn.Wire42.PacketTunnel nwconnectionreportstatewithhandleronnwqueue [C1] reporting state cancelled

21 default 2020-12-03 11:17:07.115885 -0500 nesessionmanager NESMVPNSession[Primary Tunnel:Connect:966CA0C0-ADD2-4AD8-B179-A331B23C718F:(null)] in state NESMVPNSessionStateStopping: plugin NEVPNTunnelPlugin(com.weavernetworks.sdvn.Wire42[inactive]) did detach from IPC

22 info 2020-12-03 11:17:07.115899 -0500 UserEventAgent File Handle Maintainer got a 2 action with token 703

23 info 2020-12-03 11:17:07.115906 -0500 UserEventAgent File Handle Maintainer got a 1 action with token 704

24 default 2020-12-03 11:17:07.115938 -0500 nesessionmanager NESMVPNSession[Primary Tunnel:Connect:966CA0C0-ADD2-4AD8-B179-A331B23C718F:(null)] in state NESMVPNSessionStateStopping: plugin NEVPNTunnelPlugin(com.weavernetworks.sdvn.Wire42[inactive]) disconnected with reason Plugin initiated

25 default 2020-12-03 11:17:07.115967 -0500 nesessionmanager NESMVPNSession[Primary Tunnel:Connect:966CA0C0-ADD2-4AD8-B179-A331B23C718F:(null)] in state NESMVPNSessionStateStopping: plugin disconnected, disposing all plugins

26 default 2020-12-03 11:17:07.116024 -0500 UserEventAgent Current file handles for com.apple.networkextension.file-descriptor-maintainer: (

27 "Network Agent Registration socket (174) 966CA0C0-ADD2-4AD8-B179-A331B23C718F 9DC96782-8243-4C07-99E7-405986D6DAFF 1 (null) agent flags 0",

28 "Policy Session MasterSession socket (199)",

29 "Policy Session LowPrioritySession socket (200)"

30 )

1293 default 2020-12-03 11:17:13.298505 -0500 Connect vtc Replacing extension com.weavernetworks.sdvn.Wire42.PacketTunnel version 4.2.0 with version 4.2.0

1294 default 2020-12-03 11:17:13.298615 -0500 sysextd attempting to realize properties with identifier com.weavernetworks.sdvn.Wire42.PacketTunnel

1295 default 2020-12-03 11:17:13.303921 -0500 sysextd Realizing target path: file:///Applications/Connect.app/Contents/Library/SystemExtensions/com.weavernetworks.sdvn.Wire42.PacketTunnel.systemextension/

1296 default 2020-12-03 11:17:13.304131 -0500 sysextd Bundle class: UncachedBundle

1297 default 2020-12-03 11:17:13.315362 -0500 sysextd staging extension with identifier com.weavernetworks.sdvn.Wire42.PacketTunnel

1298 default 2020-12-03 11:17:13.318556 -0500 sysextd staging bundle from /Applications/Connect.app/Contents/Library/SystemExtensions/com.weavernetworks.sdvn.Wire42.PacketTunnel.systemextension to: /Library/SystemExtensions/.staging/A77F31CE-435B-4E24-9714-E5743DA97498/ com. weavernetworks.sdvn.Wire42.PacketTunnel.systemextension

1299 info 2020-12-03 11:17:13.342587 -0500 thermald 72/22/22 SFI:67/67/67/0/0/0 GPU:0/0/0/0 IO:0/0/0/0

1300 default 2020-12-03 11:17:13.360719 -0500 distnoted register name: NSSnappingPrefsDidChangeNotificationNameGlobal object: kCFNotificationAnyObject token: 380000003e pid: 4475

1301 default 2020-12-03 11:17:13.369913 -0500 sysextd Making activation decision for extension with teamID teamID("897HPDQQM3"), identifier com.weavernetworks.sdvn.Wire42.PacketTunnel

1302 default 2020-12-03 11:17:13.369915 -0500 sysextd No extension policy -- activation decision is UserOption

1303 default 2020-12-03 11:17:13.369919 -0500 sysextd validating extension with identifier com.weavernetworks.sdvn.Wire42.PacketTunnel

1304 info 2020-12-03 11:17:13.382958 -0500 syspolicyd looking up ticket: {length = 20, bytes = 0xc71b48e250f55c9df1a1f3f331f8431951ca8b94}, 2, 0

1305 info 2020-12-03 11:17:13.384175 -0500 syspolicyd completing lookup: {length = 20, bytes = 0xc71b48e250f55c9df1a1f3f331f8431951ca8b94}, 0

1306 info 2020-12-03 11:17:13.402132 -0500 sysextd Returning cdhash for local arch x8664 of extension com.weavernetworks.sdvn.Wire42.PacketTunnel

1307 default 2020-12-03 11:17:13.402256 -0500 sysextd waiting for external validation of extension with identifier com.weavernetworks.sdvn.Wire42.PacketTunnel

1308 default 2020-12-03 11:17:13.402395 -0500 nesessionmanager Validating system extension com.weavernetworks.sdvn.Wire42.PacketTunnel

1309 info 2020-12-03 11:17:13.421921 -0500 sysextd moving bundle to: /Library/SystemExtensions/A77F31CE-435B-4E24-9714-E5743DA97498/com.weavernetworks.sdvn.Wire42.PacketTunnel.systemextension

1310 default 2020-12-03 11:17:13.423835 -0500 sysextd Upgrading extension com.weavernetworks.sdvn.Wire42.PacketTunnel/teamID("897HPDQQM3") version 00240 (activatedenabled) to version 00240

1311 default 2020-12-03 11:17:13.424995 -0500 sysextd Starting upgrade of com.weavernetworks.sdvn.Wire42.PacketTunnel/teamID("897HPDQQM3") version 00240

1312 default 2020-12-03 11:17:13.425005 -0500 sysextd Notifying delegates about replacement of com.weavernetworks.sdvn.Wire42.PacketTunnel

1313 info 2020-12-03 11:17:13.425074 -0500 sysextd Returning cdhash for local arch x8664 of extension com.weavernetworks.sdvn.Wire42.PacketTunnel

1314 info 2020-12-03 11:17:13.425096 -0500 sysextd Returning cdhash for local arch x8664 of extension com.weavernetworks.sdvn.Wire42.PacketTunnel

1315 default 2020-12-03 11:17:13.425501 -0500 nesessionmanager Replacing system extension com.weavernetworks.sdvn.Wire42.PacketTunnel 4.2.0/00240 with extension com.weavernetworks.sdvn.Wire42.PacketTunnel 4.2.0/00240

1316 default 2020-12-03 11:17:13.425586 -0500 sysextd Starting disable of com.weavernetworks.sdvn.Wire42.PacketTunnel/teamID("897HPDQQM3") version 00240 for upgrade, state: activatedenabled

1317 default 2020-12-03 11:17:13.426706 -0500 sysextd clearing +x bit on executable in bundle file:///Library/SystemExtensions/360B2B64-3AF3-4D6B-8FDF-CD24C11A0D7E/com.weavernetworks.sdvn.Wire42.PacketTunnel.systemextension/

1318 default 2020-12-03 11:17:13.427004 -0500 sysextd notifying categories that extension com.weavernetworks.sdvn.Wire42.PacketTunnel will terminate

1319 info 2020-12-03 11:17:13.427072 -0500 sysextd Returning cdhash for local arch x8664 of extension com.weavernetworks.sdvn.Wire42.PacketTunnel

1320 default 2020-12-03 11:17:13.427344 -0500 nesessionmanager System extension com.weavernetworks.sdvn.Wire42.PacketTunnel will be terminated

My VPN app system extension gets replaced every time when VPN app is restarted.

It looks like you installing a new Network System Extension each time via OSSystemExtensionRequest.activationRequest.

via:

Code Block 
1297 default 2020-12-03 11:17:13.315362 -0500 sysextd staging extension with identifier com.weavernetworks.sdvn.Wire42.PacketTunnel
1301 default 2020-12-03 11:17:13.369913 -0500 sysextd Making activation decision for extension with teamID teamID("897HPDQQM3"), identifier com.weavernetworks.sdvn.Wire42.PacketTunnel
1315 default 2020-12-03 11:17:13.425501 -0500 nesessionmanager Replacing system extension com.weavernetworks.sdvn.Wire42.PacketTunnel 4.2.0/00240 with extension com.weavernetworks.sdvn.Wire42.PacketTunnel 4.2.0/00240

If you have a Packet Tunnel Network System Extension installed already are you able to NETunnelProviderManager.loadAllFromPreferences and call startVPNTunnel on NEVPNConnection again to get the System Extension up and running? Do you see this call hit startTunnel?


Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

Thanks Matt for your response. I do call ActivationRequest everytime our VPN app is started. I am following same as SimpleFirewall example from WWDC 2019
https://docs-assets.developer.apple.com/published/f74706e42c/FilteringNetworkTraffic.zip.

Let me check whether it can be handled differently. Thanks