qlog.go

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