QUIC: qlog

[KasenX]

This patch adds qlog support for QUIC.

The work was developed as part of my master's thesis at the Czech Technical University in Prague (CTU), on top of upstream nginx QUIC master. During development I split it into three branches with increasing scope: quic-qlog, quic-qlog-extended, and http3-qlog. For upstream review, this PR submits only the first and smallest branch, quic-qlog; I am also attaching the the thesis PDF for broader design and evaluation context.

Summary

• add build-time support via --with-quic_qlog_module
• add runtime configuration for per-server/per-http qlog control
• write one .sqlog file per QUIC connection
• emit JSON-SEQ qlog output
• keep qlog logic mostly isolated in dedicated ngx_event_quic_qlog.c/.h
• make qlog failures non-fatal for the connection itself

Configuration

The patch adds the following directives in http and server contexts:

• quic_qlog on|off
• quic_qlog_path <directory>
• quic_qlog_importance core|base|extra
• quic_qlog_sample <N>
• quic_qlog_max_size <size>
• quic_qlog_allow <address-or-cidr>

Design notes

• qlog state is allocated per connection only after runtime checks pass
• completed events are staged through an 8 KiB qlog buffer allocated per worker and flushed when the worker switches to processing a different connection
• if file creation or writes fail, qlog is disabled for that connection and QUIC processing continues

The implementation targets the qlog draft family used by qvis interoperability (qlog_version: 0.3, JSON-SEQ), and the resulting logs are intended to be consumed by qvis:

• draft-ietf-quic-qlog-main-schema-05: https://datatracker.ietf.org/doc/html/draft-ietf-quic-qlog-main-schema-05
• draft-ietf-quic-qlog-quic-events-03: https://datatracker.ietf.org/doc/html/draft-ietf-quic-qlog-quic-events-03
• draft-ietf-quic-qlog-h3-events-03: https://datatracker.ietf.org/doc/html/draft-ietf-quic-qlog-h3-events-03
• qvis: https://qvis.quictools.info/

Testing

Regression testing was done against the nginx Perl test suite, and qlog-specific behavior was exercised through a dedicated nginx-tests fork:

• https://github.com/KasenX/nginx-tests-qlog

Performance notes

Relative to upstream master, compiling qlog support in but leaving it disabled did not measurably affect throughput. With qlog enabled, the quic-qlog branch reduced throughput by about 8.1% on average and increased p95 latency by about 8.4%. The complete benchmark methodology and results are included in the attached thesis.

[climagabriel]

We ran this patch on production CDN traffic and hit a trace-loss bug in ngx_quic_qlog_open().

