Npcap 0.993-0.9986 spontaneously stops capturing; all packets go to ps_drop

[akontsevoy]

Greetings,

We have an intermittent issue with Npcap running on the customer's VMware Windows Server 2016 machines. Initially everything works well and captures the traffic as expected, but eventually, despite pcap_dispatch() being called regularly and not returning errors, the traffic capture stops and all new packets seen by the adapter end up in pcap_stat::ps_drop. We have not been able to identify what triggers this problem.

Broadly, our product operates as follows:

1. A capture thread is started, which discovers network adapters with pcap_findalldevs(); filters out devices with PCAP_IF_LOOPBACK flag.
2. Open devices (in this case only one) with pcap = pcap_create(name, ...), pcap_set_buffer_size(pcap, 3 * 1024 * 1024), pcap_activate(pcap), pcap_set_snaplen(pcap, 0xFFFF), pcap_setnonblock(pcap, 1, ...), apply BPF (where BPF looks like not host <single-IP>), pcap_setmintocopy(pcap, 8000), and finally event = pcap_getevent(pcap). All of this completes without errors.
3. Call pcap_dispatch(pcap, -1, handler, NULL) every time WaitForMultipleObjects(events_size, events, FALSE, 200) returns (whether with WAIT_OBJECT_x or with WAIT_TIMEOUT, i.e. either by activity on the handle, or after 200 ms of inactivity). The handler function always returns locally (doesn't throw exceptions). It does grab a mutex, but we've double-checked that it's getting released properly by other threads in the application (i.e. there's no deadlock condition). Again, pcap_dispatch() returns without errors (always a number >= 0), but after a while stops returning data (i.e. handler no longer gets called).
4. Roughly every 30 seconds, pcap_findalldevs() is called again, without closing the open pcap handles, to see if the network device list has changed. If it has, all pcap handles are closed and reopened; otherwise no action is taken.
5. Roughly every second, pcap_stats(pcap, &ps) is called; this again returns without errors, but after a while every new packet goes into ps.ps_drop.

A few observations:

1. Npcap driver is running (not stopped), whether or not Npcap is currently affected by the problem.
2. Closing and reopening the Npcap handle temporarily mitigates the problem (the capture starts again, but after a while the same thing happens).
3. Doesn't reproduce everywhere (we have only a few users affected by the issue).
4. We've tried Npcap versions 0.993, 0.9985 and 0.9986.

Output of systeminfo.exe:

Host Name:                 <redacted>
OS Name:                   Microsoft Windows Server 2016 Standard
OS Version:                10.0.14393 N/A Build 14393
OS Manufacturer:           Microsoft Corporation
OS Configuration:          Member Server
OS Build Type:             Multiprocessor Free
Registered Owner:          <redacted>
Registered Organization:   <redacted>
Product ID:                <redacted>
Original Install Date:     10/11/2019, 2:14:57 PM
System Boot Time:          10/14/2019, 10:18:35 AM
System Manufacturer:       VMware, Inc.
System Model:              VMware Virtual Platform
System Type:               x64-based PC
Processor(s):              2 Processor(s) Installed.
                           [01]: Intel64 Family 6 Model 79 Stepping 1 GenuineIntel ~2600 Mhz
                           [02]: Intel64 Family 6 Model 79 Stepping 1 GenuineIntel ~2600 Mhz
BIOS Version:              Phoenix Technologies LTD 6.00, 9/17/2015
Windows Directory:         C:\Windows
System Directory:          C:\Windows\system32
Boot Device:               \Device\HarddiskVolume1
System Locale:             en-us;English (United States)
Input Locale:              en-us;English (United States)
Time Zone:                 (UTC-06:00) Central Time (US & Canada)
Total Physical Memory:     16,384 MB
Available Physical Memory: 13,457 MB
Virtual Memory: Max Size:  19,980 MB
Virtual Memory: Available: 13,769 MB
Virtual Memory: In Use:    6,211 MB
Page File Location(s):     C:\pagefile.sys
Domain:                    <redacted>
Logon Server:              N/A
Hotfix(s):                 4 Hotfix(s) Installed.
                           [01]: KB3199986
                           [02]: KB4033393
                           [03]: KB4521858
                           [04]: KB3200970
Network Card(s):           1 NIC(s) Installed.
                           [01]: vmxnet3 Ethernet Adapter
                                 Connection Name: Ethernet
                                 DHCP Enabled:    No
                                 IP address(es)
                                 [01]: <Private IPv4 redacted>
                                 [02]: <Link-local IPv6 redacted>
Hyper-V Requirements:      A hypervisor has been detected. Features required for Hyper-V will not be displayed.

