From a16532dbbbd907926da8398f4c416cf21a21a691 Mon Sep 17 00:00:00 2001 From: chungthuang Date: Thu, 6 Jun 2024 15:02:18 -0500 Subject: [PATCH] TUN-8451: Log QUIC flow control frames and transport parameters received --- quic/metrics.go | 54 ++++++++++++++++++++++++++++++++++++++++++------- quic/tracing.go | 51 +++++++++++++++++----------------------------- 2 files changed, 65 insertions(+), 40 deletions(-) diff --git a/quic/metrics.go b/quic/metrics.go index 666666eb..8fc8d54b 100644 --- a/quic/metrics.go +++ b/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,8 +182,10 @@ func newClientCollector(index uint8) *clientCollector { packetTooBigDropped, ) }) + return &clientCollector{ - index: uint8ToString(index), + index: index, + logger: logger, } } @@ -178,16 +193,21 @@ 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" +} diff --git a/quic/tracing.go b/quic/tracing.go index 365b8916..ab5df9d3 100644 --- a/quic/tracing.go +++ b/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 -}