I have a typical content filter implemented using NEFilterDataProvider and I'm observing that sometimes handleNewFlow will not obey the returned verdict. More specifically, drop verdict is sometimes ignored and an error message is logged. The impact on my app is that my content filter may not drop flows when it was supposed to.
I narrowed the issue down to being triggered by using my content filter alongside a VPN (Tailscale VPN, haven't tested others).
To reproduce the issue:
- Open reddit.com on Google Chrome
- Activate the content filter set to drop traffic (in my case configured for reddit)
- Run a VPN
- Refresh the reddit browser tab
- Observe reddit being loaded just fine, despite traffic being dropped
Below you may find a sample log that may be related to when the issue is triggered.
Near the end of the log below, I found this particular line interesting: "No current verdict available, cannot report flow closed". I wonder if it means that something else raced in front of my extension and gave an allow verdict. My extension only takes 621us to make a decision.
com.apple.networkextension debug 17:19:41.714581-0300 Handling new flow:
identifier = D89B5B5D-793C-4940-777A-6BB703E80900
sourceAppIdentifier = EQHXZ8M8AV.com.google.Chrome.helper
sourceAppVersion = 138.0.7204.50
sourceAppUniqueIdentifier = {length = 20, bytes = 0x57df24110a3dd3fbd954082915f8f19f6d365053}
procPID = 15492
eprocPID = 15492
rprocPID = 15481
direction = outbound
inBytes = 0
outBytes = 0
signature = {length = 32, bytes = 0x2e387b1f a214703d 62f17624 4aec86f4 ... 91d91bbd d97b6c90 }
socketID = 9e803b76b7a77
localEndpoint = 0.0.0.0:0
remoteEndpoint = 52.6.64.124:443
remoteHostname = gql-realtime.reddit.com
protocol = 6
family = 2
type = 1
procUUID = 4C4C44ED-5555-3144-A13B-2281E1056F00
eprocUUID = 4C4C44ED-5555-3144-A13B-2281E1056F00
rprocUUID = 4C4C4485-5555-3144-A122-165F9195A675
myContentFilter.ContentFilterNetworkExtension debug 17:19:41.714638-0300 Flow D89B5B5D-793C-4940-777A-6BB703E80900: handling new flow
myContentFilter.ContentFilterNetworkExtension debug 17:19:41.715446-0300 Flow D89B5B5D-793C-4940-777A-6BB703E80900: drop (1 gql-realtime.reddit.com) ( 621.0803985595703 µs)
com.apple.networkextension debug 17:19:41.715606-0300 New flow verdict for D89B5B5D-793C-4940-777A-6BB703E80900:
drop = YES
remediate = NO
needRules = NO
shouldReport = NO
pause = NO
urlAppendString = NO
filterInbound = NO
peekInboundBytes = 0
filterOutbound = NO
peekOutboundBytes = 0
statisticsReportFrequency = none
com.apple.networkextension debug 17:19:41.715775-0300 Dropping new flow 9e803b76b7a77
com.apple.networkextension error 17:19:41.715883-0300 No current verdict available, cannot report flow closed
com.apple.networkextension debug 17:19:41.715976-0300 Outbound disconnect message rejected, no flow found for sockid 2788377450216055
com.apple.networkextension debug 17:19:41.716727-0300 Inbound disconnect message rejected, no flow found for sockid 2788377450216055
Also good to note that this can only be reliably reproduced if there was a browser tab recently opened and kept open in that website. Here I'm also guessing that the browser is caching connections.
I was able to reproduce on macOS 15.6 Beta (24G5065c), Google Chrome 138 (apparently doesn't happen on Firefox), and the user has seen the issue on macOS 15.5.
My alternative theory is that this log doesn't have anything to do with the behavior and instead it's just Chrome caching the connection, and further traffic in that connection simply flows through because it was previously allowed. Could that be the case?
Thanks!