TUN-8451: Log QUIC flow control frames and transport parameters received

Author: chungthuang

quic/metrics.go

@@ -7,6 +7,7 @@ import (
 
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/quic-go/quic-go/logging"
+	"github.com/rs/zerolog"
 )
 
 const (
@@ -18,6 +19,7 @@ var (
 	clientMetrics    = struct {
 		totalConnections  prometheus.Counter
 		closedConnections prometheus.Counter
+		maxUDPPayloadSize *prometheus.GaugeVec
 		sentFrames        *prometheus.CounterVec
 		sentBytes         *prometheus.CounterVec
 		receivedFrames    *prometheus.CounterVec
@@ -45,6 +47,15 @@ var (
 				Help:      "Number of connections that has been closed",
 			},
 		),
+		maxUDPPayloadSize: prometheus.NewGaugeVec(
+			prometheus.GaugeOpts{
+				Namespace: namespace,
+				Subsystem: "client",
+				Name:      "max_udp_payload",
+				Help:      "Maximum UDP payload size in bytes for a QUIC packet",
+			},
+			clientConnLabels,
+		),
 		sentFrames: prometheus.NewCounterVec(
 			prometheus.CounterOpts{
 				Namespace: namespace,
@@ -148,14 +159,16 @@ var (
 )
 
 type clientCollector struct {
-	index string
+	index  string
+	logger *zerolog.Logger
 }
 
-func newClientCollector(index uint8) *clientCollector {
+func newClientCollector(index string, logger *zerolog.Logger) *clientCollector {
 	registerClient.Do(func() {
 		prometheus.MustRegister(
 			clientMetrics.totalConnections,
 			clientMetrics.closedConnections,
+			clientMetrics.maxUDPPayloadSize,
 			clientMetrics.sentFrames,
 			clientMetrics.sentBytes,
 			clientMetrics.receivedFrames,
@@ -169,25 +182,32 @@ func newClientCollector(index uint8) *clientCollector {
 			packetTooBigDropped,
 		)
 	})
+
 	return &clientCollector{
-		index: uint8ToString(index),
+		index:  index,
+		logger: logger,
 	}
 }
 
 func (cc *clientCollector) startedConnection() {
 	clientMetrics.totalConnections.Inc()
 }
 
-func (cc *clientCollector) closedConnection(err error) {
+func (cc *clientCollector) closedConnection(error) {
 	clientMetrics.closedConnections.Inc()
 }
 
+func (cc *clientCollector) receivedTransportParameters(params *logging.TransportParameters) {
+	clientMetrics.maxUDPPayloadSize.WithLabelValues(cc.index).Set(float64(params.MaxUDPPayloadSize))
+	cc.logger.Debug().Msgf("Received transport parameters: MaxUDPPayloadSize=%d, MaxIdleTimeout=%v, MaxDatagramFrameSize=%d", params.MaxUDPPayloadSize, params.MaxIdleTimeout, params.MaxDatagramFrameSize)
+}
+
 func (cc *clientCollector) sentPackets(size logging.ByteCount, frames []logging.Frame) {
-	cc.collectPackets(size, frames, clientMetrics.sentFrames, clientMetrics.sentBytes)
+	cc.collectPackets(size, frames, clientMetrics.sentFrames, clientMetrics.sentBytes, sent)
 }
 
 func (cc *clientCollector) receivedPackets(size logging.ByteCount, frames []logging.Frame) {
-	cc.collectPackets(size, frames, clientMetrics.receivedFrames, clientMetrics.receivedBytes)
+	cc.collectPackets(size, frames, clientMetrics.receivedFrames, clientMetrics.receivedBytes, received)
 }
 
 func (cc *clientCollector) bufferedPackets(packetType logging.PacketType) {
@@ -212,8 +232,14 @@ func (cc *clientCollector) updatedRTT(rtt *logging.RTTStats) {
 	clientMetrics.smoothedRTT.WithLabelValues(cc.index).Set(durationToPromGauge(rtt.SmoothedRTT()))
 }
 
-func (cc *clientCollector) collectPackets(size logging.ByteCount, frames []logging.Frame, counter, bandwidth *prometheus.CounterVec) {
+func (cc *clientCollector) collectPackets(size logging.ByteCount, frames []logging.Frame, counter, bandwidth *prometheus.CounterVec, direction direction) {
 	for _, frame := range frames {
+		switch f := frame.(type) {
+		case logging.DataBlockedFrame:
+			cc.logger.Debug().Msgf("%s data_blocked frame", direction)
+		case logging.StreamDataBlockedFrame:
+			cc.logger.Debug().Int64("streamID", int64(f.StreamID)).Msgf("%s stream_data_blocked frame", direction)
+		}
 		counter.WithLabelValues(cc.index, frameName(frame)).Inc()
 	}
 	bandwidth.WithLabelValues(cc.index).Add(byteCountToPromCount(size))
@@ -227,3 +253,17 @@ func frameName(frame logging.Frame) string {
 		return strings.TrimSuffix(name, "Frame")
 	}
 }
+
+type direction uint8
+
+const (
+	sent direction = iota
+	received
+)
+
+func (d direction) String() string {
+	if d == sent {
+		return "sent"
+	}
+	return "received"
+}

quic/tracing.go

@@ -10,26 +10,20 @@ import (
 
 // QUICTracer is a wrapper to create new quicConnTracer
 type tracer struct {
+	index  string
 	logger *zerolog.Logger
-	config *tracerConfig
-}
-
-type tracerConfig struct {
-	index uint8
 }
 
 func NewClientTracer(logger *zerolog.Logger, index uint8) func(context.Context, logging.Perspective, logging.ConnectionID) *logging.ConnectionTracer {
 	t := &tracer{
+		index:  uint8ToString(index),
 		logger: logger,
-		config: &tracerConfig{
-			index: index,
-		},
 	}
 	return t.TracerForConnection
 }
 
 func (t *tracer) TracerForConnection(_ctx context.Context, _p logging.Perspective, _odcid logging.ConnectionID) *logging.ConnectionTracer {
-	return newConnTracer(newClientCollector(t.config.index))
+	return newConnTracer(newClientCollector(t.index, t.logger))
 }
 
 // connTracer collects connection level metrics
@@ -42,16 +36,17 @@ func newConnTracer(metricsCollector *clientCollector) *logging.ConnectionTracer
 		metricsCollector: metricsCollector,
 	}
 	return &logging.ConnectionTracer{
-		StartedConnection:         tracer.StartedConnection,
-		ClosedConnection:          tracer.ClosedConnection,
-		SentLongHeaderPacket:      tracer.SentLongHeaderPacket,
-		SentShortHeaderPacket:     tracer.SentShortHeaderPacket,
-		ReceivedLongHeaderPacket:  tracer.ReceivedLongHeaderPacket,
-		ReceivedShortHeaderPacket: tracer.ReceivedShortHeaderPacket,
-		BufferedPacket:            tracer.BufferedPacket,
-		DroppedPacket:             tracer.DroppedPacket,
-		UpdatedMetrics:            tracer.UpdatedMetrics,
-		LostPacket:                tracer.LostPacket,
+		StartedConnection:           tracer.StartedConnection,
+		ClosedConnection:            tracer.ClosedConnection,
+		ReceivedTransportParameters: tracer.ReceivedTransportParameters,
+		SentLongHeaderPacket:        tracer.SentLongHeaderPacket,
+		SentShortHeaderPacket:       tracer.SentShortHeaderPacket,
+		ReceivedLongHeaderPacket:    tracer.ReceivedLongHeaderPacket,
+		ReceivedShortHeaderPacket:   tracer.ReceivedShortHeaderPacket,
+		BufferedPacket:              tracer.BufferedPacket,
+		DroppedPacket:               tracer.DroppedPacket,
+		UpdatedMetrics:              tracer.UpdatedMetrics,
+		LostPacket:                  tracer.LostPacket,
 	}
 }
 
@@ -63,6 +58,10 @@ func (ct *connTracer) ClosedConnection(err error) {
 	ct.metricsCollector.closedConnection(err)
 }
 
+func (ct *connTracer) ReceivedTransportParameters(params *logging.TransportParameters) {
+	ct.metricsCollector.receivedTransportParameters(params)
+}
+
 func (ct *connTracer) BufferedPacket(pt logging.PacketType, size logging.ByteCount) {
 	ct.metricsCollector.bufferedPackets(pt)
 }
@@ -94,17 +93,3 @@ func (ct *connTracer) ReceivedLongHeaderPacket(hdr *logging.ExtendedHeader, size
 func (ct *connTracer) ReceivedShortHeaderPacket(hdr *logging.ShortHeader, size logging.ByteCount, ecn logging.ECN, frames []logging.Frame) {
 	ct.metricsCollector.receivedPackets(size, frames)
 }
-
-type quicLogger struct {
-	logger       *zerolog.Logger
-	connectionID string
-}
-
-func (qt *quicLogger) Write(p []byte) (n int, err error) {
-	qt.logger.Trace().Str("quicConnection", qt.connectionID).RawJSON("event", p).Msg("Quic event")
-	return len(p), nil
-}
-
-func (*quicLogger) Close() error {
-	return nil
-}