qlog.go

Documentation: golang.org/x/net/internal/quic

     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  	"time"
    15  )
    16  
    17  // Log levels for qlog events.
    18  const (
    19  	// QLogLevelFrame includes per-frame information.
    20  	// When this level is enabled, packet_sent and packet_received events will
    21  	// contain information on individual frames sent/received.
    22  	QLogLevelFrame = slog.Level(-6)
    23  
    24  	// QLogLevelPacket events occur at most once per packet sent or received.
    25  	//
    26  	// For example: packet_sent, packet_received.
    27  	QLogLevelPacket = slog.Level(-4)
    28  
    29  	// QLogLevelConn events occur multiple times over a connection's lifetime,
    30  	// but less often than the frequency of individual packets.
    31  	//
    32  	// For example: connection_state_updated.
    33  	QLogLevelConn = slog.Level(-2)
    34  
    35  	// QLogLevelEndpoint events occur at most once per connection.
    36  	//
    37  	// For example: connection_started, connection_closed.
    38  	QLogLevelEndpoint = slog.Level(0)
    39  )
    40  
    41  func (c *Conn) logEnabled(level slog.Level) bool {
    42  	return c.log != nil && c.log.Enabled(context.Background(), level)
    43  }
    44  
    45  // slogHexstring returns a slog.Attr for a value of the hexstring type.
    46  //
    47  // https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-1.1.1
    48  func slogHexstring(key string, value []byte) slog.Attr {
    49  	return slog.String(key, hex.EncodeToString(value))
    50  }
    51  
    52  func slogAddr(key string, value netip.Addr) slog.Attr {
    53  	return slog.String(key, value.String())
    54  }
    55  
    56  func (c *Conn) logConnectionStarted(originalDstConnID []byte, peerAddr netip.AddrPort) {
    57  	if c.config.QLogLogger == nil ||
    58  		!c.config.QLogLogger.Enabled(context.Background(), QLogLevelEndpoint) {
    59  		return
    60  	}
    61  	var vantage string
    62  	if c.side == clientSide {
    63  		vantage = "client"
    64  		originalDstConnID = c.connIDState.originalDstConnID
    65  	} else {
    66  		vantage = "server"
    67  	}
    68  	// A qlog Trace container includes some metadata (title, description, vantage_point)
    69  	// and a list of Events. The Trace also includes a common_fields field setting field
    70  	// values common to all events in the trace.
    71  	//
    72  	//	Trace = {
    73  	//	    ? title: text
    74  	//	    ? description: text
    75  	//	    ? configuration: Configuration
    76  	//	    ? common_fields: CommonFields
    77  	//	    ? vantage_point: VantagePoint
    78  	//	    events: [* Event]
    79  	//	}
    80  	//
    81  	// To map this into slog's data model, we start each per-connection trace with a With
    82  	// call that includes both the trace metadata and the common fields.
    83  	//
    84  	// This means that in slog's model, each trace event will also include
    85  	// the Trace metadata fields (vantage_point), which is a divergence from the qlog model.
    86  	c.log = c.config.QLogLogger.With(
    87  		// The group_id permits associating traces taken from different vantage points
    88  		// for the same connection.
    89  		//
    90  		// We use the original destination connection ID as the group ID.
    91  		//
    92  		// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-3.4.6
    93  		slogHexstring("group_id", originalDstConnID),
    94  		slog.Group("vantage_point",
    95  			slog.String("name", "go quic"),
    96  			slog.String("type", vantage),
    97  		),
    98  	)
    99  	localAddr := c.endpoint.LocalAddr()
   100  	// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.2
   101  	c.log.LogAttrs(context.Background(), QLogLevelEndpoint,
   102  		"connectivity:connection_started",
   103  		slogAddr("src_ip", localAddr.Addr()),
   104  		slog.Int("src_port", int(localAddr.Port())),
   105  		slogHexstring("src_cid", c.connIDState.local[0].cid),
   106  		slogAddr("dst_ip", peerAddr.Addr()),
   107  		slog.Int("dst_port", int(peerAddr.Port())),
   108  		slogHexstring("dst_cid", c.connIDState.remote[0].cid),
   109  	)
   110  }
   111  
   112  func (c *Conn) logConnectionClosed() {
   113  	if !c.logEnabled(QLogLevelEndpoint) {
   114  		return
   115  	}
   116  	err := c.lifetime.finalErr
   117  	trigger := "error"
   118  	switch e := err.(type) {
   119  	case *ApplicationError:
   120  		// TODO: Distinguish between peer and locally-initiated close.
   121  		trigger = "application"
   122  	case localTransportError:
   123  		switch err {
   124  		case errHandshakeTimeout:
   125  			trigger = "handshake_timeout"
   126  		default:
   127  			if e.code == errNo {
   128  				trigger = "clean"
   129  			}
   130  		}
   131  	case peerTransportError:
   132  		if e.code == errNo {
   133  			trigger = "clean"
   134  		}
   135  	default:
   136  		switch err {
   137  		case errIdleTimeout:
   138  			trigger = "idle_timeout"
   139  		case errStatelessReset:
   140  			trigger = "stateless_reset"
   141  		}
   142  	}
   143  	// https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.3
   144  	c.log.LogAttrs(context.Background(), QLogLevelEndpoint,
   145  		"connectivity:connection_closed",
   146  		slog.String("trigger", trigger),
   147  	)
   148  }
   149  
   150  func (c *Conn) logLongPacketReceived(p longPacket, pkt []byte) {
   151  	var frames slog.Attr
   152  	if c.logEnabled(QLogLevelFrame) {
   153  		frames = c.packetFramesAttr(p.payload)
   154  	}
   155  	c.log.LogAttrs(context.Background(), QLogLevelPacket,
   156  		"transport:packet_received",
   157  		slog.Group("header",
   158  			slog.String("packet_type", p.ptype.qlogString()),
   159  			slog.Uint64("packet_number", uint64(p.num)),
   160  			slog.Uint64("flags", uint64(pkt[0])),
   161  			slogHexstring("scid", p.srcConnID),
   162  			slogHexstring("dcid", p.dstConnID),
   163  		),
   164  		slog.Group("raw",
   165  			slog.Int("length", len(pkt)),
   166  		),
   167  		frames,
   168  	)
   169  }
   170  
   171  func (c *Conn) log1RTTPacketReceived(p shortPacket, pkt []byte) {
   172  	var frames slog.Attr
   173  	if c.logEnabled(QLogLevelFrame) {
   174  		frames = c.packetFramesAttr(p.payload)
   175  	}
   176  	dstConnID, _ := dstConnIDForDatagram(pkt)
   177  	c.log.LogAttrs(context.Background(), QLogLevelPacket,
   178  		"transport:packet_received",
   179  		slog.Group("header",
   180  			slog.String("packet_type", packetType1RTT.qlogString()),
   181  			slog.Uint64("packet_number", uint64(p.num)),
   182  			slog.Uint64("flags", uint64(pkt[0])),
   183  			slogHexstring("dcid", dstConnID),
   184  		),
   185  		slog.Group("raw",
   186  			slog.Int("length", len(pkt)),
   187  		),
   188  		frames,
   189  	)
   190  }
   191  
   192  func (c *Conn) logPacketSent(ptype packetType, pnum packetNumber, src, dst []byte, pktLen int, payload []byte) {
   193  	var frames slog.Attr
   194  	if c.logEnabled(QLogLevelFrame) {
   195  		frames = c.packetFramesAttr(payload)
   196  	}
   197  	var scid slog.Attr
   198  	if len(src) > 0 {
   199  		scid = slogHexstring("scid", src)
   200  	}
   201  	c.log.LogAttrs(context.Background(), QLogLevelPacket,
   202  		"transport:packet_sent",
   203  		slog.Group("header",
   204  			slog.String("packet_type", ptype.qlogString()),
   205  			slog.Uint64("packet_number", uint64(pnum)),
   206  			scid,
   207  			slogHexstring("dcid", dst),
   208  		),
   209  		slog.Group("raw",
   210  			slog.Int("length", pktLen),
   211  		),
   212  		frames,
   213  	)
   214  }
   215  
   216  // packetFramesAttr returns the "frames" attribute containing the frames in a packet.
   217  // We currently pass this as a slog Any containing a []slog.Value,
   218  // where each Value is a debugFrame that implements slog.LogValuer.
   219  //
   220  // This isn't tremendously efficient, but avoids the need to put a JSON encoder
   221  // in the quic package or a frame parser in the qlog package.
   222  func (c *Conn) packetFramesAttr(payload []byte) slog.Attr {
   223  	var frames []slog.Value
   224  	for len(payload) > 0 {
   225  		f, n := parseDebugFrame(payload)
   226  		if n < 0 {
   227  			break
   228  		}
   229  		payload = payload[n:]
   230  		switch f := f.(type) {
   231  		case debugFrameAck:
   232  			// The qlog ACK frame contains the ACK Delay field as a duration.
   233  			// Interpreting the contents of this field as a duration requires
   234  			// knowing the peer's ack_delay_exponent transport parameter,
   235  			// and it's possible for us to parse an ACK frame before we've
   236  			// received that parameter.
   237  			//
   238  			// We could plumb connection state down into the frame parser,
   239  			// but for now let's minimize the amount of code that needs to
   240  			// deal with this and convert the unscaled value into a scaled one here.
   241  			ackDelay := time.Duration(-1)
   242  			if c.peerAckDelayExponent >= 0 {
   243  				ackDelay = f.ackDelay.Duration(uint8(c.peerAckDelayExponent))
   244  			}
   245  			frames = append(frames, slog.AnyValue(debugFrameScaledAck{
   246  				ranges:   f.ranges,
   247  				ackDelay: ackDelay,
   248  			}))
   249  		default:
   250  			frames = append(frames, slog.AnyValue(f))
   251  		}
   252  	}
   253  	return slog.Any("frames", frames)
   254  }
   255
View as plain text