From e8671a811dbc615a953d23e31f478a14f6be3cbc Mon Sep 17 00:00:00 2001 From: Viktor Liu <17948409+lixmal@users.noreply.github.com> Date: Tue, 11 Aug 2026 00:41:31 +0900 Subject: [PATCH] [client, relay] Migrate relay QUIC tracer to qlog and bump quic-go to 0.59.1 (#7124) --- go.mod | 2 +- go.sum | 4 +- shared/relay/client/dialer/quic/quic.go | 23 --- shared/relay/client/dialer/quic/quic_test.go | 145 +++++++++++++++++++ shared/relay/client/dialer/quic/tracer.go | 70 +++++++++ 5 files changed, 218 insertions(+), 26 deletions(-) create mode 100644 shared/relay/client/dialer/quic/quic_test.go create mode 100644 shared/relay/client/dialer/quic/tracer.go diff --git a/go.mod b/go.mod index 36f0a87b0..f98073417 100644 --- a/go.mod +++ b/go.mod @@ -99,7 +99,7 @@ require ( github.com/pires/go-proxyproto v0.11.0 github.com/pkg/sftp v1.13.9 github.com/prometheus/client_golang v1.23.2 - github.com/quic-go/quic-go v0.55.0 + github.com/quic-go/quic-go v0.59.1 github.com/redis/go-redis/v9 v9.7.3 github.com/rs/xid v1.3.0 github.com/shirou/gopsutil/v4 v4.25.8 diff --git a/go.sum b/go.sum index c219b0231..31e8b5454 100644 --- a/go.sum +++ b/go.sum @@ -580,8 +580,8 @@ github.com/prometheus/otlptranslator v1.0.0 h1:s0LJW/iN9dkIH+EnhiD3BlkkP5QVIUVEo github.com/prometheus/otlptranslator v1.0.0/go.mod h1:vRYWnXvI6aWGpsdY/mOT/cbeVRBlPWtBNDb7kGR3uKM= github.com/prometheus/procfs v0.19.2 h1:zUMhqEW66Ex7OXIiDkll3tl9a1ZdilUOd/F6ZXw4Vws= github.com/prometheus/procfs v0.19.2/go.mod h1:M0aotyiemPhBCM0z5w87kL22CxfcH05ZpYlu+b4J7mw= -github.com/quic-go/quic-go v0.55.0 h1:zccPQIqYCXDt5NmcEabyYvOnomjs8Tlwl7tISjJh9Mk= -github.com/quic-go/quic-go v0.55.0/go.mod h1:DR51ilwU1uE164KuWXhinFcKWGlEjzys2l8zUl5Ss1U= +github.com/quic-go/quic-go v0.59.1 h1:0Gmua0HW1Tv7ANR7hUYwRyD0MG5OJfgvYSZasGZzBic= +github.com/quic-go/quic-go v0.59.1/go.mod h1:upnsH4Ju1YkqpLXC305eW3yDZ4NfnNbmQRCMWS58IKU= github.com/redis/go-redis/v9 v9.7.3 h1:YpPyAayJV+XErNsatSElgRZZVCwXX9QzkKYNvO7x0wM= github.com/redis/go-redis/v9 v9.7.3/go.mod h1:bGUrSggJ9X9GUmZpZNEOQKaANxSGgOEBRltRTZHSvrA= github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ= diff --git a/shared/relay/client/dialer/quic/quic.go b/shared/relay/client/dialer/quic/quic.go index 2e8de8af3..cbf6ea30f 100644 --- a/shared/relay/client/dialer/quic/quic.go +++ b/shared/relay/client/dialer/quic/quic.go @@ -9,7 +9,6 @@ import ( "time" "github.com/quic-go/quic-go" - "github.com/quic-go/quic-go/logging" log "github.com/sirupsen/logrus" nbnet "github.com/netbirdio/netbird/client/net" @@ -80,28 +79,6 @@ func (d Dialer) Dial(ctx context.Context, address, serverName string) (net.Conn, return conn, nil } -// connectionTracer returns a QUIC tracer that logs the DPLPMTUD result and the -// reason a relay connection closed, so the path MTU settled on and teardown -// cause are visible in logs. Lines carry the relay address as a structured -// field, matching the rest of the relay client logging. -func connectionTracer(addr string) func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer { - relayLog := log.WithField("relay", addr) - return func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer { - return &logging.ConnectionTracer{ - UpdatedMTU: func(mtu logging.ByteCount, done bool) { - if done { - relayLog.Infof("QUIC path MTU settled at %d", mtu) - return - } - relayLog.Debugf("QUIC path MTU probing at %d", mtu) - }, - ClosedConnection: func(err error) { - relayLog.Debugf("QUIC connection closed: %v", err) - }, - } - } -} - func prepareURL(address string) (string, error) { var host string var defaultPort string diff --git a/shared/relay/client/dialer/quic/quic_test.go b/shared/relay/client/dialer/quic/quic_test.go new file mode 100644 index 000000000..af210eba2 --- /dev/null +++ b/shared/relay/client/dialer/quic/quic_test.go @@ -0,0 +1,145 @@ +package quic + +import ( + "testing" + + "github.com/quic-go/quic-go/qlog" + "github.com/quic-go/quic-go/qlogwriter" + log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" +) + +func TestCloseReason(t *testing.T) { + transportErr := qlog.TransportErrorCode(0x2) // CONNECTION_REFUSED + appErr := qlog.ApplicationErrorCode(42) + + tests := []struct { + name string + event qlog.ConnectionClosed + want string + }{ + { + // A close carrying nothing but an initiator still reads sensibly. + name: "initiator only", + event: qlog.ConnectionClosed{Initiator: qlog.InitiatorLocal}, + want: "closed by local", + }, + { + name: "transport error with trigger", + event: qlog.ConnectionClosed{ + Initiator: qlog.InitiatorRemote, + ConnectionError: &transportErr, + Trigger: qlog.ConnectionCloseTriggerIdleTimeout, + }, + want: "closed by remote, transport error: CONNECTION_REFUSED, trigger: idle_timeout", + }, + { + name: "application error with reason", + event: qlog.ConnectionClosed{ + Initiator: qlog.InitiatorLocal, + ApplicationError: &appErr, + Reason: "bye", + }, + want: "closed by local, application error: 42, reason: bye", + }, + { + // Transport and application errors are mutually exclusive in + // practice; if both are set the transport code wins. + name: "transport error takes precedence over application error", + event: qlog.ConnectionClosed{ + Initiator: qlog.InitiatorLocal, + ConnectionError: &transportErr, + ApplicationError: &appErr, + }, + want: "closed by local, transport error: CONNECTION_REFUSED", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := closeReason(tt.event); got != tt.want { + t.Errorf("closeReason() = %q, want %q", got, tt.want) + } + }) + } +} + +func TestLogSinkRecordEvent(t *testing.T) { + tests := []struct { + name string + event qlogwriter.Event + wantLevel log.Level + wantMsg string + }{ + { + name: "settled MTU is logged at info", + event: qlog.MTUUpdated{Value: 1400, Done: true}, + wantLevel: log.InfoLevel, + wantMsg: "QUIC path MTU settled at 1400", + }, + { + // Probing fires repeatedly during discovery, so it stays at debug. + name: "MTU probe is logged at debug", + event: qlog.MTUUpdated{Value: 1300, Done: false}, + wantLevel: log.DebugLevel, + wantMsg: "QUIC path MTU probing at 1300", + }, + { + name: "connection closed is logged at debug", + event: qlog.ConnectionClosed{Initiator: qlog.InitiatorRemote}, + wantLevel: log.DebugLevel, + wantMsg: "QUIC connection closed: closed by remote", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logger, hook := test.NewNullLogger() + logger.SetLevel(log.DebugLevel) + recorder := logSink{log: logger.WithField("relay", "relay.example.com:443")} + + recorder.RecordEvent(tt.event) + + entries := hook.AllEntries() + if len(entries) != 1 { + t.Fatalf("got %d log entries, want 1", len(entries)) + } + if entries[0].Level != tt.wantLevel { + t.Errorf("level = %v, want %v", entries[0].Level, tt.wantLevel) + } + if entries[0].Message != tt.wantMsg { + t.Errorf("message = %q, want %q", entries[0].Message, tt.wantMsg) + } + if relay := entries[0].Data["relay"]; relay != "relay.example.com:443" { + t.Errorf("relay field = %v, want relay.example.com:443", relay) + } + }) + } +} + +// Events the relay client does not care about must not produce log lines. +func TestLogSinkIgnoresUnhandledEvents(t *testing.T) { + logger, hook := test.NewNullLogger() + logger.SetLevel(log.DebugLevel) + recorder := logSink{log: logger.WithField("relay", "relay.example.com:443")} + + recorder.RecordEvent(qlog.PacketLost{}) + + if entries := hook.AllEntries(); len(entries) != 0 { + t.Errorf("got %d log entries, want 0", len(entries)) + } +} + +func TestLogSinkSupportsSchemas(t *testing.T) { + trace := logSink{log: log.WithField("relay", "relay.example.com:443")} + + if !trace.SupportsSchemas(qlog.EventSchema) { + t.Errorf("SupportsSchemas(%q) = false, want true", qlog.EventSchema) + } + if trace.SupportsSchemas("urn:ietf:params:qlog:events:http3-12") { + t.Error("SupportsSchemas() = true for an unrelated schema, want false") + } + if trace.AddProducer() == nil { + t.Error("AddProducer() = nil, want a recorder") + } +} diff --git a/shared/relay/client/dialer/quic/tracer.go b/shared/relay/client/dialer/quic/tracer.go new file mode 100644 index 000000000..63be09f0c --- /dev/null +++ b/shared/relay/client/dialer/quic/tracer.go @@ -0,0 +1,70 @@ +package quic + +import ( + "context" + "fmt" + "strings" + + "github.com/quic-go/quic-go" + "github.com/quic-go/quic-go/qlog" + "github.com/quic-go/quic-go/qlogwriter" + log "github.com/sirupsen/logrus" +) + +// logSink implements both qlogwriter.Trace and qlogwriter.Recorder, forwarding +// the few qlog events the relay client cares about to logrus instead of +// writing a qlog file. It holds no mutable state and logrus entries are safe +// to share, so one value can serve every producer on the connection. +type logSink struct { + log *log.Entry +} + +func (s logSink) AddProducer() qlogwriter.Recorder { return s } + +func (s logSink) SupportsSchemas(schema string) bool { return schema == qlog.EventSchema } + +func (s logSink) RecordEvent(event qlogwriter.Event) { + switch e := event.(type) { + case qlog.MTUUpdated: + if e.Done { + s.log.Infof("QUIC path MTU settled at %d", e.Value) + return + } + s.log.Debugf("QUIC path MTU probing at %d", e.Value) + case qlog.ConnectionClosed: + s.log.Debugf("QUIC connection closed: %s", closeReason(e)) + } +} + +func (s logSink) Close() error { return nil } + +// connectionTracer returns a QUIC tracer that logs the DPLPMTUD result and the +// reason a relay connection closed, so the path MTU settled on and teardown +// cause are visible in logs. Lines carry the relay address as a structured +// field, matching the rest of the relay client logging. +func connectionTracer(addr string) func(context.Context, bool, quic.ConnectionID) qlogwriter.Trace { + relayLog := log.WithField("relay", addr) + return func(context.Context, bool, quic.ConnectionID) qlogwriter.Trace { + return logSink{log: relayLog} + } +} + +// closeReason renders a ConnectionClosed event as a single line. The event +// carries the error as separate initiator, code, trigger and reason fields, +// any of which may be unset. +func closeReason(e qlog.ConnectionClosed) string { + parts := []string{fmt.Sprintf("closed by %s", e.Initiator)} + switch { + case e.ConnectionError != nil: + parts = append(parts, fmt.Sprintf("transport error: %s", *e.ConnectionError)) + case e.ApplicationError != nil: + parts = append(parts, fmt.Sprintf("application error: %d", *e.ApplicationError)) + } + if e.Trigger != "" { + parts = append(parts, fmt.Sprintf("trigger: %s", e.Trigger)) + } + if e.Reason != "" { + parts = append(parts, fmt.Sprintf("reason: %s", e.Reason)) + } + return strings.Join(parts, ", ") +}