Relevant output of reg.exe query HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Class\{4d36e972-e325-11ce-bfc1-08002be10318} /s:

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Class\{4d36e972-e325-11ce-bfc1-08002be10318}\0001
    DriverDesc    REG_SZ    vmxnet3 Ethernet Adapter
    ProviderName    REG_SZ    VMware, Inc.
    DriverDateData    REG_BINARY    0040D958AC65D401
    DriverDate    REG_SZ    10-17-2018
    DriverVersion    REG_SZ    1.8.10.0
    InfPath    REG_SZ    oem9.inf
    InfSection    REG_SZ    vmxnet3.ndis630.x64.ndi.NT
    IncludedInfs    REG_MULTI_SZ    machine.inf\0pci.inf
    MatchingDeviceId    REG_SZ    PCI\VEN_15AD&DEV_07B0
    EnableMonitorMode    REG_SZ    0
    *IfType    REG_DWORD    0x6
    *MediaType    REG_DWORD    0x0
    *PhysicalMediaType    REG_DWORD    0xe
    BusType    REG_SZ    5
    Characteristics    REG_DWORD    0x84
    *SpeedDuplex    REG_SZ    0
    *PriorityVLANTag    REG_SZ    3
    *JumboPacket    REG_SZ    1514
    *InterruptModeration    REG_SZ    1
    OffloadVlanEncap    REG_SZ    1
    EnableWakeOnLan    REG_SZ    1
    *WakeOnPattern    REG_SZ    1
    *WakeOnMagicPacket    REG_SZ    1
    *IPChecksumOffloadIPv4    REG_SZ    3
    *TCPChecksumOffloadIPv4    REG_SZ    3
    *UDPChecksumOffloadIPv4    REG_SZ    3
    OffloadIpOptions    REG_SZ    1
    OffloadTcpOptions    REG_SZ    1
    EnableAdaptiveRing    REG_SZ    1
    *TCPChecksumOffloadIPv6    REG_SZ    3
    *UDPChecksumOffloadIPv6    REG_SZ    3
    *LsoV1IPv4    REG_SZ    1
    *LsoV2IPv4    REG_SZ    1
    *LsoV2IPv6    REG_SZ    1
    *RSS    REG_SZ    0
    IfTypePreStart    REG_DWORD    0x6
    NetworkInterfaceInstallTimestamp    REG_QWORD    0x1d5806e43d780ff
    InstallTimeStamp    REG_BINARY    E3070A0006000C0002000D000F003700
    DeviceInstanceID    REG_SZ    PCI\VEN_15AD&DEV_07B0&SUBSYS_07B015AD&REV_01\FF290C00DDE810FE00
    ComponentId    REG_SZ    PCI\VEN_15AD&DEV_07B0
    NetCfgInstanceId    REG_SZ    {0C2A9A0D-3001-4519-B5FC-3CF3B8A006A2}
    NetLuidIndex    REG_DWORD    0x8001
    *RscIPv4    REG_SZ    1
    *RscIPv6    REG_SZ    1
    CoalSchemeMode    REG_SZ    4

[fyodor]

Hi Alexey. Thanks for the very detailed report. We're investigating now how this could happen and of course what can be done to fix it!

[dmiller-nmap]

Thanks again for the report. I have a few questions to help us narrow down what might be happening, since we have not yet been able to reproduce the issue here:

1. What kind of network traffic is going on or typical in the cases where the issue occurs? That is, is it many small packets, fewer large packets, etc.?
2. Does WaitForMultipleObjects stop returning WAIT_OBJECT_0? In other words, does the event still get signaled even if pcap_dispatch() does not retrieve any packets, or does it consistently time out or return WAIT_FAILED?
3. Is the pcap handle (pcap_t) shared between multiple threads or processes?
4. Are any packets dropped before pcap_dispatch() stops delivering packets? That is, does ps_recv increase without a corresponding increase in ps_drop for any amount of time after the first increase to ps_drop?

Thanks for any additional info you can provide.

[akontsevoy]

3] No, the pcap handle is used from only one thread in the process (although it's not the main thread).
2] No, the event keeps getting signalled when new packets arrive and WaitForMultipleObjects() keeps returning WAIT_OBJECT_0, but all subsequent calls to pcap_dispatch() return 0 and don't call the handler. By the way, we never call pcap_breakloop() from the handler.
4] After pcap_dispatch() stops delivering packets, ps_recv keeps increasing despite pcap_dispatch() constantly returning 0; ps_drop is initially 0 at that point. At some point (presumably when the internal buffer fills), ps_drop becomes non-0 and starts increasing.
1] It's hard to tell; the last packets successfully captured are always small packets, from what I can tell -- either 60, 61, or 171, or 200-something bytes -- much less than the MTU; and there is always a bunch of them -- like 4-20 in that last non-0 pcap_dispatch(). But this could just be a coincidence. Yet, if we divide the internal capture buffer size (3000000) by [(ps_recv when ps_drop starts increasing) - (ps_recv when this condition first triggers)] to obtain the average packet size in the full capture buffer -- that average is always over 2000. So maybe it is the jumbo frames that we trip on. However, I've seen frames as large as 66546 bytes (pcap_pkthdr::caplen == pcap_pkthdr::len) successfully captured. Not sure why that happens either, as we explicitly call pcap_set_snaplen(65535) -- so that in theory pcap_pkthdr::caplen should not be larger than 65535 (as far as I understand).

