QUIC: QLOG Draft Implementation

[hlandau]

QUIC: QLOG Draft Implementation

This is an implementation of the current QLOG draft intended to be of use to those hacking on our QUIC implementation.

An example trace loaded into qvis (namely, multistream script 2):

(For those that just want to take a quick look at what kind of output this can provide when used with qvis, here is an archive of a set of logfiles produced by running quic_multistream_test.)

Using QLOG

• Apply the patches to your branch using the instructions under “Getting the patches” below.
• Build with enable-unstable-qlog
• Set environment variable QLOGDIR= to a directory where logs should be stored
• Set environment variable QFILTER='*' to enable all events
• Run any program which uses QUIC in the built libssl (e.g. quic_multistream_test)
• Log files will appear in the specified directory. The JSON-SEQ format is used.
• You can load these log files into qvis.

For details, see:

• QUIC: Debugging and Tracing
• QLOG Design Document

The Debugging and Tracing document above also includes guidance on using packet captures and keylogs for debugging purposes, as well as on how to use QLOG.

Implementation Status

Currently supported events:

• connectivity:connection_started
• connectivity:connection_state_updated
• connectivity:connection_closed
• transport:parameters_set
• transport:packet_sent
• transport:packet_received
• recovery:packet_lost

These have been chosen as having the highest immediate utility. More will be added over time.

This implementation tracks the version of QLOG supported by qvis.

PR Status

Not intended for merge at this time as the format remains somewhat unstable.
Therefore, developers hacking on QUIC should focus on using this code to enhance their productivity, rather than reviewing this PR — though reviews are of course welcome.

We discussed the possibility of experimental feature branches (wherein incomplete features are hidden behind configure options and do not have any kind of public stability guarantee) at the Committers F2F and this would be helpful for maintaining features like this in the future.

Getting the patches

This branch will be continuously maintained for the benefit of those developing QUIC. The recommended usage pattern is for developers to cherry-pick the patches onto a branch they are developing on in order to take advantage of QLOG and enhance their productivity when troubleshooting and profiling our QUIC implementation.

The patches live at git@github.com:hlandau/openssl.git in branch quic-qlog. For convenience, the base for these patches is always kept stored as a ref at branch quic-qlog-base. This makes for easy cherry-picking (quic-qlog-base...quic-qlog).

A script called gitqlog has been developed to automate the application of these patches to arbitrary branches, and the removal of those patches again (e.g. before publishing a PR). You do not have to use this script, but reading the script may give some inspiration as to your own preferred workflow and applicable git commands. Usage of the script is at your own risk, as git environments do vary.

Let's walk through some example use cases for gitqlog:

• Applying. You want to apply the current published version of the patches to your current development branch.

  You run gitqlog apply.

  This is equivalent to:

  1. Making sure you don't already have the QLOG commits applied:

     git log --oneline -n 1000 | grep '^QLOG: '

  2. Fetching the commits into a dummy branch (overwriting any existing ref with the same name):

     $ git fetch git@github.com:hlandau/openssl.git \
        +quic-qlog:TEMP-quic-qlog +quic-qlog-base:TEMP-quic-qlog-base

  3. Cherry picking the commits onto the current branch:

     $ git cherry-pick --keep-redundant-commits \
        TEMP-quic-qlog-base...TEMP-quic-qlog

  gitqlog apply does this all for you and does the safety check to ensure you don't already have the commits applied for you.

• Dropping. You want to remove the QLOG patches from your branch.

  You run gitqlog drop.

  This is equivalent to:

  1. Running git rebase -i ${COMMIT}^, where $COMMIT is the oldest commit the commit message of which begins with QLOG: , and changing all lines in that file which begin with pick ... QLOG: to start with drop.

• Updating. You already have the QLOG patches applied and want to update them to the latest version.

  Run gitqlog drop followed by gitqlog apply.

Composition of the PR

For those that do choose to review this PR, this PR is intended to be reviewable on a commit-by-commit basis.

All commits in this PR will always have a commit message starting with QLOG: to make it easy for people to apply and then remove these commits from their own branches. The only exception are some trivial fixes discovered during development of this functionality which will also be raised in a separate PR imminently.

