[client, relay] Migrate relay QUIC tracer to qlog and bump quic-go to 0.59.1 (#7124)

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

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=

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

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")
+	}
+}

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, ", ")
+}