Skip to content

Commit 7b5abfa

Browse files
neildgopherbot
neild
authored and
gopherbot
committed
quic: basic qlog support
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 <[email protected]> LUCI-TryBot-Result: Go LUCI <[email protected]> Reviewed-by: Jonathan Amsterdam <[email protected]>
1 parent fbaf412 commit 7b5abfa

File tree

14 files changed

+1216
-11
lines changed

14 files changed

+1216
-11
lines changed

‎internal/quic/cmd/interop/main.go

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -18,21 +18,24 @@ import (
1818
"fmt"
1919
"io"
2020
"log"
21+
"log/slog"
2122
"net"
2223
"net/url"
2324
"os"
2425
"path/filepath"
2526
"sync"
2627

2728
"golang.org/x/net/internal/quic"
29+
"golang.org/x/net/internal/quic/qlog"
2830
)
2931

3032
var (
31-
listen = flag.String("listen", "", "listen address")
32-
cert = flag.String("cert", "", "certificate")
33-
pkey = flag.String("key", "", "private key")
34-
root = flag.String("root", "", "serve files from this root")
35-
output = flag.String("output", "", "directory to write files to")
33+
listen = flag.String("listen", "", "listen address")
34+
cert = flag.String("cert", "", "certificate")
35+
pkey = flag.String("key", "", "private key")
36+
root = flag.String("root", "", "serve files from this root")
37+
output = flag.String("output", "", "directory to write files to")
38+
qlogdir = flag.String("qlog", "", "directory to write qlog output to")
3639
)
3740

