Skip to content

Commit

Permalink
quic: basic qlog support
Browse files Browse the repository at this point in the history
Add the structure for generating and writing qlog events.

Events are generated as slog events using the structure of
the qlog events (draft-ietf-quic-qlog-quic-events-03).

The qlog package contains a slog Handler implementation
that converts the quic package events to qlog JSON.

This CL generates events for connection creation and closure.
Future CLs will add additional events.

Events follow draft-ietf-quic-qlog-quic-events-03, which
is the most recent draft supported by the qvis visualization
tool.

https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html
https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html

For golang/go#58547

Change-Id: I5fb1b7653d0257cb86726bd5bc9e8775da74686a
Reviewed-on: https://go-review.googlesource.com/c/net/+/537936
Auto-Submit: Damien Neil <dneil@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
  • Loading branch information
neild authored and gopherbot committed Nov 17, 2023
1 parent fbaf412 commit 7b5abfa
Show file tree
Hide file tree
Showing 14 changed files with 1,216 additions and 11 deletions.
17 changes: 12 additions & 5 deletions internal/quic/cmd/interop/main.go
Expand Up @@ -18,21 +18,24 @@ import (
"fmt"
"io"
"log"
"log/slog"
"net"
"net/url"
"os"
"path/filepath"
"sync"

"golang.org/x/net/internal/quic"
"golang.org/x/net/internal/quic/qlog"
)

var (
listen = flag.String("listen", "", "listen address")
cert = flag.String("cert", "", "certificate")
pkey = flag.String("key", "", "private key")
root = flag.String("root", "", "serve files from this root")
output = flag.String("output", "", "directory to write files to")
listen = flag.String("listen", "", "listen address")
cert = flag.String("cert", "", "certificate")
pkey = flag.String("key", "", "private key")
root = flag.String("root", "", "serve files from this root")
output = flag.String("output", "", "directory to write files to")
qlogdir = flag.String("qlog", "", "directory to write qlog output to")
)

