Using ETW to catch QUIC issues

[joejnq]

Perhaps someone can suggest the correct way to use netsh to catch a possible bug. I started netsh as follows:
netsh.exe trace start overwrite=yes report=disabled correlation=disabled traceFile=quic.etl maxSize=2048 provider=\"{ff15e657-4f26-570e-88ab-0796b258d11c}\" level=0x5 keywords=0xffffffff

When I saw the error in my application that I wanted to analyze I entered netsh trace stop. I then converted the quic.etl file to text via command netsh trace convert quic.etl manpath=.\MsQuicEtw.man. I then used the TextAnalysisTool to inspect the resulting text file and immediately noticed that the time stamp of last item was about 8 minutes earlier than the time of the error. Admittedly, I used a maxSize which was too large. But I was simply not sure I would see the error immediately and be able to catch it.

Any suggestion on how I might be more successful in catching the point of failure with ETW than what I did?

Thanks in advance,
Joe

[nibanks]

It's hard to say, because it depends on the type of error you're looking for. You are collecting all the MsQuic logs, which can be quite verbose if you're running for an extended period of time. I recommend first trying to capture the minimal repro in the logs. From there, without any additional information about your app error, I recommend starting from the last event you got from MsQuic around that error and working backwards.

[joejnq]

It doesn't really address my question about the large time delay between when I stopped the trace and what it had collected. But I will try your idea about capturing a "minimal" amount of data first. Without knowing what the problem might be, do you have a default suggested set of keywords flags I should start with?

[nibanks]

I cannot say why there was a huge time discrepancy. I've not seen that before. As for what flags to collect, if you don't know what the problem might be, start with all of them. Cast a wide net.

[joejnq]

Most embarrassing... our client and server were not time synched. They were off by about 10 minutes from each other.

[joejnq]

I managed to capture via ETW the problem that we are seeing.

I have attached a 10 packet pcap file showing the Initial and handshake packets (in order to find the SCID and DCID fields) as well as the four short header packets that make up the entire stream. The problem is in the last packet being sent from the server (ip 172.16.1.183). We cannot decrypt this packet. From looking at the quic.txt file I cannot really identify what is wrong (my first time really using this output). I did see something strange; a TX line with text "Thrown away on shutdown". No idea what that was about.

I am hoping you can identify what might be wrong.

quic.txt.zip

[nibanks]

I believe it's a stateless reset packet. Have you added support for those on the receive side yet?

[0]0004.0ED0::2022/02/10-11:51:16.092609400 [Microsoft-Quic][S][TX][-] SR 6c71cb2627fbfd57a1098ce1b423255d

The connection you were using was aborted by the application layer above QUIC and then when we receive the next packet, we send a stateless reset in response:

[1]0004.19DC::2022/02/10-11:51:16.016220500 [Microsoft-Quic][ api] Enter 14(CONNECTION_SHUTDOWN) (0xFFFFD70F9AD87010).
[0]0004.0EC4::2022/02/10-11:51:16.016276600 [Microsoft-Quic][ api] Enter 13(CONNECTION_CLOSE) (0xFFFFD70F9AD87010).
[1]0004.0EC4::2022/02/10-11:51:16.016727200 [Microsoft-Quic][conn][0xFFFFD70F9AD87010] Destroyed
[1]0000.0000::2022/02/10-11:51:16.092518000 [Microsoft-Quic][data][0xFFFFD70F9AD6E810] Recv 32 bytes (segment=32) Src=172.16.1.183:443 Dst=172.16.0.199:39131
[0]0004.0ED0::2022/02/10-11:51:16.092609400 [Microsoft-Quic][S][TX][-] SR 6c71cb2627fbfd57a1098ce1b423255d