Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
mtfriesen opened this issue May 13, 2024 · 1 comment
Open

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

mtfriesen opened this issue May 13, 2024 · 1 comment
Labels
bug Something isn't working P2 tests automated test gaps and improvements
Milestone
Backlog

Comments

@mtfriesen
Copy link
Contributor

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 mtfriesen added the bug Something isn't working label May 13, 2024
@mtfriesen mtfriesen mentioned this issue May 13, 2024
Merged
@mtfriesen mtfriesen changed the title Functional test failure - NDIS pause/restart delayed Functional test failure - NDIS pause/restart delayed in GenericLwfDelayDetachRxTx May 13, 2024
@mtfriesen
Copy link
Contributor Author

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.

@mtfriesen mtfriesen added the tests automated test gaps and improvements label Jun 11, 2024
@mtfriesen mtfriesen added this to the Backlog milestone Jun 11, 2024
@mtfriesen mtfriesen added the P2 label Jun 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working P2 tests automated test gaps and improvements
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
1 participant
@mtfriesen