Additional observations which may or may not be helpful:
a) Our handler function transports the captured data on the network, using a socket on the same network adapter from which we capture. We use a BPF to prevent the transported packets from being captured again (thus avoiding a feedback loop), but maybe the fact that the handler function potentially calls out into the network driver (albeit indirectly) plays a role here.
b) The capture process is running with low priority; however, we tried resetting it to normal and it did not help.
c) Even on healthy hosts (not subject to this issue), every now and then it happens that the handle event is signalled (WaitForMultipleObjects() returns WAIT_OBJECT_0) but the subsequent pcap_dispatch() returns 0, indicating no data to capture. (But on healthy hosts, subsequent calls to pcap_dispatch() return data.) As far as I understand, this should not be happening. Perhaps the event gets signalled before BPF is applied? This is preventing me from generically applying the workaround I had in mind (if the event is signalled but no data is captured, close and reopen the handle).

[guyharris]

c) Even on healthy hosts (not subject to this issue), every now and then it happens that the handle event is signalled (WaitForMultipleObjects() returns WAIT_OBJECT_0) but the subsequent pcap_dispatch() returns 0, indicating no data to capture. (But on healthy hosts, subsequent calls to pcap_dispatch() return data.) As far as I understand, this should not be happening. Perhaps the event gets signalled before BPF is applied? This is preventing me from generically applying the workaround I had in mind (if the event is signalled but no data is captured, close and reopen the handle).

Capture mechanisms that do buffering of packets, with a timeout to keep packets from remaining buffered for too long (because the incoming packet rate is low so that the buffer takes a long time to fill up), have two sorts of timeout:

1. timeouts that expire only if there's at least one packet in the buffer (e.g., because the timer starts when the first packet is put in the buffer);

2. timeouts that expire even if there are no packets in the buffer (e.g., because the timer starts when an attempt is made to read from the buffer).

For capture mechanisms with the second type of timer, pcap_dispatch() may return 0, because the timer timed out when there were no packets in the buffer.

As I remember, the WinPcap and Npcap NPF driver is the second type, so you may get 0 packets from a wakeup because the timer went off and no packets had arrived since the last time the buffer was read.

[guyharris]

1] ... However, I've seen frames as large as 66546 bytes (pcap_pkthdr::caplen == pcap_pkthdr::len) successfully captured. Not sure why that happens either, as we explicitly call pcap_set_snaplen(65535) -- so that in theory pcap_pkthdr::caplen should not be larger than 65535 (as far as I understand).

At least as I read the bpf_filter() call and the "Add MDLs" loop in NPF_TapExForEachOpen() in packetWin7\npf\npf\Read.c, the code 1) shouldn't copy more bytes than the return value of bpf_filter() and 2) should set the code to the total number of bytes copied; given that the BPF compiler should generate code to return the snapshot length for packets that match the filter, and should always provide a filter program even if it's just a trivial program doing a ret instruction returning the snapshot length, that shouldn't happen.

[guyharris]

3] No, the pcap handle is used from only one thread in the process (although it's not the main thread).

So in that thread, are you in a loop that just calls pcap_dispatch(), with the pcap_t not being in non-blocking mode, or are you in an event loop that waits for multiple objects, including the event handle for the pcap_t, calling pcap_dispatch() if the event handle was signaled or something such as that?

[dmiller-nmap]

There's a lot of information here to go through. This in particular intrigues me:

1] It's hard to tell; the last packets successfully captured are always small packets, from what I can tell -- either 60, 61, or 171, or 200-something bytes -- much less than the MTU; and there is always a bunch of them -- like 4-20 in that last non-0 pcap_dispatch(). But this could just be a coincidence.

If there's some condition that is causing the buffer to fill up or the driver to think that the buffer is filling up, then it would start dropping packets that are too large for the remaining space in the buffer. This would lead to smaller and smaller packets being captured until they too fill up the buffer and there is no remaining space.

This is just a hunch at this point. I need to read through the code again with this idea in mind.

[dmiller-nmap]

