QLOG not working in HTTP/3 server demo?

[lminiero]

Hi,

first of all, let me thank you for your code: it's been invaluable so far as a way for me to test QUIC, as I'm currently studying and prototyping it. The QLOG support in particular has been quite helpful when trying to figure out when something wasn't working. That said, it looks like no QLOG seems to be generated, for me, when I enable it in the http3_server.py demo: I'm not sure what could be the cause, since it seems to be working fine when I enable it in the DOQ demos, and the HTTP/3 client demo as well. I can't see any obvious reason for this when looking at the code, as it looks like it's enabled the same way in all demos, so it may be something deeper in the stack.

Do you have an idea for what could be the reason?

Thanks!

[rthalley]

If I run it with "-q some_directory" I see qlogs in that directory, so I can't reproduce what you are seeing. Are you sure the server is seeing requests? What version of aioquic are you using?

[lminiero]

This is with aioquic 1.0.0, installed via pip a few days ago since the one Fedora ships is still 0.9.22 and I wanted something more up-to-date. I see now that yesterday 1.1.0 has come out: I'm not sure if that would make a difference (I see no mentions of qlog in the changelog), but I can check again as soon as I update.

The server is definitely handling requests, since I was testing it with a WebTransport client and they were successfully talking to each other. Not sure if the WebTransport part is relevant (since its HTTP/3 interaction is very limited), but at least the QUIC part should see a lot of activity.

[jlaine]

Hi @lminiero I'm really puzzled by what your are describing, especially since the demo server at quic.aiortc.org is spewing (large) amounts of QLOG files. Be aware that the files only get written once a connection is closed.

Could you try adding some print() statements in QuicFileLogger to check it's actually being instantiated and its end_trace method is being called?

[lminiero]

Be aware that the files only get written once a connection is closed

Ah this could be the problem I'm encountering, I suspect. I was using this Webtransport demo page with http3_server.py, which works, but there's no way to close the connection from the page: even closing or refreshing the page doesn't seem to send a CC. CTRL-Cing http3_server.py to close it cleanly apparently is not acting as a trigger to close the connection either, as in my case the folder stays empty.

[lminiero]

Could you try adding some print() statements in QuicFileLogger to check it's actually being instantiated and its end_trace method is being called?

I can confirm that it's being instantiated, but end_trace is not called in the scenario I described in my previous comment.

[jlaine]

end_trace should be called when a QUIC connection gets closed:

https://github.com/aiortc/aioquic/blob/ff3281fa33ca14943e7954b8baf51c1e950c791d/src/aioquic/quic/connection.py#L1275

I just tried the following:

# Run the server
mkdir qlog
python examples/http3_server.py --certificate tests/ssl_cert.pem --private-key tests/ssl_key.pem --quic-log qlog

# Run the client
python examples/http3_client.py --insecure https://localhost:4433/

=> I end up with a QLOG file in the "qlog" directory

[lminiero]

Yes, I meant that with the web-based WebTransport demo, the browser never sends the CONNECTION_CLOSE after it succeeds, and I guess that closing the server with a CTRL+C doesn't internally mark the connection as closed either, which is probably why end_trace is not being called in my case. That said, I don't know if CTRL+C does indeed perform a clean ending for the demo, and if it's supposed to close all pending connections itself.

[jlaine]

I put together a proof-of-concept of what would be needed to cleanly shutdown the asyncio-based QUIC server here:

https://github.com/jlaine/aioquic/tree/http3-server-close

It would however be a breaking API change so I'm not too sure how to proceed here.

[lminiero]

@jlaine sorry, I didn't mean to cause such a ruckus :sweat_smile:

Not sure how important it would be to ensure the clean shutdown for the logs (I only noticed the issue and thought I'd point it out), especially if it requires a breaking API change to handle properly. I think it would be a good thing to have, but I'm admittedly not a regular user of the library (I'm only using it to help with the development of a different component), so I'm not one of the people that could be impacted by the change.

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.