Misc/WithKeyUpdateArgs1.KeyUpdate/0 failed

[nibanks]

Describe the bug

[----------] 1 test from Misc/WithKeyUpdateArgs1
[ RUN      ] Misc/WithKeyUpdateArgs1.KeyUpdate/0
D:\a\1\msquic\src\test\lib\HandshakeTest.cpp(2006): error: Server->GetLocalBidiStreamCount() not equal to (uint16_t)(101+i)
[  FAILED  ] Misc/WithKeyUpdateArgs1.KeyUpdate/0, where GetParam() = v4/0 (1492 ms)

When looking at quic.txt it seems that for some reason, the packet that was built with the update MAX_STREAMS was never actually flushed. I can't tell why not.

2711 [0]15F4.15C8::2022/03/11-11:40:48.787017500 [Microsoft-Quic][conn][0x1ADB1C68200] Execute: 4(FLUSH_SEND)
2712 [0]15F4.15C8::2022/03/11-11:40:48.787019800 [Microsoft-Quic][conn][0x1ADB1C68200] Flushing Send. Allowance=12200 bytes
2713 [0]15F4.15C8::2022/03/11-11:40:48.787022200 [Microsoft-Quic][pack][1099511627782] Created in batch 1099511627782
2714 [0]15F4.15C8::2022/03/11-11:40:48.787028500 [Microsoft-Quic][C][TX][18] SH DestCid:007de07a097ff4a990 KP:1 SB:1 (Payload 7 bytes)
2715 [0]15F4.15C8::2022/03/11-11:40:48.787032200 [Microsoft-Quic][C][TX][18]   MAX_STREAMS[1] Count:105
2716 [0]15F4.15C8::2022/03/11-11:40:48.787033100 [Microsoft-Quic][pack][1099511627782] Encrypting
2717 [0]15F4.15C8::2022/03/11-11:40:48.787040700 [Microsoft-Quic][pack][1099511627782] Finalizing
2718 [0]15F4.15C8::2022/03/11-11:40:48.787041600 [Microsoft-Quic][conn][0x1ADB1C68200][TX][18] 5(ONE_RTT) (33 bytes)
2719 [0]15F4.15C8::2022/03/11-11:40:48.787043100 [Microsoft-Quic][conn][0x1ADB1C68200] Setting 4(TIMER.IDLE), delay=30000000 us
2721 [0]15F4.15C8::2022/03/11-11:40:48.787046400 [Microsoft-Quic][time][000001ADB1781A70] Updating Connection 000001ADB1C68200.
2723 [0]15F4.15C8::2022/03/11-11:40:48.787049500 [Microsoft-Quic][time][000001ADB1781A70] Next Expiration = {828516882, 000001ADB1C68200}.
2725 [0]15F4.15C8::2022/03/11-11:40:48.787051300 [Microsoft-Quic][conn][0x1ADB1C68200] OUT: BytesSent=7243 InFlight=33 InFlightMax=6100 CWnd=12200 SSThresh=4294967295 ConnFC=16777216 ISB=131072 PostedBytes=0 SRtt=14630
2726 [0]15F4.15C8::2022/03/11-11:40:48.787052500 [Microsoft-Quic][conn][0x1ADB1C68200] OUT: StreamFC=0 StreamSendWindow=0
2727 [0]15F4.15C8::2022/03/11-11:40:48.787056200 [Microsoft-Quic][conn][0x1ADB1C68200] Sending batch. 1 datagrams
2728 [0]15F4.15C8::2022/03/11-11:40:48.787060800 [Microsoft-Quic][pack][1099511627782] Batch sent
2729 [0]15F4.15C8::2022/03/11-11:40:48.787062000 [Microsoft-Quic][conn][0x1ADB1C68200] Setting loss detection 2(PROBE) timer for 249980 ms. (ProbeCount=0)
2730 [0]15F4.15C8::2022/03/11-11:40:48.787062700 [Microsoft-Quic][conn][0x1ADB1C68200] Setting 2(TIMER.LOSS_DETECTION), delay=249980 us
2731 [0]15F4.15C8::2022/03/11-11:40:48.787065200 [Microsoft-Quic][time][000001ADB1781A70] Updating Connection 000001ADB1C68200.
2732 [0]15F4.15C8::2022/03/11-11:40:48.787067900 [Microsoft-Quic][time][000001ADB1781A70] Next Expiration = {798766881, 000001ADB1C68200}.
2733 [0]15F4.15C8::2022/03/11-11:40:48.787069600 [Microsoft-Quic][conn][0x1ADB1C68200] Flush complete flags=0x0

We never see a send (and corresponding receive) event on the datapath thread. We should see something like the following:

2652 [1]15F4.1AEC::2022/03/11-11:40:48.615549100 [Microsoft-Quic][data][0x1ADB1786B30] Send 36 bytes in 1 buffers (segment=1472) Dst=127.0.0.1:61360 Src=127.0.0.1:61361
2653 [0]15F4.1878::2022/03/11-11:40:48.619915900 [Microsoft-Quic][data][0x1ADB1784FD0] Recv 36 bytes (segment=36) Src=127.0.0.1:61360 Dst=127.0.0.1:61361

Affected OS

• All
• Windows Server 2022
• Windows 11
• Windows Insider Preview (specify affected build below)
• Ubuntu
• Debian
• Other (specify below)

Additional OS information

No response

MsQuic version

main

Steps taken to reproduce bug

Occasionally seen from BVTs in the CI.

Expected behavior

The datapath should be sending the packet.

Actual outcome

The datapath doesn't seem to send the packet.

Additional details

No response