diff --git a/examples/interop/main.go b/examples/interop/main.go index cabc001..49579e2 100644 --- a/examples/interop/main.go +++ b/examples/interop/main.go @@ -16,16 +16,13 @@ import ( "math/big" "os" "os/exec" - "strings" "time" - mqlog "github.com/mengelbart/qlog" - roqqlog "github.com/mengelbart/qlog/roq" "github.com/mengelbart/roq" + "github.com/mengelbart/roq/qlog" "github.com/pion/rtp" "github.com/pion/rtp/codecs" "github.com/quic-go/quic-go" - "github.com/quic-go/quic-go/qlog" ) type flags struct { @@ -136,19 +133,7 @@ func connect(ctx context.Context, f flags, keyLog io.Writer) (*quic.Conn, error) } func runSender(f flags, conn *quic.Conn) error { - role := "server" - if !f.Server { - role = "client" - } - qlogfile := getQLOGWriter("roq", role) - if qlogfile != nil { - defer qlogfile.Close() //nolint - } - var qlogger *mqlog.Logger - if qlogfile != nil { - qlogger = mqlog.NewQLOGHandler(qlogfile, "roq qlog", "RoQ Interop tester QLOG Events", role, roqqlog.Schema) - } - s, err := newSender(roq.NewQUICGoConnection(conn), qlogger) + s, err := newSender(roq.NewQUICGoConnection(conn)) if err != nil { return err } @@ -185,22 +170,12 @@ func runSender(f flags, conn *quic.Conn) error { } func runReceiver(f flags, conn *quic.Conn) error { - role := "client" - if f.Server { - role = "server" - } - qlogfile := getQLOGWriter("roq", role) - if qlogfile != nil { - defer qlogfile.Close() //nolint - } - var qlogger *mqlog.Logger - if qlogfile != nil { - qlogger = mqlog.NewQLOGHandler(qlogfile, "roq-qlog", "RoQ Interop tester QLOG Events", role, roqqlog.Schema) - } - r, err := newReceiver(roq.NewQUICGoConnection(conn), qlogger) + r, err := newReceiver(roq.NewQUICGoConnection(conn)) if err != nil { return err } + // Closing the session finishes the qlog trace of the connection. + defer r.Close() //nolint var writer io.WriteCloser if len(f.Destination) > 0 { fileWriter, err := newFileWriter(f.Destination, f.Codec) @@ -291,25 +266,6 @@ func generateTLSConfigWithNewCert(keyLog io.Writer) (*tls.Config, error) { }, nil } -func getQLOGWriter(id, vantagePoint string) io.WriteCloser { - qlogDir := os.Getenv("QLOGDIR") - if qlogDir == "" { - return nil - } - if _, err := os.Stat(qlogDir); os.IsNotExist(err) { - if err := os.MkdirAll(qlogDir, 0o755); err != nil { - log.Fatalf("failed to create qlog dir %s: %v", qlogDir, err) - } - } - path := fmt.Sprintf("%s/%s_%s.qlog", strings.TrimRight(qlogDir, "/"), id, vantagePoint) - f, err := os.Create(path) - if err != nil { - log.Printf("Failed to create qlog file %s: %s", path, err.Error()) - return nil - } - return f -} - type bufferedWriteCloser struct { *bufio.Writer io.Closer diff --git a/examples/interop/receiver.go b/examples/interop/receiver.go index 5cb4090..0835e18 100644 --- a/examples/interop/receiver.go +++ b/examples/interop/receiver.go @@ -3,7 +3,6 @@ package main import ( "io" - "github.com/mengelbart/qlog" "github.com/mengelbart/roq" ) @@ -11,8 +10,8 @@ type receiver struct { session *roq.Session } -func newReceiver(conn roq.Connection, qlog *qlog.Logger) (*receiver, error) { - session, err := roq.NewSession(conn, true, qlog) +func newReceiver(conn roq.Connection) (*receiver, error) { + session, err := roq.NewSession(conn, true) if err != nil { return nil, err } diff --git a/examples/interop/sender.go b/examples/interop/sender.go index 23ad792..0a7af55 100644 --- a/examples/interop/sender.go +++ b/examples/interop/sender.go @@ -4,7 +4,6 @@ import ( "context" "io" - "github.com/mengelbart/qlog" "github.com/mengelbart/roq" "github.com/pion/rtp" ) @@ -25,8 +24,8 @@ type sender struct { session *roq.Session } -func newSender(conn roq.Connection, qlog *qlog.Logger) (*sender, error) { - session, err := roq.NewSession(conn, true, qlog) +func newSender(conn roq.Connection) (*sender, error) { + session, err := roq.NewSession(conn, true) if err != nil { return nil, err } diff --git a/examples/playfromdisk/main.go b/examples/playfromdisk/main.go index 3ff3232..9a98373 100644 --- a/examples/playfromdisk/main.go +++ b/examples/playfromdisk/main.go @@ -13,11 +13,11 @@ import ( "time" "github.com/mengelbart/roq" + "github.com/mengelbart/roq/qlog" "github.com/pion/rtp" "github.com/pion/rtp/codecs" "github.com/pion/webrtc/v3/pkg/media/ivfreader" "github.com/quic-go/quic-go" - "github.com/quic-go/quic-go/qlog" ) const ( @@ -81,10 +81,12 @@ func main() { if err != nil { panic(err) } - session, err := roq.NewSession(roq.NewQUICGoConnection(conn), true, nil) + session, err := roq.NewSession(roq.NewQUICGoConnection(conn), true) if err != nil { panic(err) } + // Closing the session finishes the qlog trace of the connection. + defer session.Close() //nolint flow, err := session.NewSendFlow(0) if err != nil { @@ -97,7 +99,7 @@ func main() { frame, _, ivfErr := ivf.ParseNextFrame() if errors.Is(ivfErr, io.EOF) { fmt.Printf("All video frames parsed and sent") - os.Exit(0) + return } if ivfErr != nil { diff --git a/examples/savetodisk/main.go b/examples/savetodisk/main.go index 81fbbd3..2d48427 100644 --- a/examples/savetodisk/main.go +++ b/examples/savetodisk/main.go @@ -7,10 +7,10 @@ import ( "log" "github.com/mengelbart/roq" + "github.com/mengelbart/roq/qlog" "github.com/pion/rtp" "github.com/pion/webrtc/v3/pkg/media/ivfwriter" "github.com/quic-go/quic-go" - "github.com/quic-go/quic-go/qlog" ) func main() { @@ -34,10 +34,12 @@ func main() { if err != nil { panic(err) } - session, err := roq.NewSession(roq.NewQUICGoConnection(conn), true, nil) + session, err := roq.NewSession(roq.NewQUICGoConnection(conn), true) if err != nil { panic(err) } + // Closing the session finishes the qlog trace of the connection. + defer session.Close() //nolint flow, err := session.NewReceiveFlow(0) if err != nil { panic(err) diff --git a/go.mod b/go.mod index d00aa1d..248c23b 100644 --- a/go.mod +++ b/go.mod @@ -3,7 +3,6 @@ module github.com/mengelbart/roq go 1.25.0 require ( - github.com/mengelbart/qlog v0.1.0 github.com/pion/interceptor v0.1.47 github.com/pion/rtp v1.10.5 github.com/pion/webrtc/v3 v3.3.6 diff --git a/go.sum b/go.sum index fc0bd5e..e3a5277 100644 --- a/go.sum +++ b/go.sum @@ -5,8 +5,6 @@ github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= -github.com/mengelbart/qlog v0.1.0 h1:8cDMuCMcKtzkPXUU5FF7OBwqKiy+De0GKvIvNawifoA= -github.com/mengelbart/qlog v0.1.0/go.mod h1:nIlGcUugkfDu41B8LKdAwjHQ1NxAF54D9hS2EDOlVyk= github.com/pion/interceptor v0.1.47 h1:yw8t5pJ2f8t78NgU+8EmxhaqYLXS7uFCC/tAGOaSDBo= github.com/pion/interceptor v0.1.47/go.mod h1:7yoRBzaIDETPC6cIN8Zj9EyGqHv1ImOpcTFPha6MuOM= github.com/pion/logging v0.2.4 h1:tTew+7cmQ+Mc1pTBLKH2puKsOvhm32dROumOZ655zB8= diff --git a/integrationtests/integration_test.go b/integrationtests/integration_test.go index ec4a7ce..6a300ff 100644 --- a/integrationtests/integration_test.go +++ b/integrationtests/integration_test.go @@ -26,7 +26,7 @@ func accept(t *testing.T, ctx context.Context, listener *quic.Listener) *roq.Ses conn, err := listener.Accept(ctx) assert.NoError(t, err) assert.NoError(t, err) - s, err := roq.NewSession(roq.NewQUICGoConnection(conn), true, nil) + s, err := roq.NewSession(roq.NewQUICGoConnection(conn), true) assert.NoError(t, err) return s } @@ -34,7 +34,7 @@ func accept(t *testing.T, ctx context.Context, listener *quic.Listener) *roq.Ses func dial(t *testing.T, ctx context.Context, addr string) *roq.Session { conn, err := quic.DialAddr(ctx, addr, generateTLSConfig(), &quic.Config{EnableDatagrams: true}) assert.NoError(t, err) - s, err := roq.NewSession(roq.NewQUICGoConnection(conn), true, nil) + s, err := roq.NewSession(roq.NewQUICGoConnection(conn), true) assert.NoError(t, err) return s } diff --git a/integrationtests/qlog_test.go b/integrationtests/qlog_test.go new file mode 100644 index 0000000..a6cb80e --- /dev/null +++ b/integrationtests/qlog_test.go @@ -0,0 +1,150 @@ +package integrationtests_test + +import ( + "bufio" + "bytes" + "context" + "encoding/json" + "os" + "path/filepath" + "testing" + + "github.com/mengelbart/roq" + roqqlog "github.com/mengelbart/roq/qlog" + "github.com/quic-go/quic-go" + quicqlog "github.com/quic-go/quic-go/qlog" + "github.com/quic-go/quic-go/qlogwriter" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// TestQlog runs a session over a real QUIC connection whose tracer carries the +// RoQ event schema, and checks that the RoQ events end up in the same sqlog file +// as the QUIC transport events. +func TestQlog(t *testing.T) { + qlogDir := t.TempDir() + t.Setenv("QLOGDIR", qlogDir) + config := &quic.Config{EnableDatagrams: true, Tracer: roqqlog.DefaultConnectionTracer} + + listener, err := quic.ListenAddr("localhost:0", generateTLSConfig(), config) + require.NoError(t, err) + defer listener.Close() //nolint:errcheck + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + type receiveEnd struct { + session *roq.Session + flow *roq.ReceiveFlow + } + accepted := make(chan receiveEnd, 1) + go func() { + conn, err := listener.Accept(ctx) + assert.NoError(t, err) + s, err := roq.NewSession(roq.NewQUICGoConnection(conn), true) + assert.NoError(t, err) + f, err := s.NewReceiveFlow(0) + assert.NoError(t, err) + accepted <- receiveEnd{session: s, flow: f} + }() + + conn, err := quic.DialAddr(ctx, listener.Addr().String(), generateTLSConfig(), config) + require.NoError(t, err) + sender, err := roq.NewSession(roq.NewQUICGoConnection(conn), true) + require.NoError(t, err) + + // Only send once the peer is ready to receive, so that a datagram cannot be + // dropped before its connection has finished the handshake. + receiver := <-accepted + + f, err := sender.NewSendFlow(0) + require.NoError(t, err) + stream, err := f.NewSendStream(ctx, 0, false) + require.NoError(t, err) + _, err = stream.WriteRTPBytes(make([]byte, 100)) + require.NoError(t, err) + require.NoError(t, f.WriteRTPBytes(make([]byte, 100))) + + buf := make([]byte, 2000) + for i := 0; i < 2; i++ { + _, err = receiver.flow.Read(buf) + require.NoError(t, err) + } + + // Closing the sessions releases their qlog producers, which is what closes + // and flushes the sqlog files. + require.NoError(t, sender.Close()) + require.NoError(t, receiver.session.Close()) + + files, err := filepath.Glob(filepath.Join(qlogDir, "*.sqlog")) + require.NoError(t, err) + require.Len(t, files, 2) + + var sawRoQ, sawTransport bool + for _, file := range files { + header, names := readQlog(t, file) + assert.Contains(t, header.Trace.EventSchemas, quicqlog.EventSchema) + assert.Contains(t, header.Trace.EventSchemas, roqqlog.EventSchema) + for _, name := range names { + switch name { + case "roq:stream_packet_created", "roq:datagram_packet_parsed": + sawRoQ = true + case "transport:packet_sent": + sawTransport = true + } + } + } + assert.True(t, sawRoQ, "no RoQ events in the qlog files") + assert.True(t, sawTransport, "no QUIC transport events in the qlog files") +} + +type qlogHeader struct { + Trace struct { + EventSchemas []string `json:"event_schemas"` + } `json:"trace"` +} + +// readQlog parses a JSON-SEQ qlog file into its header record and the names of +// the events that follow. +func readQlog(t *testing.T, path string) (qlogHeader, []string) { + t.Helper() + contents, err := os.ReadFile(path) + require.NoError(t, err) + + var header qlogHeader + var names []string + scanner := bufio.NewScanner(bytes.NewReader(contents)) + scanner.Buffer(make([]byte, 0, 1<<20), 1<<20) + scanner.Split(splitRecords) + for i := 0; scanner.Scan(); i++ { + if i == 0 { + require.NoError(t, json.Unmarshal(scanner.Bytes(), &header)) + continue + } + var event struct { + Name string `json:"name"` + } + require.NoError(t, json.Unmarshal(scanner.Bytes(), &event)) + names = append(names, event.Name) + } + require.NoError(t, scanner.Err()) + return header, names +} + +// splitRecords splits a JSON-SEQ stream on its record separators. +func splitRecords(data []byte, atEOF bool) (int, []byte, error) { + start := bytes.IndexByte(data, qlogwriter.RecordSeparator) + if start < 0 { + if atEOF { + return len(data), nil, nil + } + return 0, nil, nil + } + if end := bytes.IndexByte(data[start+1:], qlogwriter.RecordSeparator); end >= 0 { + return start + 1 + end, data[start+1 : start+1+end], nil + } + if atEOF { + return len(data), data[start+1:], nil + } + return 0, nil, nil +} diff --git a/options.go b/options.go index 470d0b9..d6c3015 100644 --- a/options.go +++ b/options.go @@ -1,6 +1,10 @@ package roq -import "fmt" +import ( + "fmt" + + "github.com/quic-go/quic-go/qlogwriter" +) const ( // defaultReceiveBufferSize is the number of packets buffered per receive @@ -17,6 +21,9 @@ type Option func(*sessionConfig) error type sessionConfig struct { receiveBufferSize int unknownFlowBufferSize int + qlogTrace qlogwriter.Trace + qlogPacketData bool + qlogPacketDataLimit int } // newSessionConfig applies opts on top of the defaults. @@ -26,6 +33,9 @@ func newSessionConfig(opts []Option) (*sessionConfig, error) { unknownFlowBufferSize: defaultUnknownFlowBufferSize, } for _, opt := range opts { + if opt == nil { + return nil, fmt.Errorf("%w: option must not be nil", errInvalidOption) + } if err := opt(c); err != nil { return nil, err } @@ -61,3 +71,36 @@ func WithUnknownFlowBufferSize(flows int) Option { return nil } } + +// WithQlogTrace sets the qlog trace the session logs its RoQ events to. RoQ +// events are only logged if the trace was created with the RoQ event schema, see +// [github.com/mengelbart/roq/qlog.DefaultConnectionTracer]. +// +// It is only needed for connections that do not implement QlogConnection: a +// session on a QUICGoConnection picks up the trace of the QUIC connection by +// itself. Setting it takes precedence over that. +func WithQlogTrace(t qlogwriter.Trace) Option { + return func(c *sessionConfig) error { + c.qlogTrace = t + return nil + } +} + +// WithQlogPacketData makes the session log the wire image of every RTP and RTCP +// packet it sends and receives as the data field of the raw info of its qlog +// events. maxBytes caps how many bytes of each packet are logged; zero logs the +// whole packet. The logged length is always that of the complete packet, even +// when the data is truncated. +// +// Packet data makes qlog files considerably larger, and every logged packet is +// copied on the send and receive paths, so it is off unless this option is set. +func WithQlogPacketData(maxBytes int) Option { + return func(c *sessionConfig) error { + if maxBytes < 0 { + return fmt.Errorf("%w: qlog packet data limit must not be negative, got %v", errInvalidOption, maxBytes) + } + c.qlogPacketData = true + c.qlogPacketDataLimit = maxBytes + return nil + } +} diff --git a/options_test.go b/options_test.go index 1c15a84..4078677 100644 --- a/options_test.go +++ b/options_test.go @@ -11,7 +11,7 @@ import ( // Without options a session uses the documented defaults. func TestSessionDefaultKnobs(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -33,7 +33,7 @@ func TestSessionDefaultKnobs(t *testing.T) { // flows the session creates for unknown flow IDs. func TestWithReceiveBufferSize(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil, WithReceiveBufferSize(4)) + s, err := NewSession(c, true, WithReceiveBufferSize(4)) if err != nil { t.Fatal(err) } @@ -59,7 +59,7 @@ func TestWithReceiveBufferSize(t *testing.T) { // WithUnknownFlowBufferSize must bound how many unclaimed flows are buffered. func TestWithUnknownFlowBufferSize(t *testing.T) { c := newStubConn() - s, err := NewSessionWithAppHandledConn(c, true, nil, WithUnknownFlowBufferSize(2)) + s, err := NewSessionWithAppHandledConn(c, true, WithUnknownFlowBufferSize(2)) if err != nil { t.Fatal(err) } @@ -93,12 +93,14 @@ func TestInvalidOptions(t *testing.T) { {"negative receive buffer", WithReceiveBufferSize(-1)}, {"zero unknown flow buffer", WithUnknownFlowBufferSize(0)}, {"negative unknown flow buffer", WithUnknownFlowBufferSize(-1)}, + {"negative qlog packet data limit", WithQlogPacketData(-1)}, + {"nil option", nil}, } { t.Run(tc.name, func(t *testing.T) { - if _, err := NewSession(newStubConn(), true, nil, tc.opt); !errors.Is(err, errInvalidOption) { + if _, err := NewSession(newStubConn(), true, tc.opt); !errors.Is(err, errInvalidOption) { t.Errorf("NewSession error = %v, want errInvalidOption", err) } - if _, err := NewSessionWithAppHandledConn(newStubConn(), true, nil, tc.opt); !errors.Is(err, errInvalidOption) { + if _, err := NewSessionWithAppHandledConn(newStubConn(), true, tc.opt); !errors.Is(err, errInvalidOption) { t.Errorf("NewSessionWithAppHandledConn error = %v, want errInvalidOption", err) } }) diff --git a/qlog/event.go b/qlog/event.go new file mode 100644 index 0000000..9f50f58 --- /dev/null +++ b/qlog/event.go @@ -0,0 +1,179 @@ +package qlog + +import ( + "encoding/hex" + "time" + + "github.com/quic-go/quic-go/qlogwriter/jsontext" +) + +// encoderHelper writes tokens to an encoder, remembering the first error so that +// a sequence of writes only has to be checked once. +type encoderHelper struct { + enc *jsontext.Encoder + err error +} + +func (h *encoderHelper) WriteToken(t jsontext.Token) { + if h.err != nil { + return + } + h.err = h.enc.WriteToken(t) +} + +// RawInfo describes the wire image of a packet. +type RawInfo struct { + // Length is the length of the packet as it appears on the wire, including + // the RoQ framing around it: the length prefix on a stream, or the flow ID + // on a datagram. The flow ID of a stream is sent once, ahead of its first + // packet, and is not counted. + Length uint64 + // PayloadLength is the length of the RTP or RTCP packet, without any RoQ + // framing. + PayloadLength uint64 + // Data is the packet as it appears on the wire, of Length bytes. It is + // logged as a hex string and omitted when nil, which is what a Session + // does unless it was created with roq.WithQlogPacketData. It may be + // shorter than Length, because the session can be configured to keep only + // the first few bytes of each packet. + Data []byte +} + +func (i RawInfo) HasValues() bool { + return i.Length != 0 || i.PayloadLength != 0 || len(i.Data) > 0 +} + +func (i RawInfo) encode(enc *jsontext.Encoder) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + if i.Length != 0 { + h.WriteToken(jsontext.String("length")) + h.WriteToken(jsontext.Uint(i.Length)) + } + if i.PayloadLength != 0 { + h.WriteToken(jsontext.String("payload_length")) + h.WriteToken(jsontext.Uint(i.PayloadLength)) + } + if len(i.Data) > 0 { + h.WriteToken(jsontext.String("data")) + h.WriteToken(jsontext.String(hex.EncodeToString(i.Data))) + } + h.WriteToken(jsontext.EndObject) + return h.err +} + +// Packet is the RoQ packet an event refers to. +type Packet struct { + FlowID uint64 + // Length is the length of the packet as it appears on the wire, including + // the RoQ framing around it: the length prefix on a stream, or the flow ID + // on a datagram. + Length uint64 + Raw RawInfo +} + +func (p Packet) encode(enc *jsontext.Encoder) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("flow_id")) + h.WriteToken(jsontext.Uint(p.FlowID)) + h.WriteToken(jsontext.String("length")) + h.WriteToken(jsontext.Uint(p.Length)) + if p.Raw.HasValues() { + h.WriteToken(jsontext.String("raw")) + if h.err == nil { + h.err = p.Raw.encode(enc) + } + } + h.WriteToken(jsontext.EndObject) + return h.err +} + +// StreamOpened is logged when a stream is opened for a flow. +type StreamOpened struct { + FlowID uint64 + StreamID uint64 +} + +func (e StreamOpened) Name() string { return "roq:stream_opened" } + +func (e StreamOpened) Encode(enc *jsontext.Encoder, _ time.Time) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("flow_id")) + h.WriteToken(jsontext.Uint(e.FlowID)) + h.WriteToken(jsontext.String("stream_id")) + h.WriteToken(jsontext.Uint(e.StreamID)) + h.WriteToken(jsontext.EndObject) + return h.err +} + +// StreamPacketCreated is logged when a packet is written to a stream. +type StreamPacketCreated struct { + StreamID uint64 + Packet Packet +} + +func (e StreamPacketCreated) Name() string { return "roq:stream_packet_created" } + +func (e StreamPacketCreated) Encode(enc *jsontext.Encoder, _ time.Time) error { + return encodeStreamPacket(enc, e.StreamID, e.Packet) +} + +// StreamPacketParsed is logged when a packet is read from a stream. +type StreamPacketParsed struct { + StreamID uint64 + Packet Packet +} + +func (e StreamPacketParsed) Name() string { return "roq:stream_packet_parsed" } + +func (e StreamPacketParsed) Encode(enc *jsontext.Encoder, _ time.Time) error { + return encodeStreamPacket(enc, e.StreamID, e.Packet) +} + +func encodeStreamPacket(enc *jsontext.Encoder, streamID uint64, packet Packet) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("stream_id")) + h.WriteToken(jsontext.Uint(streamID)) + h.WriteToken(jsontext.String("packet")) + if h.err == nil { + h.err = packet.encode(enc) + } + h.WriteToken(jsontext.EndObject) + return h.err +} + +// DatagramPacketCreated is logged when a packet is sent as a datagram. +type DatagramPacketCreated struct { + Packet Packet +} + +func (e DatagramPacketCreated) Name() string { return "roq:datagram_packet_created" } + +func (e DatagramPacketCreated) Encode(enc *jsontext.Encoder, _ time.Time) error { + return encodeDatagramPacket(enc, e.Packet) +} + +// DatagramPacketParsed is logged when a datagram is received. +type DatagramPacketParsed struct { + Packet Packet +} + +func (e DatagramPacketParsed) Name() string { return "roq:datagram_packet_parsed" } + +func (e DatagramPacketParsed) Encode(enc *jsontext.Encoder, _ time.Time) error { + return encodeDatagramPacket(enc, e.Packet) +} + +func encodeDatagramPacket(enc *jsontext.Encoder, packet Packet) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("packet")) + if h.err == nil { + h.err = packet.encode(enc) + } + h.WriteToken(jsontext.EndObject) + return h.err +} diff --git a/qlog/event_test.go b/qlog/event_test.go new file mode 100644 index 0000000..0011a60 --- /dev/null +++ b/qlog/event_test.go @@ -0,0 +1,107 @@ +package qlog + +import ( + "bytes" + "strings" + "testing" + "time" + + "github.com/quic-go/quic-go/qlogwriter" + "github.com/quic-go/quic-go/qlogwriter/jsontext" +) + +func encode(t *testing.T, e qlogwriter.Event) string { + t.Helper() + buf := &bytes.Buffer{} + if err := e.Encode(jsontext.NewEncoder(buf), time.Now()); err != nil { + t.Fatalf("Encode: %v", err) + } + // The encoder terminates each top-level value with a newline. + return strings.TrimSuffix(buf.String(), "\n") +} + +func TestEventEncoding(t *testing.T) { + for _, tc := range []struct { + name string + event qlogwriter.Event + want string + }{ + { + name: "stream opened", + event: StreamOpened{FlowID: 1, StreamID: 2}, + want: `{"flow_id":1,"stream_id":2}`, + }, + { + name: "stream packet created", + event: StreamPacketCreated{ + StreamID: 4, + Packet: Packet{FlowID: 1, Length: 1203, Raw: RawInfo{Length: 1203, PayloadLength: 1200}}, + }, + want: `{"stream_id":4,"packet":{"flow_id":1,"length":1203,"raw":{"length":1203,"payload_length":1200}}}`, + }, + { + name: "stream packet parsed", + event: StreamPacketParsed{ + StreamID: 4, + Packet: Packet{FlowID: 1, Length: 1203, Raw: RawInfo{Length: 1203, PayloadLength: 1200}}, + }, + want: `{"stream_id":4,"packet":{"flow_id":1,"length":1203,"raw":{"length":1203,"payload_length":1200}}}`, + }, + { + name: "datagram packet created", + event: DatagramPacketCreated{Packet: Packet{FlowID: 7, Length: 101, Raw: RawInfo{Length: 101, PayloadLength: 100}}}, + want: `{"packet":{"flow_id":7,"length":101,"raw":{"length":101,"payload_length":100}}}`, + }, + { + name: "datagram packet parsed", + event: DatagramPacketParsed{Packet: Packet{FlowID: 7, Length: 101, Raw: RawInfo{Length: 101, PayloadLength: 100}}}, + want: `{"packet":{"flow_id":7,"length":101,"raw":{"length":101,"payload_length":100}}}`, + }, + { + name: "packet data", + event: DatagramPacketParsed{Packet: Packet{ + FlowID: 1, + Length: 5, + Raw: RawInfo{Length: 5, PayloadLength: 4, Data: []byte{0x01, 0xde, 0xad, 0xbe, 0xef}}, + }}, + want: `{"packet":{"flow_id":1,"length":5,"raw":{"length":5,"payload_length":4,"data":"01deadbeef"}}}`, + }, + { + name: "truncated packet data", + event: DatagramPacketParsed{Packet: Packet{ + FlowID: 1, + Length: 101, + Raw: RawInfo{Length: 101, PayloadLength: 100, Data: []byte{0x01, 0xde}}, + }}, + want: `{"packet":{"flow_id":1,"length":101,"raw":{"length":101,"payload_length":100,"data":"01de"}}}`, + }, + { + name: "packet without raw info", + event: DatagramPacketParsed{Packet: Packet{FlowID: 0, Length: 0}}, + want: `{"packet":{"flow_id":0,"length":0}}`, + }, + } { + t.Run(tc.name, func(t *testing.T) { + if got := encode(t, tc.event); got != tc.want { + t.Errorf("Encode() = %v, want %v", got, tc.want) + } + }) + } +} + +func TestEventNames(t *testing.T) { + for _, tc := range []struct { + event qlogwriter.Event + want string + }{ + {StreamOpened{}, "roq:stream_opened"}, + {StreamPacketCreated{}, "roq:stream_packet_created"}, + {StreamPacketParsed{}, "roq:stream_packet_parsed"}, + {DatagramPacketCreated{}, "roq:datagram_packet_created"}, + {DatagramPacketParsed{}, "roq:datagram_packet_parsed"}, + } { + if got := tc.event.Name(); got != tc.want { + t.Errorf("Name() = %v, want %v", got, tc.want) + } + } +} diff --git a/qlog/qlog.go b/qlog/qlog.go new file mode 100644 index 0000000..e8b6cd6 --- /dev/null +++ b/qlog/qlog.go @@ -0,0 +1,21 @@ +package qlog + +import ( + "context" + + "github.com/quic-go/quic-go" + quicqlog "github.com/quic-go/quic-go/qlog" + "github.com/quic-go/quic-go/qlogwriter" +) + +// EventSchema is the qlog event schema for RTP over QUIC. +const EventSchema = "urn:ietf:params:qlog:events:roq-01" + +// DefaultConnectionTracer creates a qlog trace that accepts both QUIC and RoQ +// events. Set it as quic.Config.Tracer to have a roq Session log its events into +// the same file as the QUIC transport events. Like quic-go's tracer, it writes to +// the directory named by the QLOGDIR environment variable and returns nil if +// QLOGDIR is not set. +func DefaultConnectionTracer(ctx context.Context, isClient bool, connID quic.ConnectionID) qlogwriter.Trace { + return quicqlog.DefaultConnectionTracerWithSchemas(ctx, isClient, connID, []string{quicqlog.EventSchema, EventSchema}) +} diff --git a/qlogger.go b/qlogger.go new file mode 100644 index 0000000..938a9ab --- /dev/null +++ b/qlogger.go @@ -0,0 +1,36 @@ +package roq + +import ( + "github.com/quic-go/quic-go/qlogwriter" +) + +// qlogger records the RoQ events of a session. +type qlogger struct { + recorder qlogwriter.Recorder + // logData reports whether the bytes of a packet are logged along with its + // lengths. dataLimit caps how many of them are kept; zero keeps the whole + // packet. + logData bool + dataLimit int +} + +func (q *qlogger) record(e qlogwriter.Event) { + q.recorder.RecordEvent(e) +} + +func (q *qlogger) close() error { + return q.recorder.Close() +} + +// rawData returns the bytes to log as the wire image of a packet, or nil if +// the session does not log packet data. The event is encoded on another +// goroutine and callers reuse their buffers, so the bytes have to be copied. +func (q *qlogger) rawData(b []byte) []byte { + if !q.logData { + return nil + } + if q.dataLimit > 0 && len(b) > q.dataLimit { + b = b[:q.dataLimit] + } + return append([]byte(nil), b...) +} diff --git a/quic_connection.go b/quic_connection.go index 2d0b70a..6501ca2 100644 --- a/quic_connection.go +++ b/quic_connection.go @@ -4,6 +4,7 @@ import ( "context" "github.com/quic-go/quic-go" + "github.com/quic-go/quic-go/qlogwriter" ) type QUICGoReceiveStream struct { @@ -54,6 +55,8 @@ func (s *QUICGoSendStream) CancelWrite(c uint64) { s.stream.CancelWrite(quic.StreamErrorCode(c)) } +var _ QlogConnection = &QUICGoConnection{} + type QUICGoConnection struct { conn *quic.Conn } @@ -92,6 +95,12 @@ func (c *QUICGoConnection) AcceptUniStream(ctx context.Context) (ReceiveStream, }, nil } +// QlogTrace returns the qlog trace of the QUIC connection. It is nil if qlog is +// not enabled. +func (c *QUICGoConnection) QlogTrace() qlogwriter.Trace { + return c.conn.QlogTrace() +} + func (c *QUICGoConnection) CloseWithError(code uint64, reason string) error { return c.conn.CloseWithError(quic.ApplicationErrorCode(code), reason) } diff --git a/receive_flow.go b/receive_flow.go index a059324..cb230ee 100644 --- a/receive_flow.go +++ b/receive_flow.go @@ -10,8 +10,7 @@ import ( "sync" "time" - "github.com/mengelbart/qlog" - roqqlog "github.com/mengelbart/qlog/roq" + "github.com/mengelbart/roq/qlog" "github.com/quic-go/quic-go" "github.com/quic-go/quic-go/quicvarint" ) @@ -39,10 +38,10 @@ type ReceiveFlow struct { deadlineExpired bool deadlineTimer *time.Timer - qlog *qlog.Logger + qlog *qlogger } -func newReceiveFlow(id uint64, receiveBufferSize int, qlog *qlog.Logger) *ReceiveFlow { +func newReceiveFlow(id uint64, receiveBufferSize int, qlog *qlogger) *ReceiveFlow { ctx, cancel := context.WithCancel(context.Background()) return &ReceiveFlow{ id: id, @@ -102,8 +101,9 @@ func (f *ReceiveFlow) readStream(rs ReceiveStream) { }() reader := quicvarint.NewReader(rs) + var lengthBuf [8]byte for { - length, err := quicvarint.Read(reader) + length, encodedLength, err := readVarint(reader, lengthBuf[:]) if err != nil { if errors.Is(err, io.EOF) { return @@ -119,6 +119,9 @@ func (f *ReceiveFlow) readStream(rs ReceiveStream) { r := io.LimitReader(reader, int64(length)) b := f.bufferPool.Get().(*bytes.Buffer) b.Reset() + // The buffer holds the frame as it was on the wire, prefix included, + // until the packet is handed to the flow below. + b.Write(encodedLength) n, err := b.ReadFrom(r) if err != nil { var streamErr *quic.StreamError @@ -130,26 +133,49 @@ func (f *ReceiveFlow) readStream(rs ReceiveStream) { return } if f.qlog != nil { - raw := make([]byte, b.Len()) - n := copy(raw, b.Bytes()) - f.qlog.Log(roqqlog.StreamPacketEvent{ - EventName: roqqlog.StreamPacketEventTypeParsed, - StreamID: rs.ID(), - Packet: roqqlog.Packet{ + f.qlog.record(qlog.StreamPacketParsed{ + StreamID: uint64(rs.ID()), + Packet: qlog.Packet{ FlowID: f.id, - Length: length, - Raw: &qlog.RawInfo{ - Length: length, + Length: uint64(b.Len()), + Raw: qlog.RawInfo{ + Length: uint64(b.Len()), PayloadLength: length, - Data: raw[:n], + Data: f.qlog.rawData(b.Bytes()), }, }, }) } + // Skip the prefix again: the flow hands out RTP and RTCP packets. + b.Next(len(encodedLength)) f.push(b) } } +// readVarint reads a QUIC varint from r and returns its value together with the +// bytes it was encoded in, which alias buf. buf must have room for 8 bytes. +// +// A QUIC varint is not required to use the shortest encoding of its value (RFC +// 9000, Section 16), so the encoding cannot be reconstructed from the value +// alone. Keeping it lets the qlog events report the frame as it was on the +// wire rather than as this implementation would have written it. +func readVarint(r quicvarint.Reader, buf []byte) (uint64, []byte, error) { + firstByte, err := r.ReadByte() + if err != nil { + return 0, nil, err + } + // The first two bits of the first byte encode the length. + buf = buf[:1<<(firstByte>>6)] + buf[0] = firstByte + if len(buf) > 1 { + if _, err := io.ReadFull(r, buf[1:]); err != nil { + return 0, nil, err + } + } + v, _, err := quicvarint.Parse(buf) + return v, buf, err +} + // Read reads the next RTP packet of the flow into buf. Packets are not split // across calls: if buf is too small to hold the complete packet, the packet is // dropped and Read returns 0 and io.ErrShortBuffer. Callers should provide a diff --git a/receive_flow_buffer.go b/receive_flow_buffer.go index eadba28..d363a81 100644 --- a/receive_flow_buffer.go +++ b/receive_flow_buffer.go @@ -3,8 +3,6 @@ package roq import ( "slices" "sync" - - "github.com/mengelbart/qlog" ) type receiveFlowBuffer struct { @@ -28,7 +26,7 @@ func newReceiveFlowBuffer(maxLen int) *receiveFlowBuffer { // flow if the buffer holds none. Lookup and creation happen under a single // lock hold, so concurrent callers for the same unknown flow ID all get the // same flow. -func (b *receiveFlowBuffer) getOrCreate(id uint64, receiveBufferSize int, qlogger *qlog.Logger) *ReceiveFlow { +func (b *receiveFlowBuffer) getOrCreate(id uint64, receiveBufferSize int, qlog *qlogger) *ReceiveFlow { b.mutex.Lock() defer b.mutex.Unlock() if f, ok := b.buffer[id]; ok { @@ -43,7 +41,7 @@ func (b *receiveFlowBuffer) getOrCreate(id uint64, receiveBufferSize int, qlogge delete(b.buffer, front) b.queue = b.queue[1:] } - f := newReceiveFlow(id, receiveBufferSize, qlogger) + f := newReceiveFlow(id, receiveBufferSize, qlog) b.queue = append(b.queue, id) b.buffer[id] = f return f diff --git a/rtp_send_stream.go b/rtp_send_stream.go index 6d54562..13c9779 100644 --- a/rtp_send_stream.go +++ b/rtp_send_stream.go @@ -4,8 +4,7 @@ import ( "io" "sync" - "github.com/mengelbart/qlog" - roqqlog "github.com/mengelbart/qlog/roq" + "github.com/mengelbart/roq/qlog" "github.com/quic-go/quic-go/quicvarint" ) @@ -13,7 +12,7 @@ type RTPSendStream struct { stream SendStream flowID uint64 flowIDBytes []byte - qlog *qlog.Logger + qlog *qlogger // lock guards the fields below, which are mutated by every write. lock sync.Mutex @@ -24,7 +23,7 @@ type RTPSendStream struct { pending []byte } -func newRTPSendStream(stream SendStream, flowID uint64, flowIDBytes []byte, qlog *qlog.Logger) (*RTPSendStream, error) { +func newRTPSendStream(stream SendStream, flowID uint64, flowIDBytes []byte, qlog *qlogger) (*RTPSendStream, error) { return &RTPSendStream{ stream: stream, flowID: flowID, @@ -56,9 +55,13 @@ func (s *RTPSendStream) WriteRTPBytes(packet []byte) (int, error) { } s.buffer = s.buffer[0:0] + // frameStart is where the packet's own frame begins: the flow ID ahead of + // it goes on the stream once, not once per packet. + frameStart := 0 if !s.sentFlowID { s.buffer = append(s.buffer, s.flowIDBytes...) s.sentFlowID = true + frameStart = len(s.buffer) } s.buffer = quicvarint.Append(s.buffer, uint64(len(packet))) headerLen := len(s.buffer) @@ -73,18 +76,17 @@ func (s *RTPSendStream) WriteRTPBytes(packet []byte) (int, error) { } } if s.qlog != nil { - raw := make([]byte, len(s.buffer)) - m := copy(raw, s.buffer) - s.qlog.Log(roqqlog.StreamPacketEvent{ - EventName: roqqlog.StreamPacketEventTypeCreated, - StreamID: s.stream.ID(), - Packet: roqqlog.Packet{ + length := uint64(len(packet)) + framed := uint64(len(s.buffer) - frameStart) + s.qlog.record(qlog.StreamPacketCreated{ + StreamID: uint64(s.stream.ID()), + Packet: qlog.Packet{ FlowID: s.flowID, - Length: uint64(len(s.buffer)), - Raw: &qlog.RawInfo{ - Length: uint64(m), - PayloadLength: uint64(m), - Data: raw, + Length: framed, + Raw: qlog.RawInfo{ + Length: framed, + PayloadLength: length, + Data: s.qlog.rawData(s.buffer[frameStart:]), }, }, }) diff --git a/send_flow.go b/send_flow.go index 1521334..6e97c83 100644 --- a/send_flow.go +++ b/send_flow.go @@ -6,8 +6,7 @@ import ( "log/slog" "sync" - "github.com/mengelbart/qlog" - roqqlog "github.com/mengelbart/qlog/roq" + "github.com/mengelbart/roq/qlog" "github.com/quic-go/quic-go/quicvarint" ) @@ -19,10 +18,10 @@ type SendFlow struct { streams []*RTPSendStream onClose func() closedErr error - qlog *qlog.Logger + qlog *qlogger } -func newFlow(conn Connection, id uint64, onClose func(), qlog *qlog.Logger) *SendFlow { +func newFlow(conn Connection, id uint64, onClose func(), qlog *qlogger) *SendFlow { flowID := make([]byte, 0, quicvarint.Len(id)) flowID = quicvarint.Append(flowID, id) return &SendFlow{ @@ -46,17 +45,14 @@ func (f *SendFlow) WriteRTPBytes(packet []byte) error { buf = append(buf, f.flowID...) buf = append(buf, packet...) if f.qlog != nil { - raw := make([]byte, len(buf)) - m := copy(raw, buf) - f.qlog.Log(roqqlog.DatagramPacketEvent{ - Type: roqqlog.DatagramPacketEventTypeCreated, - Packet: roqqlog.Packet{ + f.qlog.record(qlog.DatagramPacketCreated{ + Packet: qlog.Packet{ FlowID: f.id, Length: uint64(len(buf)), - Raw: &qlog.RawInfo{ - Length: uint64(m), - PayloadLength: uint64(m), - Data: raw, + Raw: qlog.RawInfo{ + Length: uint64(len(buf)), + PayloadLength: uint64(len(packet)), + Data: f.qlog.rawData(buf), }, }, }) @@ -86,7 +82,7 @@ func (f *SendFlow) NewSendStream(ctx context.Context, priority uint32, incremant return nil, err } if f.qlog != nil { - f.qlog.Log(roqqlog.StreamOpenedEvent{ + f.qlog.record(qlog.StreamOpened{ FlowID: f.id, StreamID: uint64(s.ID()), }) diff --git a/send_flow_test.go b/send_flow_test.go index de710dc..850240d 100644 --- a/send_flow_test.go +++ b/send_flow_test.go @@ -13,7 +13,7 @@ func TestSendFlowCloseContinuesAfterStreamError(t *testing.T) { closeErr := errors.New("stream close failed") c := newStubConn() c.sendCloseErr = closeErr - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } diff --git a/session.go b/session.go index d1b9572..593bf6f 100644 --- a/session.go +++ b/session.go @@ -6,8 +6,8 @@ import ( "io" "sync" - "github.com/mengelbart/qlog" - roqqlog "github.com/mengelbart/qlog/roq" + "github.com/mengelbart/roq/qlog" + "github.com/quic-go/quic-go/qlogwriter" "github.com/quic-go/quic-go/quicvarint" ) @@ -29,6 +29,14 @@ type ReceiveStream interface { CancelRead(uint64) } +// QlogConnection is implemented by Connections that can provide the qlog trace +// of the underlying QUIC connection. A Session whose Connection implements it +// logs its RoQ events into that trace, provided the trace was created with the +// RoQ event schema. QUICGoConnection implements it. +type QlogConnection interface { + QlogTrace() qlogwriter.Trace +} + type Connection interface { SendDatagram(payload []byte) error ReceiveDatagram(context.Context) ([]byte, error) @@ -56,12 +64,13 @@ type Session struct { ctx context.Context cancelCtx context.CancelFunc - qlog *qlog.Logger + qlog *qlogger + closeQlogOnce sync.Once } // NewSession creates a new roq session. QUIC connection is handled by roq. // It returns an error if conn is nil or if an option is invalid. -func NewSession(conn Connection, acceptDatagrams bool, qlogger *qlog.Logger, opts ...Option) (*Session, error) { +func NewSession(conn Connection, acceptDatagrams bool, opts ...Option) (*Session, error) { if conn == nil { return nil, errNilConnection } @@ -69,7 +78,7 @@ func NewSession(conn Connection, acceptDatagrams bool, qlogger *qlog.Logger, opt if err != nil { return nil, err } - s := newSession(conn, acceptDatagrams, qlogger, config) + s := newSession(conn, acceptDatagrams, config) s.start() return s, nil @@ -79,7 +88,7 @@ func NewSession(conn Connection, acceptDatagrams bool, qlogger *qlog.Logger, opt // handled by the application. HandleDatagram and HandleUniStreamWithFlowID have // to be called for each datagram / new stream. It returns an error if conn is // nil or if an option is invalid. -func NewSessionWithAppHandledConn(conn Connection, acceptDatagrams bool, qlogger *qlog.Logger, opts ...Option) (*Session, error) { +func NewSessionWithAppHandledConn(conn Connection, acceptDatagrams bool, opts ...Option) (*Session, error) { if conn == nil { return nil, errNilConnection } @@ -87,12 +96,12 @@ func NewSessionWithAppHandledConn(conn Connection, acceptDatagrams bool, qlogger if err != nil { return nil, err } - s := newSession(conn, acceptDatagrams, qlogger, config) + s := newSession(conn, acceptDatagrams, config) return s, nil } -func newSession(conn Connection, acceptDatagrams bool, qlogger *qlog.Logger, config *sessionConfig) *Session { +func newSession(conn Connection, acceptDatagrams bool, config *sessionConfig) *Session { ctx, cancel := context.WithCancel(context.Background()) return &Session{ receiveBufferSize: config.receiveBufferSize, @@ -107,7 +116,29 @@ func newSession(conn Connection, acceptDatagrams bool, qlogger *qlog.Logger, con wg: sync.WaitGroup{}, ctx: ctx, cancelCtx: cancel, - qlog: qlogger, + qlog: newQlogger(conn, config), + } +} + +// newQlogger returns the qlogger the session logs its RoQ events to, or nil if +// RoQ events are not being logged. A trace set on the config takes precedence +// over the trace of the connection, if any. +func newQlogger(conn Connection, config *sessionConfig) *qlogger { + trace := config.qlogTrace + if trace == nil { + qc, ok := conn.(QlogConnection) + if !ok { + return nil + } + trace = qc.QlogTrace() + } + if trace == nil || !trace.SupportsSchemas(qlog.EventSchema) { + return nil + } + return &qlogger{ + recorder: trace.AddProducer(), + logData: config.qlogPacketData, + dataLimit: config.qlogPacketDataLimit, } } @@ -199,9 +230,18 @@ func (s *Session) closeWithError(code uint64, reason string) { // Close returns the error from closing the underlying QUIC connection. It is // idempotent: later calls close nothing and report the same error as the call // that closed the session. +// +// Close also releases the session's qlog producer, which is what finishes the +// qlog trace of the QUIC connection, so it has to be called for the trace to be +// written completely. func (s *Session) Close() error { s.close(ErrRoQNoError, "") s.wg.Wait() + // Only now that nothing can record another event is it safe to close the + // producer: Recorder.Close must not run concurrently with RecordEvent. + if s.qlog != nil { + s.closeQlogOnce.Do(func() { _ = s.qlog.close() }) + } s.mutex.Lock() defer s.mutex.Unlock() return s.connCloseErr @@ -250,17 +290,14 @@ func (s *Session) HandleDatagram(datagram []byte) { return } if s.qlog != nil { - raw := make([]byte, len(datagram)) - m := copy(raw, datagram) - s.qlog.Log(roqqlog.DatagramPacketEvent{ - Type: roqqlog.DatagramPacketEventTypeParsed, - Packet: roqqlog.Packet{ + s.qlog.record(qlog.DatagramPacketParsed{ + Packet: qlog.Packet{ FlowID: flowID, - Length: uint64(n), - Raw: &qlog.RawInfo{ - Length: uint64(m), - PayloadLength: uint64(m), - Data: raw, + Length: uint64(len(datagram)), + Raw: qlog.RawInfo{ + Length: uint64(len(datagram)), + PayloadLength: uint64(len(datagram) - n), + Data: s.qlog.rawData(datagram), }, }, }) @@ -278,7 +315,7 @@ func (s *Session) HandleDatagram(datagram []byte) { // ID. func (s *Session) HandleUniStreamWithFlowID(flowID uint64, rs ReceiveStream) { if s.qlog != nil { - s.qlog.Log(roqqlog.StreamOpenedEvent{ + s.qlog.record(qlog.StreamOpened{ FlowID: flowID, StreamID: uint64(rs.ID()), }) diff --git a/session_qlog_test.go b/session_qlog_test.go new file mode 100644 index 0000000..391ad46 --- /dev/null +++ b/session_qlog_test.go @@ -0,0 +1,457 @@ +package roq + +import ( + "reflect" + "sync" + "testing" + "time" + + "github.com/mengelbart/roq/qlog" + "github.com/quic-go/quic-go/qlogwriter" + "github.com/quic-go/quic-go/quicvarint" +) + +// fakeTrace is a qlogwriter.Trace that hands out recorders collecting events in +// memory. schemas are the event schemas it claims to support. +type fakeTrace struct { + schemas []string + + mutex sync.Mutex + recorders []*fakeRecorder +} + +func newFakeTrace() *fakeTrace { + return &fakeTrace{schemas: []string{qlog.EventSchema}} +} + +func (t *fakeTrace) SupportsSchemas(schema string) bool { + for _, s := range t.schemas { + if s == schema { + return true + } + } + return false +} + +func (t *fakeTrace) AddProducer() qlogwriter.Recorder { + t.mutex.Lock() + defer t.mutex.Unlock() + r := &fakeRecorder{} + t.recorders = append(t.recorders, r) + return r +} + +// only returns the single recorder the trace handed out. +func (t *fakeTrace) only(tb testing.TB) *fakeRecorder { + tb.Helper() + t.mutex.Lock() + defer t.mutex.Unlock() + if len(t.recorders) != 1 { + tb.Fatalf("got %v producers, want 1", len(t.recorders)) + } + return t.recorders[0] +} + +type fakeRecorder struct { + mutex sync.Mutex + events []qlogwriter.Event + closes int +} + +func (r *fakeRecorder) RecordEvent(e qlogwriter.Event) { + r.mutex.Lock() + defer r.mutex.Unlock() + r.events = append(r.events, e) +} + +func (r *fakeRecorder) Close() error { + r.mutex.Lock() + defer r.mutex.Unlock() + r.closes++ + return nil +} + +func (r *fakeRecorder) recorded() []qlogwriter.Event { + r.mutex.Lock() + defer r.mutex.Unlock() + return append([]qlogwriter.Event{}, r.events...) +} + +func (r *fakeRecorder) closed() int { + r.mutex.Lock() + defer r.mutex.Unlock() + return r.closes +} + +// awaitEvent waits for an event of the same type as want and returns it. +func (r *fakeRecorder) awaitEvent(t *testing.T, want qlogwriter.Event) qlogwriter.Event { + t.Helper() + return r.awaitEventAfter(t, want, 0) +} + +// awaitEventAfter waits for the event of the same type as want that follows the +// first skip of them, and returns it. +func (r *fakeRecorder) awaitEventAfter(t *testing.T, want qlogwriter.Event, skip int) qlogwriter.Event { + t.Helper() + deadline := time.Now().Add(5 * time.Second) + for { + seen := 0 + for _, e := range r.recorded() { + if e.Name() != want.Name() { + continue + } + if seen == skip { + return e + } + seen++ + } + if time.Now().After(deadline) { + t.Fatalf("event %v #%v was never recorded, got %v", want.Name(), skip, r.recorded()) + } + time.Sleep(time.Millisecond) + } +} + +// qlogStubConn is a stubConn that exposes a qlog trace, like QUICGoConnection. +type qlogStubConn struct { + *stubConn + trace qlogwriter.Trace +} + +func newQlogStubConn(trace qlogwriter.Trace) *qlogStubConn { + return &qlogStubConn{stubConn: newStubConn(), trace: trace} +} + +func (c *qlogStubConn) QlogTrace() qlogwriter.Trace { return c.trace } + +func TestQlogTraceFromConnection(t *testing.T) { + tr := newFakeTrace() + c := newQlogStubConn(tr) + s, err := NewSession(c, true) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + + if s.qlog == nil { + t.Fatal("session did not take a producer from the connection's trace") + } + tr.only(t) +} + +// A connection without a trace, or with one that does not carry the RoQ event +// schema, must leave the session without a recorder. +func TestQlogWithoutRoQSchema(t *testing.T) { + for _, tc := range []struct { + name string + conn Connection + }{ + {"connection without a trace", newQlogStubConn(nil)}, + {"trace without the RoQ schema", newQlogStubConn(&fakeTrace{schemas: []string{"urn:ietf:params:qlog:events:quic-12"}})}, + {"connection that cannot report a trace", newStubConn()}, + } { + t.Run(tc.name, func(t *testing.T) { + s, err := NewSession(tc.conn, true) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + if s.qlog != nil { + t.Error("session took a producer, want none") + } + }) + } +} + +// An explicitly configured trace wins over the one the connection reports. +func TestQlogTraceOptionOverridesConnection(t *testing.T) { + fromConn, fromOption := newFakeTrace(), newFakeTrace() + c := newQlogStubConn(fromConn) + s, err := NewSession(c, true, WithQlogTrace(fromOption)) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + + fromOption.only(t) + fromConn.mutex.Lock() + defer fromConn.mutex.Unlock() + if len(fromConn.recorders) != 0 { + t.Errorf("got %v producers on the connection's trace, want 0", len(fromConn.recorders)) + } +} + +// Close releases the producer, which is what closes the underlying trace. It is +// idempotent, so a second Close must not close the producer again. +func TestQlogProducerClosedOnce(t *testing.T) { + tr := newFakeTrace() + s, err := NewSession(newQlogStubConn(tr), true) + if err != nil { + t.Fatal(err) + } + r := tr.only(t) + closeWithin(t, s, time.Second) + closeWithin(t, s, time.Second) + if got := r.closed(); got != 1 { + t.Errorf("producer closed %v times, want 1", got) + } +} + +func TestQlogDatagramEvents(t *testing.T) { + tr := newFakeTrace() + c := newQlogStubConn(tr) + s, err := NewSession(c, true) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + r := tr.only(t) + + f, err := s.NewSendFlow(1) + if err != nil { + t.Fatal(err) + } + if err = f.WriteRTPBytes(make([]byte, 100)); err != nil { + t.Fatal(err) + } + created := r.awaitEvent(t, qlog.DatagramPacketCreated{}).(qlog.DatagramPacketCreated) + want := qlog.DatagramPacketCreated{ + Packet: qlog.Packet{ + FlowID: 1, + Length: 101, + Raw: qlog.RawInfo{Length: 101, PayloadLength: 100}, + }, + } + if !reflect.DeepEqual(created, want) { + t.Errorf("got %+v, want %+v", created, want) + } + + // The flow ID varint is not part of the RTP packet, so it counts towards + // the raw length only. + c.datagrams <- append(quicvarint.Append(nil, 1), make([]byte, 100)...) + parsed := r.awaitEvent(t, qlog.DatagramPacketParsed{}).(qlog.DatagramPacketParsed) + if !reflect.DeepEqual(parsed.Packet, want.Packet) { + t.Errorf("got %+v, want %+v", parsed.Packet, want.Packet) + } +} + +func TestQlogStreamEvents(t *testing.T) { + tr := newFakeTrace() + c := newQlogStubConn(tr) + s, err := NewSession(c, true) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + r := tr.only(t) + + f, err := s.NewSendFlow(1) + if err != nil { + t.Fatal(err) + } + stream, err := f.NewSendStream(t.Context(), 0, false) + if err != nil { + t.Fatal(err) + } + if _, err = stream.WriteRTPBytes(make([]byte, 100)); err != nil { + t.Fatal(err) + } + + opened := r.awaitEvent(t, qlog.StreamOpened{}).(qlog.StreamOpened) + if want := (qlog.StreamOpened{FlowID: 1, StreamID: 1}); opened != want { + t.Errorf("got %+v, want %+v", opened, want) + } + created := r.awaitEvent(t, qlog.StreamPacketCreated{}).(qlog.StreamPacketCreated) + // The length prefix (2 bytes for 100) counts towards the raw length only. + // The flow ID does not: it is sent once per stream, not once per frame. + want := qlog.StreamPacketCreated{ + StreamID: 1, + Packet: qlog.Packet{ + FlowID: 1, + Length: 102, + Raw: qlog.RawInfo{Length: 102, PayloadLength: 100}, + }, + } + if !reflect.DeepEqual(created, want) { + t.Errorf("got %+v, want %+v", created, want) + } + + rs := &stubReceiveStream{ + id: 2, + data: append(quicvarint.Append(quicvarint.Append(nil, 1), 100), make([]byte, 100)...), + eof: true, + cancelled: make(chan struct{}), + } + c.streams <- rs + parsed := r.awaitEvent(t, qlog.StreamPacketParsed{}).(qlog.StreamPacketParsed) + wantParsed := qlog.StreamPacketParsed{ + StreamID: 2, + Packet: qlog.Packet{ + FlowID: 1, + Length: 102, + Raw: qlog.RawInfo{Length: 102, PayloadLength: 100}, + }, + } + if !reflect.DeepEqual(parsed, wantParsed) { + t.Errorf("got %+v, want %+v", parsed, wantParsed) + } +} + +// Without WithQlogPacketData a session logs packet lengths but no wire image. +func TestQlogPacketDataOffByDefault(t *testing.T) { + tr := newFakeTrace() + c := newQlogStubConn(tr) + s, err := NewSession(c, true) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + r := tr.only(t) + + c.datagrams <- append(quicvarint.Append(nil, 1), make([]byte, 100)...) + parsed := r.awaitEvent(t, qlog.DatagramPacketParsed{}).(qlog.DatagramPacketParsed) + if parsed.Packet.Raw.Data != nil { + t.Errorf("got packet data %v, want none", parsed.Packet.Raw.Data) + } +} + +func TestQlogPacketData(t *testing.T) { + packet := []byte{0xde, 0xad, 0xbe, 0xef} + for _, tc := range []struct { + name string + maxBytes int + // wantDatagram is the datagram wire image: the flow ID varint followed + // by the packet. wantFrame is the stream wire image: the length varint + // followed by the packet, the same on both sides of the stream. + wantDatagram []byte + wantFrame []byte + }{ + { + name: "whole packet", + maxBytes: 0, + wantDatagram: []byte{0x01, 0xde, 0xad, 0xbe, 0xef}, + wantFrame: []byte{0x04, 0xde, 0xad, 0xbe, 0xef}, + }, + { + name: "truncated", + maxBytes: 3, + wantDatagram: []byte{0x01, 0xde, 0xad}, + wantFrame: []byte{0x04, 0xde, 0xad}, + }, + { + name: "limit above the packet size", + maxBytes: 64, + wantDatagram: []byte{0x01, 0xde, 0xad, 0xbe, 0xef}, + wantFrame: []byte{0x04, 0xde, 0xad, 0xbe, 0xef}, + }, + } { + t.Run(tc.name, func(t *testing.T) { + tr := newFakeTrace() + c := newQlogStubConn(tr) + s, err := NewSession(c, true, WithQlogPacketData(tc.maxBytes)) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + r := tr.only(t) + + f, err := s.NewSendFlow(1) + if err != nil { + t.Fatal(err) + } + if err = f.WriteRTPBytes(packet); err != nil { + t.Fatal(err) + } + created := r.awaitEvent(t, qlog.DatagramPacketCreated{}).(qlog.DatagramPacketCreated) + if !reflect.DeepEqual(created.Packet.Raw.Data, tc.wantDatagram) { + t.Errorf("sent datagram data = %x, want %x", created.Packet.Raw.Data, tc.wantDatagram) + } + // The lengths always describe the complete packet, even when the + // data logged for it was truncated. + if created.Packet.Length != 5 || created.Packet.Raw.Length != 5 || created.Packet.Raw.PayloadLength != 4 { + t.Errorf("got %+v, want length 5 and payload length 4", created.Packet) + } + + c.datagrams <- append(quicvarint.Append(nil, 1), packet...) + parsedDgram := r.awaitEvent(t, qlog.DatagramPacketParsed{}).(qlog.DatagramPacketParsed) + if !reflect.DeepEqual(parsedDgram.Packet.Raw.Data, tc.wantDatagram) { + t.Errorf("received datagram data = %x, want %x", parsedDgram.Packet.Raw.Data, tc.wantDatagram) + } + + stream, err := f.NewSendStream(t.Context(), 0, false) + if err != nil { + t.Fatal(err) + } + if _, err = stream.WriteRTPBytes(packet); err != nil { + t.Fatal(err) + } + sent := r.awaitEvent(t, qlog.StreamPacketCreated{}).(qlog.StreamPacketCreated) + if !reflect.DeepEqual(sent.Packet.Raw.Data, tc.wantFrame) { + t.Errorf("sent stream data = %x, want %x", sent.Packet.Raw.Data, tc.wantFrame) + } + // Only the first packet on a stream is preceded by the flow ID, so + // a later one has to log the same wire image as the first. + if _, err = stream.WriteRTPBytes(packet); err != nil { + t.Fatal(err) + } + second := r.awaitEventAfter(t, qlog.StreamPacketCreated{}, 1).(qlog.StreamPacketCreated) + if !reflect.DeepEqual(second.Packet.Raw.Data, tc.wantFrame) { + t.Errorf("second sent stream data = %x, want %x", second.Packet.Raw.Data, tc.wantFrame) + } + + rs := &stubReceiveStream{ + id: 2, + data: append(quicvarint.Append(quicvarint.Append(nil, 1), uint64(len(packet))), packet...), + eof: true, + cancelled: make(chan struct{}), + } + c.streams <- rs + parsed := r.awaitEvent(t, qlog.StreamPacketParsed{}).(qlog.StreamPacketParsed) + if !reflect.DeepEqual(parsed.Packet.Raw.Data, tc.wantFrame) { + t.Errorf("received stream data = %x, want %x", parsed.Packet.Raw.Data, tc.wantFrame) + } + }) + } +} + +// A QUIC varint may use a longer encoding than the value needs. The receiver +// has to report the frame as it was on the wire, not as it would have written +// it, so its lengths and data follow the encoding the sender chose. +func TestQlogNonMinimalLengthVarint(t *testing.T) { + tr := newFakeTrace() + c := newQlogStubConn(tr) + s, err := NewSession(c, true, WithQlogPacketData(0)) + if err != nil { + t.Fatal(err) + } + defer closeWithin(t, s, time.Second) + r := tr.only(t) + + packet := []byte{0xde, 0xad, 0xbe, 0xef} + // The length of 4 fits in one byte, but is encoded in eight here. + prefix := quicvarint.AppendWithLen(nil, uint64(len(packet)), 8) + c.streams <- &stubReceiveStream{ + id: 2, + data: append(quicvarint.Append(nil, 1), append(prefix, packet...)...), + eof: true, + cancelled: make(chan struct{}), + } + + parsed := r.awaitEvent(t, qlog.StreamPacketParsed{}).(qlog.StreamPacketParsed) + want := qlog.StreamPacketParsed{ + StreamID: 2, + Packet: qlog.Packet{ + FlowID: 1, + // Eight bytes of length prefix, not the one the value needs. + Length: 12, + Raw: qlog.RawInfo{ + Length: 12, + PayloadLength: 4, + Data: append(append([]byte{}, prefix...), packet...), + }, + }, + } + if !reflect.DeepEqual(parsed, want) { + t.Errorf("got %+v, want %+v", parsed, want) + } +} diff --git a/session_test.go b/session_test.go index 4711e0f..6009841 100644 --- a/session_test.go +++ b/session_test.go @@ -208,7 +208,7 @@ func closeWithin(t *testing.T, s *Session, timeout time.Duration) { // a protocol violation by the sender and closes the session. func TestCloseAfterMalformedDatagram(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -230,7 +230,7 @@ func TestCloseAfterMalformedDatagram(t *testing.T) { // peer cancelling one frame must not tear down the session. func TestMalformedStreamHeaderIsDropped(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -253,7 +253,7 @@ func TestMalformedStreamHeaderIsDropped(t *testing.T) { // Close must tear down open send flows without deadlocking on the flow map. func TestCloseWithOpenSendFlow(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -275,7 +275,7 @@ func TestCloseWithOpenSendFlow(t *testing.T) { // Close must tear down open receive flows and their streams. func TestCloseWithOpenReceiveFlow(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -310,7 +310,7 @@ func TestCloseWithOpenReceiveFlow(t *testing.T) { // close is idempotent: the first code wins and the connection is closed once. func TestCloseIsIdempotent(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -333,7 +333,7 @@ func TestCloseIsIdempotent(t *testing.T) { // Concurrent Close calls must all return. func TestConcurrentClose(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -357,7 +357,7 @@ func TestConcurrentClose(t *testing.T) { // Operations after close must fail rather than block. func TestNewFlowAfterClose(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -375,7 +375,7 @@ func TestNewFlowAfterClose(t *testing.T) { // with, not just its message. func TestSessionErrorAccessors(t *testing.T) { c := newStubConn() - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -401,7 +401,7 @@ func TestSessionErrorAccessors(t *testing.T) { func TestCloseReturnsConnectionError(t *testing.T) { c := newStubConn() c.closeErr = errors.New("connection close failed") - s, err := NewSession(c, true, nil) + s, err := NewSession(c, true) if err != nil { t.Fatal(err) } @@ -416,10 +416,10 @@ func TestCloseReturnsConnectionError(t *testing.T) { // The constructors' error return must mean something: a nil connection is // rejected instead of panicking in a receive loop later on. func TestNewSessionNilConnection(t *testing.T) { - if _, err := NewSession(nil, true, nil); !errors.Is(err, errNilConnection) { + if _, err := NewSession(nil, true); !errors.Is(err, errNilConnection) { t.Errorf("NewSession(nil) error = %v, want errNilConnection", err) } - if _, err := NewSessionWithAppHandledConn(nil, true, nil); !errors.Is(err, errNilConnection) { + if _, err := NewSessionWithAppHandledConn(nil, true); !errors.Is(err, errNilConnection) { t.Errorf("NewSessionWithAppHandledConn(nil) error = %v, want errNilConnection", err) } } @@ -428,7 +428,7 @@ func TestNewSessionNilConnection(t *testing.T) { // buffered flow off with it: the winner has to be the flow that already holds // the packets that arrived for the ID before it was registered. func TestNewReceiveFlowDoesNotStrandBufferedFlow(t *testing.T) { - s, err := NewSessionWithAppHandledConn(newStubConn(), true, nil) + s, err := NewSessionWithAppHandledConn(newStubConn(), true) if err != nil { t.Fatal(err) }