// Copyright 2023 The Go Authors. All rights reserved. // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. //go:build go1.21 package quic import ( "context" "encoding/hex" "log/slog" "net/netip" "time" ) // Log levels for qlog events. const ( // QLogLevelFrame includes per-frame information. // When this level is enabled, packet_sent and packet_received events will // contain information on individual frames sent/received. QLogLevelFrame = slog.Level(-6) // QLogLevelPacket events occur at most once per packet sent or received. // // For example: packet_sent, packet_received. QLogLevelPacket = slog.Level(-4) // QLogLevelConn events occur multiple times over a connection's lifetime, // but less often than the frequency of individual packets. // // For example: connection_state_updated. QLogLevelConn = slog.Level(-2) // QLogLevelEndpoint events occur at most once per connection. // // For example: connection_started, connection_closed. QLogLevelEndpoint = slog.Level(0) ) func (c *Conn) logEnabled(level slog.Level) bool { return c.log != nil && c.log.Enabled(context.Background(), level) } // slogHexstring returns a slog.Attr for a value of the hexstring type. // // https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-1.1.1 func slogHexstring(key string, value []byte) slog.Attr { return slog.String(key, hex.EncodeToString(value)) } func slogAddr(key string, value netip.Addr) slog.Attr { return slog.String(key, value.String()) } func (c *Conn) logConnectionStarted(originalDstConnID []byte, peerAddr netip.AddrPort) { if c.config.QLogLogger == nil || !c.config.QLogLogger.Enabled(context.Background(), QLogLevelEndpoint) { return } var vantage string if c.side == clientSide { vantage = "client" originalDstConnID = c.connIDState.originalDstConnID } else { vantage = "server" } // A qlog Trace container includes some metadata (title, description, vantage_point) // and a list of Events. The Trace also includes a common_fields field setting field // values common to all events in the trace. // // Trace = { // ? title: text // ? description: text // ? configuration: Configuration // ? common_fields: CommonFields // ? vantage_point: VantagePoint // events: [* Event] // } // // To map this into slog's data model, we start each per-connection trace with a With // call that includes both the trace metadata and the common fields. // // This means that in slog's model, each trace event will also include // the Trace metadata fields (vantage_point), which is a divergence from the qlog model. c.log = c.config.QLogLogger.With( // The group_id permits associating traces taken from different vantage points // for the same connection. // // We use the original destination connection ID as the group ID. // // https://www.ietf.org/archive/id/draft-ietf-quic-qlog-main-schema-04.html#section-3.4.6 slogHexstring("group_id", originalDstConnID), slog.Group("vantage_point", slog.String("name", "go quic"), slog.String("type", vantage), ), ) localAddr := c.endpoint.LocalAddr() // https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.2 c.log.LogAttrs(context.Background(), QLogLevelEndpoint, "connectivity:connection_started", slogAddr("src_ip", localAddr.Addr()), slog.Int("src_port", int(localAddr.Port())), slogHexstring("src_cid", c.connIDState.local[0].cid), slogAddr("dst_ip", peerAddr.Addr()), slog.Int("dst_port", int(peerAddr.Port())), slogHexstring("dst_cid", c.connIDState.remote[0].cid), ) } func (c *Conn) logConnectionClosed() { if !c.logEnabled(QLogLevelEndpoint) { return } err := c.lifetime.finalErr trigger := "error" switch e := err.(type) { case *ApplicationError: // TODO: Distinguish between peer and locally-initiated close. trigger = "application" case localTransportError: switch err { case errHandshakeTimeout: trigger = "handshake_timeout" default: if e.code == errNo { trigger = "clean" } } case peerTransportError: if e.code == errNo { trigger = "clean" } default: switch err { case errIdleTimeout: trigger = "idle_timeout" case errStatelessReset: trigger = "stateless_reset" } } // https://www.ietf.org/archive/id/draft-ietf-quic-qlog-quic-events-03.html#section-4.3 c.log.LogAttrs(context.Background(), QLogLevelEndpoint, "connectivity:connection_closed", slog.String("trigger", trigger), ) } func (c *Conn) logLongPacketReceived(p longPacket, pkt []byte) { var frames slog.Attr if c.logEnabled(QLogLevelFrame) { frames = c.packetFramesAttr(p.payload) } c.log.LogAttrs(context.Background(), QLogLevelPacket, "transport:packet_received", slog.Group("header", slog.String("packet_type", p.ptype.qlogString()), slog.Uint64("packet_number", uint64(p.num)), slog.Uint64("flags", uint64(pkt[0])), slogHexstring("scid", p.srcConnID), slogHexstring("dcid", p.dstConnID), ), slog.Group("raw", slog.Int("length", len(pkt)), ), frames, ) } func (c *Conn) log1RTTPacketReceived(p shortPacket, pkt []byte) { var frames slog.Attr if c.logEnabled(QLogLevelFrame) { frames = c.packetFramesAttr(p.payload) } dstConnID, _ := dstConnIDForDatagram(pkt) c.log.LogAttrs(context.Background(), QLogLevelPacket, "transport:packet_received", slog.Group("header", slog.String("packet_type", packetType1RTT.qlogString()), slog.Uint64("packet_number", uint64(p.num)), slog.Uint64("flags", uint64(pkt[0])), slogHexstring("dcid", dstConnID), ), slog.Group("raw", slog.Int("length", len(pkt)), ), frames, ) } func (c *Conn) logPacketSent(ptype packetType, pnum packetNumber, src, dst []byte, pktLen int, payload []byte) { var frames slog.Attr if c.logEnabled(QLogLevelFrame) { frames = c.packetFramesAttr(payload) } var scid slog.Attr if len(src) > 0 { scid = slogHexstring("scid", src) } c.log.LogAttrs(context.Background(), QLogLevelPacket, "transport:packet_sent", slog.Group("header", slog.String("packet_type", ptype.qlogString()), slog.Uint64("packet_number", uint64(pnum)), scid, slogHexstring("dcid", dst), ), slog.Group("raw", slog.Int("length", pktLen), ), frames, ) } // packetFramesAttr returns the "frames" attribute containing the frames in a packet. // We currently pass this as a slog Any containing a []slog.Value, // where each Value is a debugFrame that implements slog.LogValuer. // // This isn't tremendously efficient, but avoids the need to put a JSON encoder // in the quic package or a frame parser in the qlog package. func (c *Conn) packetFramesAttr(payload []byte) slog.Attr { var frames []slog.Value for len(payload) > 0 { f, n := parseDebugFrame(payload) if n < 0 { break } payload = payload[n:] switch f := f.(type) { case debugFrameAck: // The qlog ACK frame contains the ACK Delay field as a duration. // Interpreting the contents of this field as a duration requires // knowing the peer's ack_delay_exponent transport parameter, // and it's possible for us to parse an ACK frame before we've // received that parameter. // // We could plumb connection state down into the frame parser, // but for now let's minimize the amount of code that needs to // deal with this and convert the unscaled value into a scaled one here. ackDelay := time.Duration(-1) if c.peerAckDelayExponent >= 0 { ackDelay = f.ackDelay.Duration(uint8(c.peerAckDelayExponent)) } frames = append(frames, slog.AnyValue(debugFrameScaledAck{ ranges: f.ranges, ackDelay: ackDelay, })) default: frames = append(frames, slog.AnyValue(f)) } } return slog.Any("frames", frames) }