Tips on debugging a non-functional NEFilterPacketProvider?

I have been implementing a NEFilterPacketProvider to be used as part of a system extension and running into a problem that I find highly bewildering.

The packet handler function just never gets called for one of my VMs while it gets called just fine in another VM. They both have the exact same MDM profile installed that pre-authorizes the activation of the sysx and network filters.

I have looked at every instance of this problem online and tried every single one of the tips I've read. I've made sure to set filterPacket = true. I ensured that my NEFilterPacketProvider is getting initialized and startFilter() gets called. I ensured that I am calling the completionHandler in startFilter. I ensured there are proper entitlements. I have tried implementations in both Swift and Objective-C. Nothing seems to make a difference.

The data provider gets called reliably and consistently.

Since this is working just fine in one of my VMs, I am quite confident the code is correct.

My question is this: what are some tips to systematically debug this issue? If you were me, where would you start looking at this?

Are there some command line tools that I can use to inspect the state of the network extension or macOS's state regarding them? scutil --nc list doesn't show anything (I assume because NEFilterPacketProvider isn't a proxy). What are some other commands I can use to really poke at network extensions?

I've looked at Console logs for sysextd and neagent and nothing stands out as an explanation.

I would love to know why the packet handler isn't getting called!

Up vote post of kn-cs Down vote post of kn-cs
1.1k views
Posted by
kn-cs
Reply
Add a Comment

Replies

My question is this: what are some tips to systematically debug this issue? If you were me, where would you start looking at this?

I would use the os_log API as much as possible here to try and identify where the breakdown was. I would also try and install the (VPN (Network Extension) for macOS) debug profile and capture the system logs of your device by trying to start the provider to see what is emitted here. This may give you some more detail than what you are seeing currently.

Also, make sure that you are adding overrides for init and stopFiler:

class FilterPacketProvider: NEFilterPacketProvider {
    
    static let log = OSLog(subsystem: "com.apple.test.simplefirewall.extension", category: "packet_provider")
    private let log: OSLog
    
    override init() {
        self.log = Self.log
        os_log(.debug, log: self.log, "init")
        super.init()
    }

    override func startFilter(completionHandler: @escaping (Error?) -> Void) {

    	// ...
    	let errDescription = error.localizedDescription ?? "No Error"
        os_log(.debug, log: self.log, "startFilter %{public}@", errDescription)
        
        completionHandler(nil)
    }
    
    override func stopFilter(with reason: NEProviderStopReason, completionHandler: @escaping () -> Void) {
        os_log(.debug, log: self.log, "stopFilter with reason: %d", reason)
        
        completionHandler()
    }
}

Because if your provider is crashing then init, stopFilter, and startFilter will get hit over and over as the system restarts it.

Regarding:

Are there some command line tools that I can use to inspect the state of the network extension or macOS's state regarding them?

scutil --nc is my go to Terminal utility here

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com
Posted by
meaton
Up vote reply of meaton Down vote reply of meaton
Add a Comment

Thank you!

I have enabled greater logging and still don't see what could be causing this. I am seeing the init and startFilter happening only once and there are no crash logs generated.

scutil --nc list is not showing anything.

Posted by
kn-cs
Up vote reply of kn-cs Down vote reply of kn-cs
Add a Comment

I see logs like:

nesessionmanager	Found 1 (1 active) registrations for com.company.name.Agent (com.apple.networkextension.filter-packet)
nesessionmanager	NESMFilterSession[AppName:172E3B4C-7A2C-4371-8355-97B653A32390]: Plugin NEFilterPlugin(com.company.appname.App[inactive]) requested a packet filter channel
nesessionmanager	NESMFilterSession[AppName:172E3B4C-7A2C-4371-8355-97B653A32390] in state NESMFilterSessionStateStarting: plugin NEFilterPlugin(com.company.appname.App[inactive]) status changed to running
nesessionmanager	<NESMServer: 0x7fcd2850a0f0>: Request to install session: NESMFilterSession[AppName:172E3B4C-7A2C-4371-8355-97B653A32390] (exclusive)
nesessionmanager	NESMFilterSession[AppName:172E3B4C-7A2C-4371-8355-97B653A32390]: status changed to connected
nesessionmanager	NESMFilterSession[AppName:172E3B4C-7A2C-4371-8355-97B653A32390]: Updated network agent (active, compulsory, not-user-activiated, not-kernel-activated)

Any other log lines I should look for to identify the cause of this problem? By the way, the VM has macOS 11.5 (20G71) on it.

Posted by
kn-cs
Up vote reply of kn-cs Down vote reply of kn-cs
Add a Comment

Any other log lines I should look for to identify the cause of this problem? I am seeing the init and startFilter happening only once and there are no crash logs generated. I am seeing the init and startFilter happening only once and there are no crash logs generated.

Okay, if you see your init and startFilter calls being hit then that is good. What do you get from your packetHandler if you add them in like so:

packetHandler = { (context, interface, direction, packetBytes, packetLength) in
    // Analyze packet
    return .allow
}

Or Objective-C:

self.packetHandler= ^NEFilterPacketProviderVerdict(NEFilterPacketContext * context,
                                                   _Nonnull nw_interface_t interface,
                                                   NETrafficDirection direction,
                                                   const void * packetBytes,
                                                   const size_t packetLength) {
    
    // Analyze packet
    
    return NEFilterPacketProviderVerdictAllow;
};

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com
Posted by
meaton
Up vote reply of meaton Down vote reply of meaton
Add a Comment

So when I use a packetHandler as one you gave, it still doesn't get called. I added a logging statement within it and it never fires.

Is there a known issue with NEFilterPacketProvider and Parallels VMs? Our packet handlers are getting called within VMWare Fusion VMs. It's the only difference I can think of. Same MDM profiles, same build of my app/binaries, and same macOS installations from scratch.

Posted by
kn-cs
Up vote reply of kn-cs Down vote reply of kn-cs
Add a Comment

Is there a known issue with NEFilterPacketProvider and Parallels VMs?

Not that I am aware of, but if this is the only environment where this code path does not work then it would be good to get a bug report down for this. Can you open a bug report with a sysdiagnose. Please respond with the Feedback ID.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com
Posted by
meaton
Post not yet marked as solved Up vote reply of meaton Down vote reply of meaton
Add a Comment

Thanks! Here's the bug report: FB9648977.

Posted by
kn-cs
Up vote reply of kn-cs Down vote reply of kn-cs

  • Hi @kn-cs,

    I have encountered the exact same problem.... outside of a VM. It get the exact same behavior (packetHandler block not called) on native macOS Monterey 12.3.1 on one of my machines (and surprisingly running a VM on this host also reveals the bug in the VM!), whereas the very same code works perfectly on another similar machine. Note that DataFilter APIs works correctly. I've spent hours on this bug and can't understand what's happening. Do you have any comment or answer to share since 7 months? Thanks.

    —
    altimac
Add a Comment

I've spent hours on this bug and can't understand what's happening.

Given that, I recommend that you open a DTS tech support incident so that someone (well, that’d be me :-) can help you with this one-on-one.

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

Posted by
eskimo
Up vote reply of eskimo Down vote reply of eskimo
Add a Comment