qlog.go

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