3841
func main() {
@@ -48,6 +51,10 @@ func main() {
4851
},
4952
MaxBidiRemoteStreams: -1,
5053
MaxUniRemoteStreams: -1,
54+
QLogLogger: slog.New(qlog.NewJSONHandler(qlog.HandlerOptions{
55+
Level: quic.QLogLevelFrame,
56+
Dir: *qlogdir,
57+
})),
5158
}
5259
if *cert != "" {
5360
c, err := tls.LoadX509KeyPair(*cert, *pkey)

‎internal/quic/cmd/interop/run_endpoint.sh

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@
1111
if [ "$ROLE" == "client" ]; then
1212
# Wait for the simulator to start up.
1313
/wait-for-it.sh sim:57832 -s -t 30
14-
./interop -output=/downloads $CLIENT_PARAMS $REQUESTS
14+
./interop -output=/downloads -qlog=$QLOGDIR $CLIENT_PARAMS $REQUESTS
1515
elif [ "$ROLE" == "server" ]; then
16-
./interop -cert=/certs/cert.pem -key=/certs/priv.key -listen=:443 -root=/www "$@" $SERVER_PARAMS
16+
./interop -cert=/certs/cert.pem -key=/certs/priv.key -qlog=$QLOGDIR -listen=:443 -root=/www "$@" $SERVER_PARAMS
1717
fi

‎internal/quic/config.go

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ package quic
88

99
import (
1010
"crypto/tls"
11+
"log/slog"
1112
)
1213

1314
// A Config structure configures a QUIC endpoint.
@@ -72,6 +73,16 @@ type Config struct {
7273
//
7374
// If this field is left as zero, stateless reset is disabled.
7475
StatelessResetKey [32]byte
76+
77+
// QLogLogger receives qlog events.
78+
//
79+
// Events currently correspond to the definitions in draft-ietf-qlog-quic-events-03.
80+
// This is not the latest version of the draft, but is the latest version supported
81+
// by common event log viewers as of the time this paragraph was written.
82+
//
83+
// The qlog package contains a slog.Handler which serializes qlog events
84+
// to a standard JSON representation.
85+
QLogLogger *slog.Logger
7586
}
7687

7788
func configDefault(v, def, limit int64) int64 {

‎internal/quic/conn.go

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ import (
1111
"crypto/tls"
1212
"errors"
1313
"fmt"
14+
"log/slog"
1415
"net/netip"
1516
"time"
1617
)
@@ -60,6 +61,8 @@ type Conn struct {
6061
// Tests only: Send a PING in a specific number space.
6162
testSendPingSpace numberSpace
6263
testSendPing sentVal
64+
65+
log *slog.Logger
6366
}
6467

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

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

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

263276
// The connection timer sends a message to the connection loop on expiry.
264277
// We need to give it an expiry when creating it, so set the initial timeout to

‎internal/quic/conn_close_test.go

Lines changed: 20 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,8 @@ func TestConnCloseResponseBackoff(t *testing.T) {
7070
}
7171

7272
func TestConnCloseWithPeerResponse(t *testing.T) {
73-
tc := newTestConn(t, clientSide)
73+
qr := &qlogRecord{}
74+
tc := newTestConn(t, clientSide, qr.config)
7475
tc.handshake()
7576

7677
tc.conn.Abort(nil)
@@ -99,10 +100,19 @@ func TestConnCloseWithPeerResponse(t *testing.T) {
99100
if err := tc.conn.Wait(canceledContext()); !errors.Is(err, wantErr) {
100101
t.Errorf("non-blocking conn.Wait() = %v, want %v", err, wantErr)
101102
}
103+
104+
tc.advance(1 * time.Second) // long enough to exit the draining state
105+
qr.wantEvents(t, jsonEvent{
106+
"name": "connectivity:connection_closed",
107+
"data": map[string]any{
108+
"trigger": "application",
109+
},
110+
})
102111
}
103112

104113
func TestConnClosePeerCloses(t *testing.T) {
105-
tc := newTestConn(t, clientSide)
114+
qr := &qlogRecord{}
115+
tc := newTestConn(t, clientSide, qr.config)
106116
tc.handshake()
107117

108118
wantErr := &ApplicationError{
@@ -128,6 +138,14 @@ func TestConnClosePeerCloses(t *testing.T) {
128138
code: 9,
129139
reason: "because",
130140
})
141+
142+
tc.advance(1 * time.Second) // long enough to exit the draining state
143+
qr.wantEvents(t, jsonEvent{
144+
"name": "connectivity:connection_closed",
145+
"data": map[string]any{
146+
"trigger": "application",
147+
},
148+
})
131149
}
132150

133151
func TestConnCloseReceiveInInitial(t *testing.T) {

‎internal/quic/conn_test.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -198,6 +198,7 @@ func newTestConn(t *testing.T, side connSide, opts ...any) *testConn {
198198
// The initial connection ID for the server is chosen by the client.
199199
cids.srcConnID = testPeerConnID(0)
200200
cids.dstConnID = testPeerConnID(-1)
201+
cids.originalDstConnID = cids.dstConnID
201202
}
202203
var configTransportParams []func(*transportParameters)
203204
var configTestConn []func(*testConn)

‎internal/quic/qlog.go

Lines changed: 141 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,141 @@
1+
// Copyright 2023 The Go Authors. All rights reserved.
2+
// Use of this source code is governed by a BSD-style
3+
// license that can be found in the LICENSE file.
4+
5+
//go:build go1.21
6+
7+
package quic
8+
9+
import (
10+
"context"
11+
"encoding/hex"
12+
"log/slog"
13+
"net/netip"
14+
)
15+
16+
// Log levels for qlog events.
17+
const (
18+
// QLogLevelFrame includes per-frame information.
19+
// When this level is enabled, packet_sent and packet_received events will
20+
// contain information on individual frames sent/received.
21+
QLogLevelFrame = slog.Level(-6)
22+
23+
// QLogLevelPacket events occur at most once per packet sent or received.
24+
//
25+
// For example: packet_sent, packet_received.
26+
QLogLevelPacket = slog.Level(-4)
27+
28+
// QLogLevelConn events occur multiple times over a connection's lifetime,
29+
// but less often than the frequency of individual packets.
30+
//
31+
// For example: connection_state_updated.
32+
QLogLevelConn = slog.Level(-2)
33+
34+
// QLogLevelEndpoint events occur at most once per connection.
35+
//
36+
// For example: connection_started, connection_closed.
37+
QLogLevelEndpoint = slog.Level(0)
38+
)
39+
40+
func (c *Conn) logEnabled(level slog.Level) bool {
41+
return c.log != nil && c.log.Enabled(context.Background(), level)
42+
}
43+
44+
// slogHexstring returns a slog.Attr for a value of the hexstring type.
45+
//
46+
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-1.1.1
47+
func slogHexstring(key string, value []byte) slog.Attr {
48+
return slog.String(key, hex.EncodeToString(value))
49+
}
50+
51+
func slogAddr(key string, value netip.Addr) slog.Attr {
52+
return slog.String(key, value.String())
53+
}
54+
55+
func (c *Conn) logConnectionStarted(originalDstConnID []byte, peerAddr netip.AddrPort) {
56+
if c.config.QLogLogger == nil ||
57+
!c.config.QLogLogger.Enabled(context.Background(), QLogLevelEndpoint) {
58+
return
59+
}
60+
var vantage string
61+
if c.side == clientSide {
62+
vantage = "client"
63+
originalDstConnID = c.connIDState.originalDstConnID
64+
} else {
65+
vantage = "server"
66+
}
67+
// A qlog Trace container includes some metadata (title, description, vantage_point)
68+
// and a list of Events. The Trace also includes a common_fields field setting field
69+
// values common to all events in the trace.
70+
//
71+
// Trace = {
72+
// ? title: text
73+
// ? description: text
74+
// ? configuration: Configuration
75+
// ? common_fields: CommonFields
76+
// ? vantage_point: VantagePoint
77+
// events: [* Event]
78+
// }
79+
//
80+
// To map this into slog's data model, we start each per-connection trace with a With
81+
// call that includes both the trace metadata and the common fields.
82+
//
83+
// This means that in slog's model, each trace event will also include
84+
// the Trace metadata fields (vantage_point), which is a divergence from the qlog model.
85+
c.log = c.config.QLogLogger.With(
86+
// The group_id permits associating traces taken from different vantage points
87+
// for the same connection.
88+
//
89+
// We use the original destination connection ID as the group ID.
90+
//
91+
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-3.4.6
92+
slogHexstring("group_id", originalDstConnID),
93+
slog.Group("vantage_point",
94+
slog.String("name", "go quic"),
95+
slog.String("type", vantage),
96+
),
97+
)
98+
localAddr := c.listener.LocalAddr()
99+
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.2
100+
c.log.LogAttrs(context.Background(), QLogLevelEndpoint,
101+
"connectivity:connection_started",
102+
slogAddr("src_ip", localAddr.Addr()),
103+
slog.Int("src_port", int(localAddr.Port())),
104+
slogHexstring("src_cid", c.connIDState.local[0].cid),
105+
slogAddr("dst_ip", peerAddr.Addr()),
106+
slog.Int("dst_port", int(peerAddr.Port())),
107+
slogHexstring("dst_cid", c.connIDState.remote[0].cid),
108+
)
109+
}
110+
111+
func (c *Conn) logConnectionClosed() {
112+
if !c.logEnabled(QLogLevelEndpoint) {
113+
return
114+
}
115+
err := c.lifetime.finalErr
116+
trigger := "error"
117+
switch e := err.(type) {
118+
case *ApplicationError:
119+
// TODO: Distinguish between peer and locally-initiated close.
120+
trigger = "application"
121+
case localTransportError:
122+
if e.code == errNo {
123+
trigger = "clean"
124+
}
125+
case peerTransportError:
126+
if e.code == errNo {
127+
trigger = "clean"
128+
}
129+
default:
130+
switch err {
131+
case errStatelessReset:
132+
trigger = "stateless_reset"
133+
}
134+
// TODO: idle_timeout, handshake_timeout
135+
}
136+
// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.3
137+
c.log.LogAttrs(context.Background(), QLogLevelEndpoint,
138+
"connectivity:connection_closed",
139+
slog.String("trigger", trigger),
140+
)
141+
}

0 commit comments

Comments
 (0)