I haven't been able to figure out anywhere where we might be losing account of free space remaining. I'm guessing it has something to do with calculating how much space a packet takes up when writing it to the buffer or how much space to free up when reading a packet out of the buffer. So instead of constantly incrementing and decrementing the free space counter, I'm going to try a change that calculates the free space based on the size of the buffer and the positions of the consumer and producer pointers. We'll have to acquire a lock on the buffer in the Read handler in order to ensure we don't calculate based on an outdated position, but that's probably best anyway to avoid concurrency issues if some software somewhere is sharing an adapter handle between multiple threads.

Please let us know if the issue persists in the next release.

[akontsevoy]

There's a lot of information here to go through. This in particular intrigues me:

1] It's hard to tell; the last packets successfully captured are always small packets, from what I can tell -- either 60, 61, or 171, or 200-something bytes -- much less than the MTU; and there is always a bunch of them -- like 4-20 in that last non-0 pcap_dispatch(). But this could just be a coincidence.

If there's some condition that is causing the buffer to fill up or the driver to think that the buffer is filling up, then it would start dropping packets that are too large for the remaining space in the buffer. This would lead to smaller and smaller packets being captured until they too fill up the buffer and there is no remaining space.

This is just a hunch at this point. I need to read through the code again with this idea in mind.

But if what you said were the case and we thought the buffer was full, wouldn't ps_drop start increasing immediately after the condition triggers? As it stands, we see ps_recv increase by several hundreds, or thousands (3 MB buffer) after the problem appears, and before we see ps_drop increase. That would suggest we are having problems reading from the buffer, not writing to the buffer (why is pcap_dispatch() returning 0, when there are obviously things there we can read). Without knowing much else, but given the fact that we sometimes capture packets larger than snaplen (which shouldn't be happening), I'd look for potential buffer overwrites or overreads.

Again, without knowing anything else, if you are using a circular buffer as your response seems to suggest, I'd double check the edge/overflow conditions:

1. Are the cursors adjusted correctly when an incoming packet aligns exactly with the buffer boundaries?
2. What happens if an incoming packet would write past the current read position (write cursor overruns the read cursor)?
3. What happens if an incoming packet is larger than the full buffer (write cursor overruns both the read cursor and the write cursor)?

P.S. As part of troubleshooting I also tried to remove the pcap_setmintocopy() call, but the problem persisted.

[dmiller-nmap]

Npcap 0.9987, released today, includes the above commit that may address this issue. Please let us know one way or the other so we know if we need to continue to investigate this issue.

[akontsevoy]

Instructed one of our users to try the new version, will confirm one way or another.

[akontsevoy]

Unfortunately, a deployment of version 0.9989 on one of the affected machines indicates that the problem still persists -- with roughly the same symptoms.

[dmiller-nmap]

@akontsevoy Thanks for letting us know. I'll take another look.

[dmiller-nmap]

Ok, here's an interesting thing: the processors listed appear to be Intel XEONs with 56 cores each. Npcap has some weirdness surrounding number of processors (#1967) that might explain the problem here:

The kernel capture buffer for an instance is split into g_NCpu segments, which is the return value from NdisSystemProcessorCount(). This function is documented on another page as only returning "the processor count for processor group 0." For the sake of argument, let's guess that the number is 56, meaning all the cores on processor 0. So Npcap will split the buffer into 56 segments, and whenever a thread is scheduled to deal with incoming packets, it will try to write to the segment corresponding to its processor number.

HOWEVER! In order to determine the processor number, Npcap uses KeGetCurrentProcessorNumberEx(), which returns the systemwide processor index of the current processor. So if the thread is scheduled on core 10 of processor 1, the index would be 55+10=65, which is greater than the number of segments the buffer is split into.

So why do we not see a BSoD due to buffer overrun? Well, each OPEN_INSTANCE has an array of 128 CpuPrivateData structures to keep track of position in the buffer segment and statistics. It is 0-initialized, including the Free counter. So when the thread grabs CpuPrivateData number 65, it's there and it claims that there is no space for the packet, so we record a drop (in a place that won't be checked) and signal the Read event to tell the application to clear out some space. But of course there's nothing that reading more packets will do to solve things as long as the thread remains scheduled on a core without a corresponding buffer segment. This is why you are likely seeing WAIT_OBJECT_0 but not getting any packets: a packet drop happened, but there weren't any new saved packets to clear out. So you can definitely reopen the handle in this case because it's a clear case that something went wrong.

Unfortunately, none of this explains why the ps_drop counter keeps increasing. The stats gathering routines only reference CpuPrivateData structures less than g_NCpu, so the count should only increase when there's a valid buffer for that thread. I'm still thinking about that one, and I don't see any bugs in the way the sequence numbers are written/read from the buffer.