6336a407e7 (self/quic-qlog) QLOG: Add debugging guide
743035f9fe QLOG: Events: Implement transport:packet_received
b319709767 QLOG: Events: Implement transport:packet_sent
f35276878f QLOG: Wiring: QUIC QTX
1c57112b58 QLOG: QUIC MULTISTREAM TEST: Pass script name to QLOG
e1098334d8 QLOG: Wire title-setting code to QUIC_CHANNEL and SSL_CTX
7227b5fe79 QLOG: QUIC CHANNEL: Allow a log title to be specified
2a1472a06c QLOG: Events: Implement recovery:packet_lost
8d855c4eb8 QLOG: Wiring: QUIC TXPIM: Record the packet type
20375c0e25 QLOG: Wiring: QUIC FIFD
6ae8c6af16 QLOG: Wiring: QUIC QRX: Report the datagram ID from the DEMUX
5611e82f6a QLOG: Wiring: QUIC DEMUX: Report a monotonically increasing datagram ID
53ba0d4cad QLOG: Events: Implement connectivity:connection_closed
440032c448 QLOG: Events: Implement transport:parameters_set
a35ca594a2 QLOG: Events: Implement connectivity:connection_state_updated
0cfa07219a QLOG: Events: Implement connectivity:connection_started
26ce928edb QLOG: Wiring: QUIC CHANNEL
70ed273f9f QLOG: Frontend: Implementation
571105fad2 QLOG: Frontend: API Definition
4f50bbe045 QLOG: Frontend: Design
eda88cac21 QLOG: JSON Encoder: Tests
663140c3cc QLOG: JSON Encoder: Implementation
a452ea2a4a QLOG: Configuration
52b5c87b23 QLOG: JSON Encoder: Design
8793acf93b QUIC MULTISTREAM TEST: Correct trivial bug
4d0cdabc45 QUIC CHANNEL: Add missing duplicate TPARAM handling cases

[mattcaswell]

Note we can't merge this until we've created the 3.2 branch.

[t-j-h]

???

[hlandau]

Heh, this isn't about abort() if you're curious — at one point I was thinking we may need the ability to log entries transactionally and roll back if an error occurs during the process of logging an entry. Currently however the actual logging code is simple enough that this doesn't prove necessary.

Anyway, I forgot to remove this comment; removed.

[t-j-h]

This is nice and would be good to see in the mainline code. Just a couple of nits noted in reviewing.

[hlandau]

@t-j-h

Of course, QLOG is still a draft. Strictly speaking our policy probably doesn't prevent us putting this in because it's not a cryptographic algorithm (it's not like ad-hoc printf tracing output is governed by a standard either).

However I've actually become more conservative about this during the implementation of this PR as there are still a few nits and inconsistencies in the spec that I think will need to be worked out. I hope to find the time to write to the QUIC ML to get these addressed.

Again, we discussed the notion of experimental feature flags without stability guarantees at the committers F2F and this probably is an area we need to address strategically in the future. (But if we deem an enable-unstable-qlog flag to be adequate for now, well, I'm not going to say no...)

As the above indicates I've developed this at least for our own use for the time being. Not having this has already cost us too much productivity.

[hlandau]

For those wanting to use the packet capture based methods discussed in the Debugging and Tracing document, this tool of mine may prove useful:

https://gist.github.com/hlandau/f67b4065909913ed31da1500dc4a8719

[hlandau]

Perhaps we should have an "Experimental Features" technical policy that lets us carve things out from our stability guarantees. I could draft one. Any interest in this?

[hlandau]

Updated to rename JSON_ENC.

[hlandau]

Updated after port refactor.

[hlandau]

@t-j-h This is already gated by a configure flag enable-unstable-qlog. I don't mind it going in as is subject to that. Thoughts?

[t-j-h]

@hlandau this is not something that should require any additional actions on the part of a user to be able to enable - it is sufficiently useful and widespread used that it should be a core always-enabled capability - my view hasn't changed on this.

That the format perhaps might change over time is not an issue that should require us to leave the feature out or require a developer to jump through extra hoops to get this enabled.

[t8m]

@hlandau does the current implementation impose any overhead if built in but not used?

[hlandau]

@hlandau does the current implementation impose any overhead if built in but not used?

No.

That the format perhaps might change over time is not an issue that should require us to leave the feature out or require a developer to jump through extra hoops to get this enabled.

The format has already changed. This doesn't even implement the current draft revision because qvis doesn't implement that. So this implements a format which is already obsolete because the tool which is actually useful only supports an even older draft revision.

I don't understand the attitude here. "Let's ship this and randomly break it in an incompatible way later" is the diametrical opposite of every principle ordinarily underlying this project.

[t8m]

Yeah, I actually do not understand why do we absolutely must enable it by default. Of course it is very much useful to many of our users but having to acknowledge that the format will change in future releases by configuring with enable-unstable-qlog for now until the RFC is published - I do not see a problem with that.

Having it as unstable and off-by-default in 3.3 of course does not mean that qlog cannot be enabled by default in a future release once the format is stable.

[t8m]

I'd suggest merging this as is - i.e. with the off-by-default configure flag and handling whether it should be always on by default as a separate follow up OTC (or OMC?) decision.

[hlandau]

I have no objection to merging this as-is.