search

microsoft / xdp-for-windows

XDP speeds up networking on Windows
MIT License
348 stars 41 forks source link

Functional test failure - NDIS pause/restart delayed in GenericLwfDelayDetachRxTx #513

Open mtfriesen opened 1 month ago

mtfriesen commented 1 month ago

We can see a delay between XDP requesting a restart and the stack fully pausing. The delay appears to be either in TCPIP or NIDS itself.

Test case output:

LastMpPauseTime.QuadPart > LowerBoundTime.QuadPart not true
  Failed GenericLwfDelayDetachRxTx [36 s]
  Error Message:
   Assert failed. Stop test execution.
  Stack Trace:
    at StopTest() in D:\a\xdp-for-windows\xdp-for-windows\test\functional\taef\tests.cpp:line 26
    at GenericLwfDelayDetach() in D:\a\xdp-for-windows\xdp-for-windows\test\functional\lib\tests.cpp:line 5634
    at xdpfunctionaltests::GenericLwfDelayDetachRxTx() in D:\a\xdp-for-windows\xdp-for-windows\test\functional\taef\tests.cpp:line 301
  Standard Output Messages:
 LastMpPauseTime.QuadPart > LowerBoundTime.QuadPart not true

Traces:

511306 [3]0004.0120::2024/05/11-04:45:53.891230300 [rtl] XdpTimerWorker:351 ---> Timer=FFFFB70477A96F60 IoObject=FFFFB70474E392E0
511307 [2]0004.1490::2024/05/11-04:45:53.891251300 [rtl] XdpTimerWorker:351 ---> Timer=FFFFB70477C7AF60 IoObject=FFFFB70474E392E0
511308 [2]0004.1490::2024/05/11-04:45:53.891287400 [xdplwf] XdpGenericDelayDereferenceDatapath:288 IfIndex=22 Requesting TX datapath detach
511309 [2]0004.1490::2024/05/11-04:45:53.891298900 [xdplwf] XdpGenericRequestRestart:517 IfIndex=22 Requesting datapath restart
511310 [2]0004.1490::2024/05/11-04:45:53.891422700 [rtl] XdpTimerWorker:379 <--- STATUS_SUCCESS
511311 [2]0004.0784::2024/05/11-04:45:53.891768200 [Microsoft-Windows-TCPIP]Framing: NDIS pause event. Interface = 22, Compartment = 1.
511312 [2]0004.0784::2024/05/11-04:45:53.891771400 [Microsoft-Windows-TCPIP]Framing: A PNP event has been indicated. Interface: 22. Address Family: 2(IPV4). Compartment: 1. Event: 8. Data: 0.
511313 [2]0004.0784::2024/05/11-04:45:53.892127100 [Microsoft-Windows-TCPIP]Framing: NDIS pause event. Interface = 22, Compartment = 1.
511314 [2]0004.0784::2024/05/11-04:45:53.892127900 [Microsoft-Windows-TCPIP]Framing: A PNP event has been indicated. Interface: 22. Address Family: 23(IPV6). Compartment: 1. Event: 8. Data: 0.
511315 [3]0004.0120::2024/05/11-04:45:53.895659500 [xdplwf] XdpGenericDelayDereferenceDatapath:288 IfIndex=22 Requesting RX datapath detach
511316 [3]0004.0120::2024/05/11-04:45:53.895666400 [xdplwf] XdpGenericRequestRestart:517 IfIndex=22 Requesting datapath restart
511317 [3]0004.0120::2024/05/11-04:45:53.895731300 [rtl] XdpTimerWorker:379 <--- STATUS_SUCCESS
511318 [0]037C.18A8::2024/05/11-04:45:53.984927200 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 0 at Tick = 591003, was scheduled for = 591000.
511319 [2]1570.17AC::2024/05/11-04:45:53.984934900 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 2 at Tick = 591003, was scheduled for = 591000.
511320 [0]037C.18A8::2024/05/11-04:45:53.984937200 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 0 for processor 0 at Tick = 591003 to Tick = 593000, OldScheduledExpiration = 5909802908 NewScheduledExpiration = 5929801598 DueTime = -19970000 Aperiodic = 1(TRUE).
511321 [2]1570.17AC::2024/05/11-04:45:53.984962600 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 2 for processor 2 at Tick = 591003 to Tick = 592000, OldScheduledExpiration = 5909800427 NewScheduledExpiration = 5919801598 DueTime = -9970000 Aperiodic = 1(TRUE).
511322 [2]0DF4.0A04::2024/05/11-04:45:54.522669800 [Microsoft-Windows-Winsock-AFD]recvfrom: 1: Process 0xFFFFB7046D488080, Endpoint 0xFFFFB7046DC9C050, Buffer Count 1, Buffer 0xFFFFB704774655A0, Length 0, Seq 4063, Status 0xC0000120(NT=The I/O request was canceled.)
511323 [2]0DF4.0A04::2024/05/11-04:45:54.522803400 [Microsoft-Windows-Winsock-AFD]recvfrom: 0: Process 0xFFFFB7046D488080, Endpoint 0xFFFFB7046DC9C050, Buffer Count 1, Buffer 0xFFFFB704774655A0, Length 512, Seq 4049, Status 0x0(NT=STATUS_SUCCESS)
511324 [2]0A54.1274::2024/05/11-04:45:54.965008800 [xdpfntest] LogTestFailure:49 LastMpPauseTime.QuadPart > LowerBoundTime.QuadPart not true
511325 [3]0A54.1274::2024/05/11-04:45:54.968044800 [Microsoft-Windows-Winsock-AFD]send: 0: Process 0xFFFFB704778CA080, Endpoint 0xFFFFB7046DB77AA0, Buffer Count 1, Buffer 0xFFFFB7046DE781B8, Length 152, Seq 3047, Status 0x0(NT=STATUS_SUCCESS)
511326 [3]0A54.1274::2024/05/11-04:45:54.968045700 [Microsoft-Windows-Winsock-AFD]send: 0: Process 0xFFFFB704778CA080, Endpoint 0xFFFFB7046DB77AA0, Buffer Count 1, Buffer 0xFFFFB7046DE781B8, Length 152, Seq 3056, Status 0x0(NT=STATUS_SUCCESS)
511327 [3]0A54.1274::2024/05/11-04:45:54.968049200 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20 send posted 152 bytes at 3916149574.
511328 [3]0A54.1274::2024/05/11-04:45:54.968058200 [Microsoft-Windows-TCPIP]IP: RouteLookup - API: IppFindNextHopAtDpcHelper DstAddr: 127.0.0.1 ConstrainSrcAddr: 127.0.0.1 ConstrainIfIndex: 1 ConstraintOveridden: 0 ReturnConstrained: 0 OutgoingIfIndex: 1 NextHopAddr: 127.0.0.1 Status: 0x0(NT=STATUS_SUCCESS)
511329 [3]0A54.1274::2024/05/11-04:45:54.968061700 [Microsoft-Windows-TCPIP]IP: SourceAddrLookup - DstAddr: 127.0.0.1 ConstrainSrcAddr: 127.0.0.1 ConstrainIfIndex: 1 OutgoingIfIndex: 1 ReturnConstrained: 2048 SelectedSrcAddr: 127.0.0.1
511330 [3]0A54.1274::2024/05/11-04:45:54.968064200 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046E365A20 stopping 7(SwsTimer) timer. 
511331 [3]0A54.1274::2024/05/11-04:45:54.968064600 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20 send transmitted 152 bytes at 3916149574.
511332 [3]0A54.1274::2024/05/11-04:45:54.968065800 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20: TCP send event, SeqNo = 3916149574, BytesSent = 152, CWnd = 892396, SndWnd = 2124544, SRtt = 160, RttVar = 49, RTO = 261, RcvWnd = 2161335.
511333 [3]0A54.1274::2024/05/11-04:45:54.968105500 [Microsoft-Windows-TCPIP]TCP: connection = 0xFFFFB7046E365A20 send tracker enqueued a transmit. Start = 3916149574, End = 3916149726, Timestamp = 591986374, SackedBytes = 0, BytesInFlight = 152.
511334 [3]0A54.1274::2024/05/11-04:45:54.968107300 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046E365A20 0(RetransmitTimer) timer started. Scheduled to expire in 261 ms. Processor 3: LastInterruptTime 5919626112 100-ns ticks; LastMicrosecondCount 591986374 msec; CachedKQPCValue 5919863742 ticks; CachedFrequencyValue 10000000.
511335 [3]0A54.1274::2024/05/11-04:45:54.968201000 [Microsoft-Windows-TCPIP]IP: Transmitting loopback Nbl 0xFFFFB70477AF6C60. Interface=1, Compartment=1, Src=127.0.0.1:50982, Dst=127.0.0.1:50981, Proto=6(TCP).
511336 [3]0A54.1274::2024/05/11-04:45:54.968202400 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB70477AF6C60 OOB info (1(Receive)): TcpIpChecksumNetBufferListInfo 0x140108, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0xAE0E1AA2, NetBufferListHashInfo 0x0, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511337 [3]0A54.1274::2024/05/11-04:45:54.968286100 [Microsoft-Windows-TCPIP]INETINSPECT: Owner = 0xFFFFB704778C5A60, InspectHandle = 0xFFFFB7046EFD6A60, InspectType = 4(ReceiveTcpDatagram), Action = 1(Allow), Status = 0x0(NT=STATUS_SUCCESS)
511338 [3]0A54.1274::2024/05/11-04:45:54.968288800 [Microsoft-Windows-Winsock-AFD]Data indication: 3: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer 0xFFFFB70477AF6DE0, Length 152, Seq 9000
511339 [3]0A54.1274::2024/05/11-04:45:54.968319300 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB704778C5A60 delivery 0xFFFFB704778C5C30 indicated 0x98 bytes accepted 0x98 bytes, status = 0x0(NT=STATUS_SUCCESS). RcvNxt = 3916149574.
511340 [3]0A54.1274::2024/05/11-04:45:54.968320700 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB704778C5A60: Received data with number of bytes = 152. ThSeq = 3916149574.
511341 [3]0A54.1274::2024/05/11-04:45:54.968322700 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 3 for processor 0 at Tick = 591986 to Tick = 591996, OldScheduledExpiration = 5929801598 NewScheduledExpiration = 5919726112 DueTime = -100000 Aperiodic = 1(TRUE).
511342 [3]0A54.1274::2024/05/11-04:45:54.968323700 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB704778C5A60: TCP send event, SeqNo = 4120237006, BytesSent = 0, CWnd = 654950, SndWnd = 2161152, SRtt = 160, RttVar = 46, RTO = 261, RcvWnd = 2124428.
511343 [3]0A54.1274::2024/05/11-04:45:54.968354500 [Microsoft-Windows-TCPIP]IP: Transmitting loopback Nbl 0xFFFFB70477AF8C60. Interface=1, Compartment=1, Src=127.0.0.1:50981, Dst=127.0.0.1:50982, Proto=6(TCP).
511344 [3]0A54.1274::2024/05/11-04:45:54.968356200 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB70477AF8C60 OOB info (1(Receive)): TcpIpChecksumNetBufferListInfo 0x108, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0xBEC75054, NetBufferListHashInfo 0x0, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511345 [3]0A54.1274::2024/05/11-04:45:54.968359600 [Microsoft-Windows-TCPIP]INETINSPECT: Owner = 0xFFFFB7046E365A20, InspectHandle = 0xFFFFB7046E2AE2B0, InspectType = 4(ReceiveTcpDatagram), Action = 1(Allow), Status = 0x0(NT=STATUS_SUCCESS)
511346 [0]0B24.0DB0::2024/05/11-04:45:54.968360200 [Microsoft-Windows-Winsock-AFD]recv: 0: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x0, Length 1, Seq 4115, Status 0x0(NT=STATUS_SUCCESS)
511347 [3]0A54.1274::2024/05/11-04:45:54.968360800 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20 send advance 152 bytes at 3916149574.
511348 [0]0B24.0DB0::2024/05/11-04:45:54.968361000 [Microsoft-Windows-Winsock-AFD]recv: 1: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x0, Length 1, Seq 4116, Status 0x0(NT=STATUS_SUCCESS)
511349 [3]0A54.1274::2024/05/11-04:45:54.968362100 [Microsoft-Windows-TCPIP]TCP: connection = 0xFFFFB7046E365A20 send tracker acked a transmit. AckNo = 3916149726, Start = 3916149574, End = 3916149726, Timestamp = 591986374, EverTransmitted = 0(FALSE), SackedBytes = 0, BytesInFlight = 0.
511350 [3]0A54.1274::2024/05/11-04:45:54.968363000 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20 SRTT measurement complete (tick = 591986, sample = 0 ms, new srtt = 0 ms).
511351 [0]0B24.0DB0::2024/05/11-04:45:54.968363100 [Microsoft-Windows-Winsock-AFD]recv: 0: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x0, Length 1, Seq 4115, Status 0x0(NT=STATUS_SUCCESS)
511352 [0]0B24.0DB0::2024/05/11-04:45:54.968363500 [Microsoft-Windows-Winsock-AFD]recv: 1: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x0, Length 1, Seq 4116, Status 0x0(NT=STATUS_SUCCESS)
511353 [3]0A54.1274::2024/05/11-04:45:54.968363700 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20:  Rtt sample recorded 293 SRTT 177 RttVar 70.
511354 [3]0A54.1274::2024/05/11-04:45:54.968364800 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046E365A20 send queue is idle. Cwnd = 892396, Processor = 3, CurrentTick = 591986, IdleTick = 591986.
511355 [0]0B24.0DB0::2024/05/11-04:45:54.968365200 [Microsoft-Windows-Winsock-AFD]recv: 0: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x0, Length 128, Seq 4115, Status 0x0(NT=STATUS_SUCCESS)
511356 [3]0A54.1274::2024/05/11-04:45:54.968365500 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046E365A20 stopping 0(RetransmitTimer) timer. 
511357 [0]0B24.0DB0::2024/05/11-04:45:54.968365600 [Microsoft-Windows-Winsock-AFD]recv: 1: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x0, Length 128, Seq 4116, Status 0x0(NT=STATUS_SUCCESS)
511358 [3]0A54.1274::2024/05/11-04:45:54.968366500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20: Cumulative Ack event, SeqNo = 3916149726, BytesAcked = 0, CWnd = 892548, SndWnd = 2124288, InRecovery = 0, TimeSinceLastLossMS = 0, CubicCwnd = 0, AimdCwnd = 0, K = 0, Wmax = 0, LastWmax = 0, MaxSndWnd = 2161152 IsLimitedSlowStart = 0.
511359 [3]0A54.1274::2024/05/11-04:45:54.968367500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20: Cumulative Ack event, SeqNo = 3916149574, BytesAcked = 152, CWnd = 892548, SndWnd =2124288.
511360 [3]0A54.1274::2024/05/11-04:45:54.968368100 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20: Received data with number of bytes = 0. ThSeq = 4120237006.
511361 [0]0B24.0DB0::2024/05/11-04:45:54.968373100 [Microsoft-Windows-TCPIP]TCP: TcpReleaseIndicationList: Nbl = 0xFFFFB70477AF6C60.
511362 [3]0A54.1274::2024/05/11-04:45:54.968406800 [Microsoft-Windows-Winsock-AFD]send: 1: Process 0xFFFFB704778CA080, Endpoint 0xFFFFB7046DB77AA0, Buffer Count 1, Buffer 0xFFFFB7046DE781B8, Length 152, Seq 3051, Status 0x0(NT=STATUS_SUCCESS)
511363 [0]0B24.0DB0::2024/05/11-04:45:54.968414000 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046E365A20 send complete 152 bytes at 3916149574 (normal).
511364 [0]0B24.0DB0::2024/05/11-04:45:54.968415000 [Microsoft-Windows-Winsock-AFD]send: 1: Process 0xFFFFB704778CA080, Endpoint 0xFFFFB7046DB77AA0, Buffer Count 1, Buffer 0xFFFFB7046DE781B8, Length 152, Seq 3073, Status 0x0(NT=STATUS_SUCCESS)
511365 [0]0B24.0DB0::2024/05/11-04:45:54.968416600 [Microsoft-Windows-Winsock-AFD]recv: 0: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x15D41B8, Length 22, Seq 4115, Status 0x0(NT=STATUS_SUCCESS)
511366 [0]0B24.0DB0::2024/05/11-04:45:54.968416900 [Microsoft-Windows-Winsock-AFD]recv: 1: Process 0xFFFFB70477E27080, Endpoint 0xFFFFB7046DA1C120, Buffer Count 1, Buffer 0x15D41B8, Length 22, Seq 4116, Status 0x0(NT=STATUS_SUCCESS)
511367 [0]0000.0000::2024/05/11-04:45:54.984994900 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 0 at Tick = 592003, was scheduled for = 591996.
511368 [0]0000.0000::2024/05/11-04:45:54.985001500 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 0 for processor 0 at Tick = 592003 to Tick = 592086, OldScheduledExpiration = 5919726112 NewScheduledExpiration = 5920662199 DueTime = -830000 Aperiodic = 1(TRUE).
511369 [3]0A54.1274::2024/05/11-04:45:54.985014300 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 3 at Tick = 592003, was scheduled for = 592000.
511370 [3]0A54.1274::2024/05/11-04:45:54.985022600 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 3 for processor 3 at Tick = 592003 to Tick = 594000, OldScheduledExpiration = 5919800427 NewScheduledExpiration = 5939802199 DueTime = -19970000 Aperiodic = 1(TRUE).
511371 [2]0000.0000::2024/05/11-04:45:54.985034100 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 2 at Tick = 592003, was scheduled for = 592000.
511372 [2]0000.0000::2024/05/11-04:45:54.985038100 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 2 for processor 2 at Tick = 592003 to Tick = 592247, OldScheduledExpiration = 5919801598 NewScheduledExpiration = 5922272199 DueTime = -2440000 Aperiodic = 1(TRUE).
511373 [2]1028.1230::2024/05/11-04:45:54.985323700 [Microsoft-Windows-Winsock-AFD]send: 0: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 473, Seq 3047, Status 0x0(NT=STATUS_SUCCESS)
511374 [2]1028.1230::2024/05/11-04:45:54.985324900 [Microsoft-Windows-Winsock-AFD]send: 0: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 473, Seq 3056, Status 0x0(NT=STATUS_SUCCESS)
511375 [2]1028.1230::2024/05/11-04:45:54.985327900 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 send posted 473 bytes at 5289840.
511376 [2]1028.1230::2024/05/11-04:45:54.985331900 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046EE13A60 stopping 7(SwsTimer) timer. 
511377 [2]1028.1230::2024/05/11-04:45:54.985332900 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 send transmitted 473 bytes at 5289840.
511378 [2]1028.1230::2024/05/11-04:45:54.985334900 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60: TCP send event, SeqNo = 5289840, BytesSent = 473, CWnd = 56976, SndWnd = 4193536, SRtt = 8245, RttVar = 1266, RTO = 60, RcvWnd = 1573920.
511379 [2]1028.1230::2024/05/11-04:45:54.985381800 [Microsoft-Windows-TCPIP]TCP: connection = 0xFFFFB7046EE13A60 send tracker enqueued a transmit. Start = 5289840, End = 5290313, Timestamp = 592003642, SackedBytes = 0, BytesInFlight = 473.
511380 [2]1028.1230::2024/05/11-04:45:54.985382700 [Microsoft-Windows-TCPIP]TCP: Tail Loss Probe Event Connection = 0xFFFFB7046EE13A60, Event = 1(TimerArmed).
511381 [2]1028.1230::2024/05/11-04:45:54.985384200 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046EE13A60 0(RetransmitTimer) timer started. Scheduled to expire in 60 ms. Processor 2: LastInterruptTime 5919832199 100-ns ticks; LastMicrosecondCount 592003642 msec; CachedKQPCValue 5920036425 ticks; CachedFrequencyValue 10000000.
511382 [2]1028.1230::2024/05/11-04:45:54.985388200 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB70477AF8C60 OOB info (0(Send)): TcpIpChecksumNetBufferListInfo 0x220015, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0x9FE7DDFD, NetBufferListHashInfo 0x0, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511383 [2]1028.1230::2024/05/11-04:45:54.985429500 [Microsoft-Windows-Winsock-AFD]send: 1: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 473, Seq 3051, Status 0x0(NT=STATUS_SUCCESS)
511384 [2]0000.0000::2024/05/11-04:45:54.994287900 [fnlwf] FilterReceiveNetBufferLists:321 ---> Filter=FFFFB70477CBEF90
511385 [2]0000.0000::2024/05/11-04:45:54.994289100 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B07EDD0
511386 [2]0000.0000::2024/05/11-04:45:54.994289300 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B6DD0
511387 [2]0000.0000::2024/05/11-04:45:54.994306100 [fnlwf] FilterReceiveNetBufferLists:350 <--- STATUS_SUCCESS
511388 [2]0000.0000::2024/05/11-04:45:54.994315100 [fnlwf] FilterReceiveNetBufferLists:321 ---> Filter=FFFFB70477CB0F90
511389 [2]0000.0000::2024/05/11-04:45:54.994315400 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B07EDD0
511390 [2]0000.0000::2024/05/11-04:45:54.994315500 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B6DD0
511391 [2]0000.0000::2024/05/11-04:45:54.994324200 [fnlwf] FilterReceiveNetBufferLists:350 <--- STATUS_SUCCESS
511392 [2]0000.0000::2024/05/11-04:45:54.994328900 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB7046B07EDD0 OOB info (1(Receive)): TcpIpChecksumNetBufferListInfo 0x38, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0x9FE7DDFD, NetBufferListHashInfo 0x301, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511393 [2]0000.0000::2024/05/11-04:45:54.994329600 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB7046B0B6DD0 OOB info (1(Receive)): TcpIpChecksumNetBufferListInfo 0x38, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0x9FE7DDFD, NetBufferListHashInfo 0x301, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511394 [2]0000.0000::2024/05/11-04:45:54.994347100 [Microsoft-Windows-TCPIP]INETINSPECT: Owner = 0xFFFFB7046EE13A60, InspectHandle = 0xFFFFB7046DCDBA20, InspectType = 4(ReceiveTcpDatagram), Action = 1(Allow), Status = 0x0(NT=STATUS_SUCCESS)
511395 [2]0000.0000::2024/05/11-04:45:54.994348500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 send advance 473 bytes at 5289840.
511396 [2]0000.0000::2024/05/11-04:45:54.994349700 [Microsoft-Windows-TCPIP]TCP: connection = 0xFFFFB7046EE13A60 send tracker acked a transmit. AckNo = 5290313, Start = 5289840, End = 5290313, Timestamp = 592003642, EverTransmitted = 0(FALSE), SackedBytes = 0, BytesInFlight = 0.
511397 [2]0000.0000::2024/05/11-04:45:54.994350500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 SRTT measurement complete (tick = 592012, sample = 8 ms, new srtt = 8 ms).
511398 [2]0000.0000::2024/05/11-04:45:54.994351100 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60:  Rtt sample recorded 9010 SRTT 8341 RttVar 1141.
511399 [2]0000.0000::2024/05/11-04:45:54.994352700 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046EE13A60 send queue is idle. Cwnd = 56976, Processor = 2, CurrentTick = 592012, IdleTick = 592012.
511400 [2]0000.0000::2024/05/11-04:45:54.994353200 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046EE13A60 stopping 0(RetransmitTimer) timer. 
511401 [2]0000.0000::2024/05/11-04:45:54.994354000 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60: Cumulative Ack event, SeqNo = 5290313, BytesAcked = 0, CWnd = 57449, SndWnd = 4193280, InRecovery = 0, TimeSinceLastLossMS = 0, CubicCwnd = 0, AimdCwnd = 0, K = 0, Wmax = 0, LastWmax = 0, MaxSndWnd = 4194560 IsLimitedSlowStart = 0.
511402 [2]0000.0000::2024/05/11-04:45:54.994354500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60: Cumulative Ack event, SeqNo = 5289840, BytesAcked = 473, CWnd = 57449, SndWnd =4193280.
511403 [2]0000.0000::2024/05/11-04:45:54.994356600 [Microsoft-Windows-Winsock-AFD]Data indication: 3: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer 0xFFFFB7046B07EF50, Length 366, Seq 9000
511404 [2]0000.0000::2024/05/11-04:45:54.994359600 [Microsoft-Windows-Winsock-AFD]recv: 1: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0x0, Length 0, Seq 4114, Status 0x0(NT=STATUS_SUCCESS)
511405 [2]0000.0000::2024/05/11-04:45:54.994367900 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 delivery 0xFFFFB7046EE13C30 indicated 0x16E bytes accepted 0x16E bytes, status = 0x0(NT=STATUS_SUCCESS). RcvNxt = 2159257588.
511406 [2]0000.0000::2024/05/11-04:45:54.994369900 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046EE13A60 2(DelAckTimer) timer started. Scheduled to expire in 10 ms. Processor 2: LastInterruptTime 5919832199 100-ns ticks; LastMicrosecondCount 592012652 msec; CachedKQPCValue 5920126525 ticks; CachedFrequencyValue 10000000.
511407 [2]0000.0000::2024/05/11-04:45:54.994370300 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60: Received data with number of bytes = 366. ThSeq = 2159257588.
511408 [2]0000.0000::2024/05/11-04:45:54.994370900 [Microsoft-Windows-TCPIP]INETINSPECT: Owner = 0xFFFFB7046EE13A60, InspectHandle = 0xFFFFB7046DCDBA20, InspectType = 4(ReceiveTcpDatagram), Action = 1(Allow), Status = 0x0(NT=STATUS_SUCCESS)
511409 [2]0000.0000::2024/05/11-04:45:54.994371300 [Microsoft-Windows-Winsock-AFD]Data indication: 3: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer 0xFFFFB7046B0B6F50, Length 27, Seq 9000
511410 [2]0000.0000::2024/05/11-04:45:54.994372100 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 delivery 0xFFFFB7046EE13C30 indicated 0x1B bytes accepted 0x1B bytes, status = 0x0(NT=STATUS_SUCCESS). RcvNxt = 2159257954.
511411 [2]0000.0000::2024/05/11-04:45:54.994372600 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60: Received data with number of bytes = 27. ThSeq = 2159257954.
511412 [2]0000.0000::2024/05/11-04:45:54.994373400 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60 send complete 473 bytes at 5289840 (normal).
511413 [2]0000.0000::2024/05/11-04:45:54.994374000 [Microsoft-Windows-Winsock-AFD]send: 1: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 473, Seq 3073, Status 0x0(NT=STATUS_SUCCESS)
511414 [2]0000.0000::2024/05/11-04:45:54.994376000 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046EE13A60: TCP send event, SeqNo = 5290313, BytesSent = 0, CWnd = 57449, SndWnd = 4193280, SRtt = 8341, RttVar = 1141, RTO = 60, RcvWnd = 1573527.
511415 [2]0000.0000::2024/05/11-04:45:54.994412700 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB70477AFAC60 OOB info (0(Send)): TcpIpChecksumNetBufferListInfo 0x220015, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0x9FE7DDFD, NetBufferListHashInfo 0x0, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511416 [2]1028.16C8::2024/05/11-04:45:54.994498300 [Microsoft-Windows-TCPIP]TCP: TcpReleaseIndicationList: Nbl = 0xFFFFB7046B07EDD0.
511417 [2]1028.16C8::2024/05/11-04:45:54.997517900 [fnlwf] FilterReturnNetBufferLists:298 ---> Filter=FFFFB70477CB0F90
511418 [2]1028.16C8::2024/05/11-04:45:54.997518600 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B07EDD0
511419 [2]1028.16C8::2024/05/11-04:45:54.997519500 [fnlwf] FilterReturnNetBufferLists:304 <--- STATUS_SUCCESS
511420 [2]1028.16C8::2024/05/11-04:45:54.997522300 [fnlwf] FilterReturnNetBufferLists:298 ---> Filter=FFFFB70477CBEF90
511421 [2]1028.16C8::2024/05/11-04:45:54.997522500 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B07EDD0
511422 [2]1028.16C8::2024/05/11-04:45:54.997522900 [fnlwf] FilterReturnNetBufferLists:304 <--- STATUS_SUCCESS
511423 [2]1028.16C8::2024/05/11-04:45:54.997533100 [Microsoft-Windows-TCPIP]TCP: TcpReleaseIndicationList: Nbl = 0xFFFFB7046B0B6DD0.
511424 [2]1028.16C8::2024/05/11-04:45:54.997801000 [fnlwf] FilterReturnNetBufferLists:298 ---> Filter=FFFFB70477CB0F90
511425 [2]1028.16C8::2024/05/11-04:45:54.997801200 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B6DD0
511426 [2]1028.16C8::2024/05/11-04:45:54.997801500 [fnlwf] FilterReturnNetBufferLists:304 <--- STATUS_SUCCESS
511427 [2]1028.16C8::2024/05/11-04:45:54.997801900 [fnlwf] FilterReturnNetBufferLists:298 ---> Filter=FFFFB70477CBEF90
511428 [2]1028.16C8::2024/05/11-04:45:54.997802100 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B6DD0
511429 [2]1028.16C8::2024/05/11-04:45:54.997802300 [fnlwf] FilterReturnNetBufferLists:304 <--- STATUS_SUCCESS
511430 [2]1028.16C8::2024/05/11-04:45:54.997804200 [Microsoft-Windows-Winsock-AFD]recv: 0: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0x206C396DFD8, Length 32768, Seq 4115, Status 0x0(NT=STATUS_SUCCESS)
511431 [2]1028.16C8::2024/05/11-04:45:54.997805100 [Microsoft-Windows-Winsock-AFD]recv: 1: Process 0xFFFFB7046D8A70C0, Endpoint 0xFFFFB7045F2F55F0, Buffer Count 1, Buffer 0x206C396DFD8, Length 393, Seq 4116, Status 0x0(NT=STATUS_SUCCESS)
511432 [0]0000.0000::2024/05/11-04:45:55.078719200 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 0 at Tick = 592097, was scheduled for = 592086.
511433 [0]0000.0000::2024/05/11-04:45:55.078728300 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 0 for processor 0 at Tick = 592097 to Tick = 593000, OldScheduledExpiration = 5920662199 NewScheduledExpiration = 5929799429 DueTime = -9030000 Aperiodic = 1(TRUE).
511434 [2]0000.0000::2024/05/11-04:45:55.235175400 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 2 at Tick = 592253, was scheduled for = 592247.
511435 [2]0000.0000::2024/05/11-04:45:55.235186100 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 2 for processor 2 at Tick = 592253 to Tick = 594000, OldScheduledExpiration = 5922272199 NewScheduledExpiration = 5939802011 DueTime = -17470000 Aperiodic = 1(TRUE).
511436 [1]1498.0BEC::2024/05/11-04:45:55.378832000 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 1 at Tick = 592397, was scheduled for = 592000.
511437 [1]1498.0BEC::2024/05/11-04:45:55.378836100 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046EE13A60 2(DelAckTimer) timer has expired.
511438 [1]1498.0BEC::2024/05/11-04:45:55.378843600 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 1 for processor 1 at Tick = 592397 to Tick = 594000, OldScheduledExpiration = 5919805378 NewScheduledExpiration = 5939768125 DueTime = -16030000 Aperiodic = 1(TRUE).
511439 [1]1498.0BEC::2024/05/11-04:45:55.378857400 [Microsoft-Windows-TCPIP]0(IP) timer fired on processor 1 at Tick = 1184, was scheduled for = 1184.
511440 [1]1498.0BEC::2024/05/11-04:45:55.378878500 [Microsoft-Windows-TCPIP]0(IP) timer rescheduled by processor 1 for processor 0 at Tick = 1184 to Tick = 7202, OldScheduledExpiration = 5920000000 NewScheduledExpiration = 36010000000 DueTime = -30086261875 Aperiodic = 1(TRUE).
511441 [2]18B0.0258::2024/05/11-04:45:55.379167400 [Microsoft-Windows-Winsock-AFD]send: 0: Process 0xFFFFB70474B4A080, Endpoint 0xFFFFB7046DEE8410, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 209, Seq 3047, Status 0x0(NT=STATUS_SUCCESS)
511442 [2]18B0.0258::2024/05/11-04:45:55.379168200 [Microsoft-Windows-Winsock-AFD]send: 0: Process 0xFFFFB70474B4A080, Endpoint 0xFFFFB7046DEE8410, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 209, Seq 3056, Status 0x0(NT=STATUS_SUCCESS)
511443 [2]18B0.0258::2024/05/11-04:45:55.379170900 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0 send posted 209 bytes at 3258005891.
511444 [2]18B0.0258::2024/05/11-04:45:55.379173200 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046DBD64B0 stopping 7(SwsTimer) timer. 
511445 [2]18B0.0258::2024/05/11-04:45:55.379173800 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0 send transmitted 209 bytes at 3258005891.
511446 [2]18B0.0258::2024/05/11-04:45:55.379175100 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0: TCP send event, SeqNo = 3258005891, BytesSent = 209, CWnd = 58242, SndWnd = 174080, SRtt = 714, RttVar = 30, RTO = 60, RcvWnd = 12583668.
511447 [2]18B0.0258::2024/05/11-04:45:55.379229200 [Microsoft-Windows-TCPIP]TCP: connection = 0xFFFFB7046DBD64B0 send tracker enqueued a transmit. Start = 3258005891, End = 3258006100, Timestamp = 592397483, SackedBytes = 0, BytesInFlight = 209.
511448 [2]18B0.0258::2024/05/11-04:45:55.379230200 [Microsoft-Windows-TCPIP]TCP: Tail Loss Probe Event Connection = 0xFFFFB7046DBD64B0, Event = 1(TimerArmed).
511449 [2]18B0.0258::2024/05/11-04:45:55.379232200 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 2 for processor 1 at Tick = 592397 to Tick = 592407, OldScheduledExpiration = 5939768125 NewScheduledExpiration = 5923838125 DueTime = -100000 Aperiodic = 1(TRUE).
511450 [2]18B0.0258::2024/05/11-04:45:55.379233000 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046DBD64B0 0(RetransmitTimer) timer started. Scheduled to expire in 60 ms. Processor 2: LastInterruptTime 5923738125 100-ns ticks; LastMicrosecondCount 592397483 msec; CachedKQPCValue 5923974834 ticks; CachedFrequencyValue 10000000.
511451 [2]18B0.0258::2024/05/11-04:45:55.379235800 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB70477C64C60 OOB info (0(Send)): TcpIpChecksumNetBufferListInfo 0x220015, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0xB9D5C41D, NetBufferListHashInfo 0x0, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511452 [2]18B0.0258::2024/05/11-04:45:55.379271600 [Microsoft-Windows-Winsock-AFD]send: 1: Process 0xFFFFB70474B4A080, Endpoint 0xFFFFB7046DEE8410, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 209, Seq 3051, Status 0x0(NT=STATUS_SUCCESS)
511453 [2]0000.0000::2024/05/11-04:45:55.379825300 [fnlwf] FilterReceiveNetBufferLists:321 ---> Filter=FFFFB70477CBEF90
511454 [2]0000.0000::2024/05/11-04:45:55.379826300 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B8DD0
511455 [2]0000.0000::2024/05/11-04:45:55.379840900 [fnlwf] FilterReceiveNetBufferLists:350 <--- STATUS_SUCCESS
511456 [2]0000.0000::2024/05/11-04:45:55.379847200 [fnlwf] FilterReceiveNetBufferLists:321 ---> Filter=FFFFB70477CB0F90
511457 [2]0000.0000::2024/05/11-04:45:55.379847500 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B8DD0
511458 [2]0000.0000::2024/05/11-04:45:55.379855300 [fnlwf] FilterReceiveNetBufferLists:350 <--- STATUS_SUCCESS
511459 [2]0000.0000::2024/05/11-04:45:55.379858800 [Microsoft-Windows-TCPIP]Nbl 0xFFFFB7046B0B8DD0 OOB info (1(Receive)): TcpIpChecksumNetBufferListInfo 0x38, TcpLargeSendNetBufferListInfo 0x0, Ieee8021QNetBufferListInfo 0x0, NetBufferListHashValue 0xB9D5C41D, NetBufferListHashInfo 0x301, VirtualSubnetInfo 0x0, UdpSegmentationOffloadInfo/TcpRecvSegCoalesceInfo 0x0, NrtNameResolutionId/UdpRecvSegCoalesceOffloadInfo 0x0
511460 [2]0000.0000::2024/05/11-04:45:55.379873900 [Microsoft-Windows-TCPIP]INETINSPECT: Owner = 0xFFFFB7046DBD64B0, InspectHandle = 0xFFFFB7045F3BFA20, InspectType = 4(ReceiveTcpDatagram), Action = 1(Allow), Status = 0x0(NT=STATUS_SUCCESS)
511461 [2]0000.0000::2024/05/11-04:45:55.379875400 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0 send advance 209 bytes at 3258005891.
511462 [2]0000.0000::2024/05/11-04:45:55.379876800 [Microsoft-Windows-TCPIP]TCP: connection = 0xFFFFB7046DBD64B0 send tracker acked a transmit. AckNo = 3258006100, Start = 3258005891, End = 3258006100, Timestamp = 592397483, EverTransmitted = 0(FALSE), SackedBytes = 0, BytesInFlight = 0.
511463 [2]0000.0000::2024/05/11-04:45:55.379877500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0 SRTT measurement complete (tick = 592398, sample = 0 ms, new srtt = 0 ms).
511464 [2]0000.0000::2024/05/11-04:45:55.379877900 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0:  Rtt sample recorded 696 SRTT 712 RttVar 27.
511465 [2]0000.0000::2024/05/11-04:45:55.379880200 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046DBD64B0 send queue is idle. Cwnd = 58242, Processor = 2, CurrentTick = 592398, IdleTick = 592398.
511466 [2]0000.0000::2024/05/11-04:45:55.379880600 [Microsoft-Windows-TCPIP]TCP: Connection 0xFFFFB7046DBD64B0 stopping 0(RetransmitTimer) timer. 
511467 [2]0000.0000::2024/05/11-04:45:55.379881400 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0: Cumulative Ack event, SeqNo = 3258006100, BytesAcked = 0, CWnd = 58451, SndWnd = 174080, InRecovery = 0, TimeSinceLastLossMS = 0, CubicCwnd = 0, AimdCwnd = 0, K = 0, Wmax = 0, LastWmax = 0, MaxSndWnd = 174080 IsLimitedSlowStart = 0.
511468 [2]0000.0000::2024/05/11-04:45:55.379882000 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0: Cumulative Ack event, SeqNo = 3258005891, BytesAcked = 209, CWnd = 58451, SndWnd =174080.
511469 [2]0000.0000::2024/05/11-04:45:55.379882500 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0: Received data with number of bytes = 0. ThSeq = 2029314807.
511470 [2]0000.0000::2024/05/11-04:45:55.379883000 [Microsoft-Windows-TCPIP]TCP: connection 0xFFFFB7046DBD64B0 send complete 209 bytes at 3258005891 (normal).
511471 [2]0000.0000::2024/05/11-04:45:55.379883900 [Microsoft-Windows-Winsock-AFD]send: 1: Process 0xFFFFB70474B4A080, Endpoint 0xFFFFB7046DEE8410, Buffer Count 1, Buffer 0xFFFFB7046DC1B1B8, Length 209, Seq 3073, Status 0x0(NT=STATUS_SUCCESS)
511472 [2]0000.0000::2024/05/11-04:45:55.379886500 [fnlwf] FilterReturnNetBufferLists:298 ---> Filter=FFFFB70477CB0F90
511473 [2]0000.0000::2024/05/11-04:45:55.379886700 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B8DD0
511474 [2]0000.0000::2024/05/11-04:45:55.379887400 [fnlwf] FilterReturnNetBufferLists:304 <--- STATUS_SUCCESS
511475 [2]0000.0000::2024/05/11-04:45:55.379888800 [fnlwf] FilterReturnNetBufferLists:298 ---> Filter=FFFFB70477CBEF90
511476 [2]0000.0000::2024/05/11-04:45:55.379889000 [fnlwf] TraceNbls:15 Nbl=FFFFB7046B0B8DD0
511477 [2]0000.0000::2024/05/11-04:45:55.379889400 [fnlwf] FilterReturnNetBufferLists:304 <--- STATUS_SUCCESS
511478 [1]0000.0000::2024/05/11-04:45:55.391285000 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 1 at Tick = 592409, was scheduled for = 592407.
511479 [1]0000.0000::2024/05/11-04:45:55.391290800 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 1 for processor 1 at Tick = 592409 to Tick = 592457, OldScheduledExpiration = 5923838125 NewScheduledExpiration = 5924375059 DueTime = -480000 Aperiodic = 1(TRUE).
511480 [1]0000.0000::2024/05/11-04:45:55.453748300 [Microsoft-Windows-TCPIP]1(TCP) timer fired on processor 1 at Tick = 592472, was scheduled for = 592457.
511481 [1]0000.0000::2024/05/11-04:45:55.453758400 [Microsoft-Windows-TCPIP]1(TCP) timer rescheduled by processor 1 for processor 1 at Tick = 592472 to Tick = 594000, OldScheduledExpiration = 5924375059 NewScheduledExpiration = 5939799383 DueTime = -15280000 Aperiodic = 1(TRUE).
511482 [2]0004.0784::2024/05/11-04:45:55.688125200 [fnlwf] FilterPause:268 IfIndex=22
511483 [2]0004.0784::2024/05/11-04:45:55.688235800 [fnlwf] FilterSetOptions:332 IfIndex=22
511484 [2]0004.0784::2024/05/11-04:45:55.688833500 [xdplwf] XdpGenericPause:189 IfIndex=22 Datapath is pausing
511485 [2]0004.0784::2024/05/11-04:45:55.688843400 [xdplwf] XdpGenericRxPause:1232 ---> IfIndex=22
511486 [2]0004.0784::2024/05/11-04:45:55.688845200 [xdplwf] XdpGenericRxPause:1243 <--- STATUS_SUCCESS
511487 [2]0004.0784::2024/05/11-04:45:55.688845800 [xdplwf] XdpGenericTxPause:513 ---> IfIndex=22
511488 [2]0004.0784::2024/05/11-04:45:55.688846600 [xdplwf] XdpGenericTxPause:524 <--- STATUS_SUCCESS
511489 [2]0004.0784::2024/05/11-04:45:55.688850100 [xdplwf] XdpGenericPause:201 IfIndex=22 Datapath is paused
511490 [2]0004.0784::2024/05/11-04:45:55.688929400 [xdplwf] XdpGenericFilterSetOptions:477 IfIndex=22 Set datapath handlers RX=0 TX=0 Status=STATUS_SUCCESS
511491 [2]0004.0784::2024/05/11-04:45:55.689347200 [fnmp] MiniportPauseHandler:36 ---> Adapter=FFFFB70477CA4E90
511492 [2]0004.0784::2024/05/11-04:45:55.689348400 [fnmp] MiniportPauseHandler:43 <--- STATUS_SUCCESS
511493 [2]0004.0784::2024/05/11-04:45:55.689503400 [fnmp] MiniportRestartHandler:17 ---> Adapter=FFFFB70477CA4E90
511494 [2]0004.0784::2024/05/11-04:45:55.689503900 [fnmp] MiniportRestartHandler:23 <--- STATUS_SUCCESS
511495 [2]0004.0784::2024/05/11-04:45:55.689640800 [xdplwf] XdpGenericRestart:214 IfIndex=22 Datapath is restarting
511496 [2]0004.0784::2024/05/11-04:45:55.689645300 [xdplwf] XdpGenericRxRestart:1281 ---> IfIndex=22 NewMtu=16777216
511497 [2]0004.0784::2024/05/11-04:45:55.689645700 [xdplwf] XdpGenericRxRestart:1297 <--- STATUS_SUCCESS
511498 [2]0004.0784::2024/05/11-04:45:55.689646100 [xdplwf] XdpGenericTxRestart:537 ---> IfIndex=22 NewMtu=16777216
511499 [2]0004.0784::2024/05/11-04:45:55.689646500 [xdplwf] XdpGenericTxRestart:564 <--- STATUS_SUCCESS
511500 [2]0004.0784::2024/05/11-04:45:55.689650000 [xdplwf] XdpGenericRestart:239 IfIndex=22 Datapath is restarted
511501 [2]0004.0784::2024/05/11-04:45:55.689802800 [xdplwf] XdpLwfCommonOidRequest:342 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477DBEF00 Oid=10111 RequestInterface=XDP_OID_REQUEST_INTERFACE_REGULAR
511502 [2]0004.0784::2024/05/11-04:45:55.689822900 [xdplwf] XdpLwfCommonOidRequest:384 <--- 0x00000103(STATUS_PENDING)
511503 [1]0004.1268::2024/05/11-04:45:55.689843800 [xdplwf] XdpLwfOidRequestWorker:211 ---> Filter=FFFFB704652E8DC0 IoObject=FFFFB70474E392E0
511504 [1]0004.1268::2024/05/11-04:45:55.689845300 [xdplwf] XdpLwfCommonOidRequest:342 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477DBEF00 Oid=10111 RequestInterface=XDP_OID_REQUEST_INTERFACE_REGULAR
511505 [1]0004.1268::2024/05/11-04:45:55.689846300 [xdplwf] XdpLwfOidInspectRequest:321 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477DBEF00 Oid=10111
511506 [1]0004.1268::2024/05/11-04:45:55.689846900 [xdplwf] XdpLwfOffloadInspectOidRequest:289 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477DBEF00 OID=10111
511507 [1]0004.1268::2024/05/11-04:45:55.689892300 [xdplwf] XdpLwfOffloadInspectOidRequest:305 <--- 0x00000103(STATUS_PENDING)
511508 [1]0004.1268::2024/05/11-04:45:55.689892700 [xdplwf] XdpLwfOidInspectRequest:326 <--- 0x00000103(STATUS_PENDING)
511509 [1]0004.1268::2024/05/11-04:45:55.689893000 [xdplwf] XdpLwfCommonOidRequest:384 <--- 0x00000103(STATUS_PENDING)
511510 [1]0004.1268::2024/05/11-04:45:55.689893300 [xdplwf] XdpLwfOidRequestWorker:220 <--- STATUS_SUCCESS
511511 [2]0004.0120::2024/05/11-04:45:55.689907900 [rtl] XdpIoWorkItemRoutine:250 ---> WorkQueue=FFFFA48ACBAF6FC0 IoObject=FFFFB70474E392E0
511512 [2]0004.0120::2024/05/11-04:45:55.689918400 [xdplwf] XdpLwfOffloadRssInspectOidRequest:1259 ---> Filter=FFFFB704652E8DC0 Oid=10111
511513 [2]0004.0120::2024/05/11-04:45:55.689918900 [xdplwf] XdpLwfOffloadRssInspectOidRequest:1358 <--- STATUS_SUCCESS
511514 [2]0004.0120::2024/05/11-04:45:55.689919400 [xdplwf] XdpLwfOidInspectRequestOffloadComplete:288 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477DBEF00 Oid=10111 Action=XdpOidActionPass Status=STATUS_SUCCESS
511515 [2]0004.0120::2024/05/11-04:45:55.689920700 [xdplwf] XdpLwfCommonOidRequestInspectComplete:235 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477DBEF00 Oid=10111 RequestInterface=XDP_OID_REQUEST_INTERFACE_REGULAR Action=XdpOidActionPass Status=STATUS_SUCCESS
511516 [2]0004.0120::2024/05/11-04:45:55.690364500 [xdplwf] XdpLwfCommonOidRequestInspectComplete:276 <--- 0x00000103(STATUS_PENDING)
511517 [2]0004.0120::2024/05/11-04:45:55.690365000 [xdplwf] XdpLwfOidInspectRequestOffloadComplete:309 <--- STATUS_SUCCESS
511518 [2]0004.0120::2024/05/11-04:45:55.690388400 [rtl] XdpIoWorkItemRoutine:303 <--- STATUS_SUCCESS
511519 [1]0004.0784::2024/05/11-04:45:55.690426500 [fnlwf] FilterRestart:289 IfIndex=22
511520 [1]0004.0784::2024/05/11-04:45:55.691070900 [xdplwf] XdpLwfCommonOidRequest:342 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477BA4F00 Oid=1010102 RequestInterface=XDP_OID_REQUEST_INTERFACE_REGULAR
511521 [1]0004.0784::2024/05/11-04:45:55.691071800 [xdplwf] XdpLwfOidInspectRequest:321 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477BA4F00 Oid=1010102
511522 [1]0004.0784::2024/05/11-04:45:55.691072200 [xdplwf] XdpLwfOffloadInspectOidRequest:289 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477BA4F00 OID=1010102
511523 [1]0004.0784::2024/05/11-04:45:55.691104300 [xdplwf] XdpLwfOffloadInspectOidRequest:305 <--- 0x00000103(STATUS_PENDING)
511524 [1]0004.0784::2024/05/11-04:45:55.691104700 [xdplwf] XdpLwfOidInspectRequest:326 <--- 0x00000103(STATUS_PENDING)
511525 [1]0004.0784::2024/05/11-04:45:55.691105100 [xdplwf] XdpLwfCommonOidRequest:384 <--- 0x00000103(STATUS_PENDING)
511526 [2]0004.0120::2024/05/11-04:45:55.691108100 [rtl] XdpIoWorkItemRoutine:250 ---> WorkQueue=FFFFA48ACBAF6FC0 IoObject=FFFFB70474E392E0
511527 [2]0004.0120::2024/05/11-04:45:55.691122000 [xdplwf] XdpLwfOffloadRssInspectOidRequest:1259 ---> Filter=FFFFB704652E8DC0 Oid=1010102
511528 [2]0004.0120::2024/05/11-04:45:55.691122500 [xdplwf] XdpLwfOffloadRssInspectOidRequest:1358 <--- STATUS_SUCCESS
511529 [2]0004.0120::2024/05/11-04:45:55.691122900 [xdplwf] XdpLwfOidInspectRequestOffloadComplete:288 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477BA4F00 Oid=1010102 Action=XdpOidActionPass Status=STATUS_SUCCESS
511530 [2]0004.0120::2024/05/11-04:45:55.691123700 [xdplwf] XdpLwfCommonOidRequestInspectComplete:235 ---> Filter=FFFFB704652E8DC0 Request=FFFFB70477BA4F00 Oid=1010102 RequestInterface=XDP_OID_REQUEST_INTERFACE_REGULAR Action=XdpOidActionPass Status=STATUS_SUCCESS
511531 [1]0004.0784::2024/05/11-04:45:55.691565000 [Microsoft-Windows-TCPIP]Framing: NDIS restart event. Interface = 22, Compartment = 1.
511532 [1]0004.0784::2024/05/11-04:45:55.691566100 [Microsoft-Windows-TCPIP]Framing: A PNP event has been indicated. Interface: 22. Address Family: 2(IPV4). Compartment: 1. Event: 9. Data: 0.

Filtered ETW

mtfriesen commented 1 month ago

Looks like TCPIP is in the clear. Unknown what is causing the delay between TCPIP completing the pause request and FNLWF receiving a pause request.