The qlog file is named by the client's source connection id (qc->path->cid) and opened with NGX_FILE_TRUNCATE. Client source cids may be zero-length — Chrome and other Chromium-based stacks use zero-length scids — so every such connection maps to the same file, <quic_qlog_path>/.sqlog, and each new connection truncates the previous trace. On a production listener the majority of traces collapse into that one file and only the last connection's trace survives. This is invisible with test clients that send non-empty scids (curl/ngtcp2, nginx-tests' Test::Nginx::HTTP3).

Naming the file by the original DCID fixes it: it is at least 8 bytes, effectively unique, and is already what ngx_quic_qlog_write_header() writes as group_id, so the filename matches the trace's group id:

--- a/src/event/quic/ngx_event_quic_qlog.c
+++ b/src/event/quic/ngx_event_quic_qlog.c
@@ static ngx_int_t ngx_quic_qlog_open(...)
-    if (qc->path == NULL || qc->path->cid == NULL) {
+    if (qc->tp.original_dcid.len == 0) {
         return NGX_ERROR;
     }
 
-    file.len = dir->len + 1 + qc->path->cid->len * 2 + sizeof(".sqlog");
+    file.len = dir->len + 1 + qc->tp.original_dcid.len * 2 + sizeof(".sqlog");
@@
-    p = ngx_hex_dump(p, qc->path->cid->id, qc->path->cid->len);
+    p = ngx_hex_dump(p, qc->tp.original_dcid.data,
+                     qc->tp.original_dcid.len);

original_dcid is set in ngx_quic_open_sockets(), which runs before the qlog init hook, so it is always available at open time.

[Copilot]

Pull request overview

This PR introduces optional QUIC qlog (JSON-SEQ) generation to nginx’s QUIC implementation, including build-time enablement and runtime configuration, with per-connection .sqlog output intended for qvis consumption.

Changes:

• Adds --with-quic_qlog_module build flag and NGX_QUIC_QLOG conditional compilation for qlog support.
• Adds new HTTP-level directives to enable/parameterize qlog (path, sampling, max size, importance, allow-list).
• Hooks qlog event emission into QUIC connection lifecycle, packet send/receive, frame parsing, loss, and metric updates.

Reviewed changes

Copilot reviewed 13 out of 13 changed files in this pull request and generated 2 comments.

Show a summary per file

File	Description
src/http/v3/ngx_http_v3_module.c	Adds HTTP/server directives for configuring QUIC qlog behavior.
src/event/quic/ngx_event_quic.h	Extends QUIC config with qlog parameters and defines qlog importance levels.
src/event/quic/ngx_event_quic.c	Hooks qlog init/start/TP events into connection creation and adds packet receive start/end logging.
src/event/quic/ngx_event_quic_transport.c	Records parsed frame length on ngx_quic_frame_t to support logging.
src/event/quic/ngx_event_quic_ssl.c	Logs remote transport parameters when received via TLS callbacks.
src/event/quic/ngx_event_quic_qlog.h	Declares qlog API and provides no-op stubs when qlog is not compiled in.
src/event/quic/ngx_event_quic_qlog.c	Implements qlog writing, buffering, and QUIC event/frame serialization.
src/event/quic/ngx_event_quic_output.c	Adds packet send start/end logging and frame logging on transmit paths; logs metric updates.
src/event/quic/ngx_event_quic_migration.c	Logs metric updates when path validation completes / RTT init occurs.
src/event/quic/ngx_event_quic_connection.h	Adds qc->qlog pointer under NGX_QUIC_QLOG.
src/event/quic/ngx_event_quic_ack.c	Logs metric updates and packet loss triggers into qlog.
auto/options	Adds --with-quic_qlog_module configure option.
auto/modules	Conditionally compiles qlog implementation and sets NGX_QUIC_QLOG.

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[KasenX]

We ran this patch on production CDN traffic and hit a trace-loss bug in ngx_quic_qlog_open().

The qlog file is named by the client's source connection id (qc->path->cid) and opened with NGX_FILE_TRUNCATE. Client source cids may be zero-length — Chrome and other Chromium-based stacks use zero-length scids — so every such connection maps to the same file, <quic_qlog_path>/.sqlog, and each new connection truncates the previous trace. On a production listener the majority of traces collapse into that one file and only the last connection's trace survives. This is invisible with test clients that send non-empty scids (curl/ngtcp2, nginx-tests' Test::Nginx::HTTP3).

Naming the file by the original DCID fixes it: it is at least 8 bytes, effectively unique, and is already what ngx_quic_qlog_write_header() writes as group_id, so the filename matches the trace's group id:

--- a/src/event/quic/ngx_event_quic_qlog.c
+++ b/src/event/quic/ngx_event_quic_qlog.c
@@ static ngx_int_t ngx_quic_qlog_open(...)
-    if (qc->path == NULL || qc->path->cid == NULL) {
+    if (qc->tp.original_dcid.len == 0) {
         return NGX_ERROR;
     }
 
-    file.len = dir->len + 1 + qc->path->cid->len * 2 + sizeof(".sqlog");
+    file.len = dir->len + 1 + qc->tp.original_dcid.len * 2 + sizeof(".sqlog");
@@
-    p = ngx_hex_dump(p, qc->path->cid->id, qc->path->cid->len);
+    p = ngx_hex_dump(p, qc->tp.original_dcid.data,
+                     qc->tp.original_dcid.len);

original_dcid is set in ngx_quic_open_sockets(), which runs before the qlog init hook, so it is always available at open time.

Thank you for catching this! I was aware that the RFC allows the client's source connection ID to be zero-length, but I falsely assumed it wouldn't happen in real-world traffic... Thanks again for the catch and the detailed write-up. Fixed.

[climagabriel]

Heads-up on a latent fd bug in ngx_event_quic_qlog.c (verified against head 88d0ac1).

qc->qlog is ngx_pcalloc'd in ngx_quic_qlog_init, so qlog->fd == 0. If ngx_quic_qlog_init_worker_buffers() fails, init returns NGX_ERROR with fd still 0 and closed still 0. The caller in ngx_event_quic.c only logs "quic qlog init failed, continuing without qlog" and leaves qc->qlog non-NULL. At teardown, ngx_quic_qlog_close guards on fd != NGX_INVALID_FILE — 0 != -1 is true — so it calls ngx_close_file(0), closing the worker's stdin. A later open()/accept() silently reuses fd 0.

Trigger is memory pressure at the first qlog connection in a worker, so it's rare, but the failure mode (cross-talk on a recycled fd 0) is nasty and silent.

Fix is two lines in ngx_quic_qlog_init:

    qc->qlog = ngx_pcalloc(c->pool, sizeof(ngx_quic_qlog_t));
    if (qc->qlog == NULL) {
        return NGX_ERROR;
    }

    qc->qlog->fd = NGX_INVALID_FILE;          /* add */

    if (ngx_quic_qlog_init_worker_buffers() != NGX_OK) {
        qc->qlog->closed = 1;                 /* add */
        return NGX_ERROR;
    }

Setting fd = NGX_INVALID_FILE right after the pcalloc closes the same hole on the ngx_pnalloc-failure path in ngx_quic_qlog_open too; the closed = 1 keeps later events from passing the ngx_quic_qlog_start_event guard with an unset buffer.

[KasenX]

Heads-up on a latent fd bug in ngx_event_quic_qlog.c (verified against head 88d0ac1).

qc->qlog is ngx_pcalloc'd in ngx_quic_qlog_init, so qlog->fd == 0. If ngx_quic_qlog_init_worker_buffers() fails, init returns NGX_ERROR with fd still 0 and closed still 0. The caller in ngx_event_quic.c only logs "quic qlog init failed, continuing without qlog" and leaves qc->qlog non-NULL. At teardown, ngx_quic_qlog_close guards on fd != NGX_INVALID_FILE — 0 != -1 is true — so it calls ngx_close_file(0), closing the worker's stdin. A later open()/accept() silently reuses fd 0.

Trigger is memory pressure at the first qlog connection in a worker, so it's rare, but the failure mode (cross-talk on a recycled fd 0) is nasty and silent.

Fix is two lines in ngx_quic_qlog_init:

    qc->qlog = ngx_pcalloc(c->pool, sizeof(ngx_quic_qlog_t));
    if (qc->qlog == NULL) {
        return NGX_ERROR;
    }

    qc->qlog->fd = NGX_INVALID_FILE;          /* add */

    if (ngx_quic_qlog_init_worker_buffers() != NGX_OK) {
        qc->qlog->closed = 1;                 /* add */
        return NGX_ERROR;
    }

Setting fd = NGX_INVALID_FILE right after the pcalloc closes the same hole on the ngx_pnalloc-failure path in ngx_quic_qlog_open too; the closed = 1 keeps later events from passing the ngx_quic_qlog_start_event guard with an unset buffer.

Thanks again for finding this, and for the suggested fix. Fixed.

[climagabriel]

Third one from running this under sustained production HTTP/3 traffic (verified against PR head 77a89e2a): a worker use-after-free in the shared qlog output buffer, reachable whenever quic_qlog_max_size is set. Unlike the earlier two this one crashes the worker, not just loses traces.

Mechanism

ngx_quic_qlog_out_owner is a per-worker static pointing at the connection that currently owns the shared output buffer. When a sampled connection's qlog crosses max_size, the flush inside ngx_quic_qlog_write() closes the fd, but ngx_quic_qlog_write_fd() returns NGX_OK. Back in ngx_quic_qlog_write() the "buffer full" path then re-acquires ownership and strands the triggering event against the now-closed qlog:

if (ngx_quic_qlog_flush(qlog) != NGX_OK) {
    return NGX_ERROR;
}

ngx_quic_qlog_out_owner = qlog;      /* re-owns a qlog the flush just closed */
...
ngx_quic_qlog_out_last = ngx_cpymem(ngx_quic_qlog_out_last, buf, size);  /* strands one event */

ngx_quic_qlog_close() then skips the flush because the fd is already invalid, so it never clears the owner:

if (qc->qlog && qc->qlog->fd != NGX_INVALID_FILE) {   /* false: fd already closed by max_size */
    (void) ngx_quic_qlog_flush(qc->qlog);
    ...
}

qc->qlog is ngx_pcalloc'd from the connection pool, so once the connection is torn down ngx_quic_qlog_out_owner dangles at freed memory with a pending event. The next sampled connection flushes it on its first header write → ngx_quic_qlog_write_fd() reads the freed qlog->fd, the write fails, and ngx_log_error() dereferences the freed qlog->log.

Evidence

Two production worker cores, both faulting in ngx_quic_qlog_write_fd while flushing the header write of a freshly created connection. Reduced to a deterministic Test::Nginx HTTP/3 reproducer, built with AddressSanitizer (line numbers are from our tree; they map to the functions above):

==ERROR: AddressSanitizer: heap-use-after-free  READ of size 4
    #0 ngx_quic_qlog_write_fd       ngx_event_quic_qlog.c   (n = ngx_write_fd(qlog->fd, ...))
    #1 ngx_quic_qlog_flush
    #2 ngx_quic_qlog_write
    #3 ngx_quic_qlog_write_header
    #4 ngx_quic_qlog_init
    #5 ngx_quic_new_connection      ngx_event_quic.c        (the NEW connection, in its handshake)
freed by thread T0 here:
    ngx_destroy_pool  <-  ngx_quic_close_connection  <-  ngx_quic_close_handler
previously allocated by thread T0 here:
    ngx_pcalloc  <-  ngx_quic_qlog_init      (qc->qlog)

Recipe: quic_qlog on; quic_qlog_sample 1; quic_qlog_max_size 20000;, one connection whose response produces more than ~8 KB of qlog (enough to fill the shared out buffer once and cross max_size), close it, then open one more connection. ASan is what makes it deterministic — on a normal build the freed connection pool is usually handed straight back to the next connection, which overwrites the dangling struct and hides the crash most of the time.

Fix

Smallest change is to not re-own a qlog the flush just closed:

if (ngx_quic_qlog_flush(qlog) != NGX_OK) {
    return NGX_ERROR;
}

if (qlog->closed) {
    return NGX_OK;      /* flush hit max_size and closed the fd; owner already cleared */
}

ngx_quic_qlog_out_owner = qlog;

Belt-and-suspenders, also have ngx_quic_qlog_close() relinquish the shared buffer even when the fd is already invalid — clear ngx_quic_qlog_out_owner and reset ngx_quic_qlog_out_last when the owner equals qc->qlog — so the owner can never outlive the connection that set it. With both changes the ASan reproducer above flips from a guaranteed crash to clean.

Both changes as a single commit on top of the current PR head (77a89e2a), build-verified with -Werror: climagabriel@5f19405 (branch quic-qlog-maxsize-uaf-fix).

[pluknet]

Thanks for the great work, I will take a look