func main() {
Expand All @@ -48,6 +51,10 @@ func main() {
},
MaxBidiRemoteStreams: -1,
MaxUniRemoteStreams: -1,
QLogLogger: slog.New(qlog.NewJSONHandler(qlog.HandlerOptions{
Level: quic.QLogLevelFrame,
Dir: *qlogdir,
})),
}
if *cert != "" {
c, err := tls.LoadX509KeyPair(*cert, *pkey)
Expand Down
4 changes: 2 additions & 2 deletions internal/quic/cmd/interop/run_endpoint.sh
Expand Up @@ -11,7 +11,7 @@
if [ "$ROLE" == "client" ]; then
# Wait for the simulator to start up.
/wait-for-it.sh sim:57832 -s -t 30
./interop -output=/downloads $CLIENT_PARAMS $REQUESTS
./interop -output=/downloads -qlog=$QLOGDIR $CLIENT_PARAMS $REQUESTS
elif [ "$ROLE" == "server" ]; then
./interop -cert=/certs/cert.pem -key=/certs/priv.key -listen=:443 -root=/www "$@" $SERVER_PARAMS
./interop -cert=/certs/cert.pem -key=/certs/priv.key -qlog=$QLOGDIR -listen=:443 -root=/www "$@" $SERVER_PARAMS
fi
11 changes: 11 additions & 0 deletions internal/quic/config.go
Expand Up @@ -8,6 +8,7 @@ package quic

import (
"crypto/tls"
"log/slog"
)

// A Config structure configures a QUIC endpoint.
Expand Down Expand Up @@ -72,6 +73,16 @@ type Config struct {
//
// If this field is left as zero, stateless reset is disabled.
StatelessResetKey [32]byte

// QLogLogger receives qlog events.
//
// Events currently correspond to the definitions in draft-ietf-qlog-quic-events-03.
// This is not the latest version of the draft, but is the latest version supported
// by common event log viewers as of the time this paragraph was written.
//
// The qlog package contains a slog.Handler which serializes qlog events
// to a standard JSON representation.
QLogLogger *slog.Logger
}

func configDefault(v, def, limit int64) int64 {
Expand Down
15 changes: 14 additions & 1 deletion internal/quic/conn.go
Expand Up @@ -11,6 +11,7 @@ import (
"crypto/tls"
"errors"
"fmt"
"log/slog"
"net/netip"
"time"
)
Expand Down Expand Up @@ -60,6 +61,8 @@ type Conn struct {
// Tests only: Send a PING in a specific number space.
testSendPingSpace numberSpace
testSendPing sentVal

log *slog.Logger
}

// connTestHooks override conn behavior in tests.
Expand Down Expand Up @@ -94,7 +97,7 @@ type newServerConnIDs struct {
retrySrcConnID []byte // source from server's Retry
}

func newConn(now time.Time, side connSide, cids newServerConnIDs, peerAddr netip.AddrPort, config *Config, l *Listener) (*Conn, error) {
func newConn(now time.Time, side connSide, cids newServerConnIDs, peerAddr netip.AddrPort, config *Config, l *Listener) (conn *Conn, _ error) {
c := &Conn{
side: side,
listener: l,
Expand All @@ -106,6 +109,14 @@ func newConn(now time.Time, side connSide, cids newServerConnIDs, peerAddr netip
idleTimeout: now.Add(defaultMaxIdleTimeout),
peerAckDelayExponent: -1,
}
defer func() {
// If we hit an error in newConn, close donec so tests don't get stuck waiting for it.
// This is only relevant if we've got a bug, but it makes tracking that bug down
// much easier.
if conn == nil {
close(c.donec)
}
}()

// A one-element buffer allows us to wake a Conn's event loop as a
// non-blocking operation.
Expand Down Expand Up @@ -135,6 +146,7 @@ func newConn(now time.Time, side connSide, cids newServerConnIDs, peerAddr netip
// The smallest allowed maximum QUIC datagram size is 1200 bytes.
// TODO: PMTU discovery.
const maxDatagramSize = 1200
c.logConnectionStarted(cids.originalDstConnID, peerAddr)
c.keysAppData.init()
c.loss.init(c.side, maxDatagramSize, now)
c.streamsInit()
Expand Down Expand Up @@ -259,6 +271,7 @@ func (c *Conn) loop(now time.Time) {
defer close(c.donec)
defer c.tls.Close()
defer c.listener.connDrained(c)
defer c.logConnectionClosed()

// The connection timer sends a message to the connection loop on expiry.
// We need to give it an expiry when creating it, so set the initial timeout to
Expand Down
22 changes: 20 additions & 2 deletions internal/quic/conn_close_test.go
Expand Up @@ -70,7 +70,8 @@ func TestConnCloseResponseBackoff(t *testing.T) {
}

func TestConnCloseWithPeerResponse(t *testing.T) {
tc := newTestConn(t, clientSide)
qr := &qlogRecord{}
tc := newTestConn(t, clientSide, qr.config)
tc.handshake()

tc.conn.Abort(nil)
Expand Down Expand Up @@ -99,10 +100,19 @@ func TestConnCloseWithPeerResponse(t *testing.T) {
if err := tc.conn.Wait(canceledContext()); !errors.Is(err, wantErr) {
t.Errorf("non-blocking conn.Wait() = %v, want %v", err, wantErr)
}

tc.advance(1 * time.Second) // long enough to exit the draining state
qr.wantEvents(t, jsonEvent{
"name": "connectivity:connection_closed",
"data": map[string]any{
"trigger": "application",
},
})
}

func TestConnClosePeerCloses(t *testing.T) {
tc := newTestConn(t, clientSide)
qr := &qlogRecord{}
tc := newTestConn(t, clientSide, qr.config)
tc.handshake()

wantErr := &ApplicationError{
Expand All @@ -128,6 +138,14 @@ func TestConnClosePeerCloses(t *testing.T) {
code: 9,
reason: "because",
})

tc.advance(1 * time.Second) // long enough to exit the draining state
qr.wantEvents(t, jsonEvent{
"name": "connectivity:connection_closed",
"data": map[string]any{
"trigger": "application",
},
})
}

func TestConnCloseReceiveInInitial(t *testing.T) {
Expand Down
1 change: 1 addition & 0 deletions internal/quic/conn_test.go
Expand Up @@ -198,6 +198,7 @@ func newTestConn(t *testing.T, side connSide, opts ...any) *testConn {
// The initial connection ID for the server is chosen by the client.
cids.srcConnID = testPeerConnID(0)
cids.dstConnID = testPeerConnID(-1)
cids.originalDstConnID = cids.dstConnID
}
var configTransportParams []func(*transportParameters)
var configTestConn []func(*testConn)
Expand Down
141 changes: 141 additions & 0 deletions internal/quic/qlog.go
@@ -0,0 +1,141 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

//go:build go1.21

package quic

import (
"context"
"encoding/hex"
"log/slog"
"net/netip"
)

// Log levels for qlog events.
const (
// QLogLevelFrame includes per-frame information.
// When this level is enabled, packet_sent and packet_received events will
// contain information on individual frames sent/received.
QLogLevelFrame = slog.Level(-6)

// QLogLevelPacket events occur at most once per packet sent or received.
//
// For example: packet_sent, packet_received.
QLogLevelPacket = slog.Level(-4)

// QLogLevelConn events occur multiple times over a connection's lifetime,
// but less often than the frequency of individual packets.
//
// For example: connection_state_updated.
QLogLevelConn = slog.Level(-2)

// QLogLevelEndpoint events occur at most once per connection.
//
// For example: connection_started, connection_closed.
QLogLevelEndpoint = slog.Level(0)
)

func (c *Conn) logEnabled(level slog.Level) bool {
return c.log != nil && c.log.Enabled(context.Background(), level)
}

// slogHexstring returns a slog.Attr for a value of the hexstring type.
//
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-1.1.1
func slogHexstring(key string, value []byte) slog.Attr {
return slog.String(key, hex.EncodeToString(value))
}

func slogAddr(key string, value netip.Addr) slog.Attr {
return slog.String(key, value.String())
}

func (c *Conn) logConnectionStarted(originalDstConnID []byte, peerAddr netip.AddrPort) {
if c.config.QLogLogger == nil ||
!c.config.QLogLogger.Enabled(context.Background(), QLogLevelEndpoint) {
return
}
var vantage string
if c.side == clientSide {
vantage = "client"
originalDstConnID = c.connIDState.originalDstConnID
} else {
vantage = "server"
}
// A qlog Trace container includes some metadata (title, description, vantage_point)
// and a list of Events. The Trace also includes a common_fields field setting field
// values common to all events in the trace.
//
// Trace = {
// ? title: text
// ? description: text
// ? configuration: Configuration
// ? common_fields: CommonFields
// ? vantage_point: VantagePoint
// events: [* Event]
// }
//
// To map this into slog's data model, we start each per-connection trace with a With
// call that includes both the trace metadata and the common fields.
//
// This means that in slog's model, each trace event will also include
// the Trace metadata fields (vantage_point), which is a divergence from the qlog model.
c.log = c.config.QLogLogger.With(
// The group_id permits associating traces taken from different vantage points
// for the same connection.
//
// We use the original destination connection ID as the group ID.
//
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-3.4.6
slogHexstring("group_id", originalDstConnID),
slog.Group("vantage_point",
slog.String("name", "go quic"),
slog.String("type", vantage),
),
)
localAddr := c.listener.LocalAddr()
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.2
c.log.LogAttrs(context.Background(), QLogLevelEndpoint,
"connectivity:connection_started",
slogAddr("src_ip", localAddr.Addr()),
slog.Int("src_port", int(localAddr.Port())),
slogHexstring("src_cid", c.connIDState.local[0].cid),
slogAddr("dst_ip", peerAddr.Addr()),
slog.Int("dst_port", int(peerAddr.Port())),
slogHexstring("dst_cid", c.connIDState.remote[0].cid),
)
}

func (c *Conn) logConnectionClosed() {
if !c.logEnabled(QLogLevelEndpoint) {
return
}
err := c.lifetime.finalErr
trigger := "error"
switch e := err.(type) {
case *ApplicationError:
// TODO: Distinguish between peer and locally-initiated close.
trigger = "application"
case localTransportError:
if e.code == errNo {
trigger = "clean"
}
case peerTransportError:
if e.code == errNo {
trigger = "clean"
}
default:
switch err {
case errStatelessReset:
trigger = "stateless_reset"
}
// TODO: idle_timeout, handshake_timeout
}
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.3
c.log.LogAttrs(context.Background(), QLogLevelEndpoint,
"connectivity:connection_closed",
slog.String("trigger", trigger),
)
}

0 comments on commit 7b5abfa

Please sign in to comment.