Sending with pcap_sendqueue_transmit sometimes takes a long time to return

[zhscnd]

Environment: npcap-0.9987.exe, npcap-sdk-1.04.
I use pcap_sendqueue_transmit to send data, sending 500 packets each time, sending a total of 10,000 times. Most of the time the function returns in about 10 milliseconds, but occasionally (less than 10 times) the function takes more than 10 seconds to return.
The third parameter of pcap_sendqueue_transmit is 0.

DiagReport-20200305-110303.txt
install.log
NPFInstall.log

[zhscnd]

npcap-0.9995.exe, npcap-sdk-1.05.
Have the same problem.

[zirahvi]

The API documentation says the function should respect the packet timestamps only if the sync argument is non-zero (At least that is my interpretation). The sending logic in wpcap's PacketSendPackets() (in Packet32.cpp) is as follows:

...
		do{
			// Send the data to the driver
			//TODO Res is NEVER checked, this is REALLY bad.
			Res = (BOOLEAN)DeviceIoControl(AdapterObject->hFile,
				(Sync)?BIOCSENDPACKETSSYNC:BIOCSENDPACKETSNOSYNC,
				(PCHAR)PacketBuff + TotBytesTransfered,
				Size - TotBytesTransfered,
				NULL,
				0,
				&BytesTransfered,
				NULL);

			// Exit from the loop on error
			if(Res != TRUE)
				break;

			TotBytesTransfered += BytesTransfered;

			// Exit from the loop if we have transferred everything
			if(TotBytesTransfered >= Size)
				break;

			// calculate the time interval to wait before sending the next packet
			TargetTicks.QuadPart = StartTicks.QuadPart +
			(LONGLONG)
			((((struct timeval*)((PCHAR)PacketBuff + TotBytesTransfered))->tv_sec - BufStartTime.tv_sec) * 1000000 +
			(((struct timeval*)((PCHAR)PacketBuff + TotBytesTransfered))->tv_usec - BufStartTime.tv_usec)) *
			(TimeFreq.QuadPart) / 1000000;
			
			// Wait until the time interval has elapsed
			while( CurTicks.QuadPart <= TargetTicks.QuadPart )
				QueryPerformanceCounter(&CurTicks);

		}
		while(TRUE);
...

It looks like the packet timestamps are unconditionally respected. The Sync argument only seems to have effect on the device I/O call. So if you queue packets with different timestamps, you'll always end up having synchronized send. I guess the only difference Sync makes is whether the wait happens in the kernel or here (PacketSendPackets).

@dmiller-nmap: Should the inner busy-while condition be Sync && (CurTicks.QuadPart < TargetTicks.QuadPart) instead?

[dmiller-nmap]

@zirahvi Thanks for that analysis. The BIOCSENDPACKETSSYNC vs BIOCSENDPACKETSNOSYNC correctly enables or disables synchronization within the driver code, but since this could result in very long blocking calls to DeviceIoControl, there is a check to ensure the call doesn't last more than about 1 second:

// Release the application if it has been blocked for approximately more than 1 seconds
if (pWinpcapHdr->ts.tv_sec - BufStartTime.tv_sec > 1)
{
    IF_LOUD(DbgPrint("NPF_BufferedWrite: timestamp elapsed, returning.\n");)
    result = Pos;
    break;
}

This results in a return back to PacketSendPackets, where the loop goes around and sends again. The problem is that if the user wants synchronization, the kernel won't know if there's supposed to be a pause before sending the first packet in the next batch. So Packet.dll keeps track of waiting (a busy wait!) for the next packet to be ready to send. And yes, as you point out, it is doing this even if the user did not request synchronization, which is probably what is causing the bug.

[dmiller-nmap]

Also, the wait time is being calculated assuming a fixed 1000000 ticks per second, even though we call QueryPerformanceFrequency() earlier. If this value (approx 1MHz) is too high, we could end up waiting a long time. If it's too small, we won't wait long enough. The driver code uses the correct calculation, so I'll change this here as well.

[dmiller-nmap]

Well, I guess that's not technically true. I misread the parentheses, but we're risking an overflow by trying to accumulate the number of microseconds and multiplying by the tick count before dividing by 1M. Changed it to just get the number of ticks in each term and add those last. By my guesstimation, the tick count would get high enough to overflow this after 10 days.