Repository: quic-go/quic-go
Pull request #4305 (2024-02-03 05:13:37)

add a qlog tracer for events outside of QUIC connections
By attaching a qlog tracer to the `Transport`, it's now possible to log QUIC events that don't belong to any particular connection. For example, this could be Version Negotiation and Retry packets that we send, packets that we can't associate with any connection, etc.

It also allows using the `Debug` function on the `logging.Tracer` to dig deeper into unexpected behavior happening in a server.

codecov[bot]: ## [Codecov](https://app.codecov.io/gh/quic-go/quic-go/pull/4305?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=quic-go) Report
All modified and coverable lines are covered by tests :white_check_mark:
> Comparison is base [(`07ec324`)](https://app.codecov.io/gh/quic-go/quic-go/commit/07ec3245bd4ac4c510b6905b5f1c443f7273c08a?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=quic-go) 84.14% compared to head [(`e08589e`)](https://app.codecov.io/gh/quic-go/quic-go/pull/4305?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=quic-go) 84.20%.


<details><summary>Additional details and impacted files</summary>


```diff
@@            Coverage Diff             @@
##           master    #4305      +/-   ##
==========================================
+ Coverage   84.14%   84.20%   +0.05%     
==========================================
  Files         150      151       +1     
  Lines       15364    15413      +49     
==========================================
+ Hits        12928    12977      +49     
  Misses       1938     1938              
  Partials      498      498              
```



</details>

[:umbrella: View full report in Codecov by Sentry](https://app.codecov.io/gh/quic-go/quic-go/pull/4305?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=quic-go).   
:loudspeaker: Have feedback on the report? [Share it here](https://about.codecov.io/codecov-pr-comment-feedback/?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=quic-go).


Patch:
diff --git a/qlog/connection_tracer.go b/qlog/connection_tracer.go
index c73a3fe3..ce6c0db3 100644
--- a/qlog/connection_tracer.go
+++ b/qlog/connection_tracer.go
@@ -23,10 +23,10 @@ type connectionTracer struct {
 // NewConnectionTracer creates a new tracer to record a qlog for a connection.
 func NewConnectionTracer(w io.WriteCloser, p logging.Perspective, odcid protocol.ConnectionID) *logging.ConnectionTracer {
 	tr := &trace{
-		VantagePoint: vantagePoint{Type: p},
+		VantagePoint: vantagePoint{Type: p.String()},
 		CommonFields: commonFields{
-			ODCID:         odcid,
-			GroupID:       odcid,
+			ODCID:         &odcid,
+			GroupID:       &odcid,
 			ReferenceTime: time.Now(),
 		},
 	}
diff --git a/qlog/event.go b/qlog/event.go
index d3d26601..c70ee548 100644
--- a/qlog/event.go
+++ b/qlog/event.go
@@ -233,6 +233,20 @@ func (e eventVersionNegotiationReceived) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.ArrayKey("supported_versions", versions(e.SupportedVersions))
 }
 
+type eventVersionNegotiationSent struct {
+	Header            packetHeaderVersionNegotiation
+	SupportedVersions []versionNumber
+}
+
+func (e eventVersionNegotiationSent) Category() category { return categoryTransport }
+func (e eventVersionNegotiationSent) Name() string       { return "packet_sent" }
+func (e eventVersionNegotiationSent) IsNil() bool        { return false }
+
+func (e eventVersionNegotiationSent) MarshalJSONObject(enc *gojay.Encoder) {
+	enc.ObjectKey("header", e.Header)
+	enc.ArrayKey("supported_versions", versions(e.SupportedVersions))
+}
+
 type eventPacketBuffered struct {
 	PacketType logging.PacketType
 	PacketSize protocol.ByteCount
diff --git a/qlog/trace.go b/qlog/trace.go
index dcb7da6f..c183368d 100644
--- a/qlog/trace.go
+++ b/qlog/trace.go
@@ -4,7 +4,6 @@ import (
 	"runtime/debug"
 	"time"
 
-	"github.com/quic-go/quic-go/internal/protocol"
 	"github.com/quic-go/quic-go/logging"
 
 	"github.com/francoispqt/gojay"
@@ -62,30 +61,27 @@ func (c configuration) MarshalJSONObject(enc *gojay.Encoder) {
 
 type vantagePoint struct {
 	Name string
-	Type protocol.Perspective
+	Type string
 }
 
 func (p vantagePoint) IsNil() bool { return false }
 func (p vantagePoint) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKeyOmitEmpty("name", p.Name)
-	switch p.Type {
-	case protocol.PerspectiveClient:
-		enc.StringKey("type", "client")
-	case protocol.PerspectiveServer:
-		enc.StringKey("type", "server")
-	}
+	enc.StringKeyOmitEmpty("type", p.Type)
 }
 
 type commonFields struct {
-	ODCID         logging.ConnectionID
-	GroupID       logging.ConnectionID
+	ODCID         *logging.ConnectionID
+	GroupID       *logging.ConnectionID
 	ProtocolType  string
 	ReferenceTime time.Time
 }
 
 func (f commonFields) MarshalJSONObject(enc *gojay.Encoder) {
-	enc.StringKey("ODCID", f.ODCID.String())
-	enc.StringKey("group_id", f.ODCID.String())
+	if f.ODCID != nil {
+		enc.StringKey("ODCID", f.ODCID.String())
+		enc.StringKey("group_id", f.ODCID.String())
+	}
 	enc.StringKeyOmitEmpty("protocol_type", f.ProtocolType)
 	enc.Float64Key("reference_time", float64(f.ReferenceTime.UnixNano())/1e6)
 	enc.StringKey("time_format", "relative")
diff --git a/qlog/tracer.go b/qlog/tracer.go
new file mode 100644
index 00000000..562f7a26
--- /dev/null
+++ b/qlog/tracer.go
@@ -0,0 +1,60 @@
+package qlog
+
+import (
+	"io"
+	"net"
+	"time"
+
+	"github.com/quic-go/quic-go/internal/protocol"
+	"github.com/quic-go/quic-go/logging"
+)
+
+func NewTracer(w io.WriteCloser) *logging.Tracer {
+	tr := &trace{
+		VantagePoint: vantagePoint{Type: "transport"},
+		CommonFields: commonFields{ReferenceTime: time.Now()},
+	}
+	wr := *newWriter(w, tr)
+	go wr.Run()
+	return &logging.Tracer{
+		SentPacket: func(_ net.Addr, hdr *logging.Header, size logging.ByteCount, frames []logging.Frame) {
+			fs := make([]frame, 0, len(frames))
+			for _, f := range frames {
+				fs = append(fs, frame{Frame: f})
+			}
+			wr.RecordEvent(time.Now(), &eventPacketSent{
+				Header: transformHeader(hdr),
+				Length: size,
+				Frames: fs,
+			})
+		},
+		SentVersionNegotiationPacket: func(_ net.Addr, dest, src logging.ArbitraryLenConnectionID, versions []logging.VersionNumber) {
+			ver := make([]versionNumber, len(versions))
+			for i, v := range versions {
+				ver[i] = versionNumber(v)
+			}
+			wr.RecordEvent(time.Now(), &eventVersionNegotiationSent{
+				Header: packetHeaderVersionNegotiation{
+					SrcConnectionID:  src,
+					DestConnectionID: dest,
+				},
+				SupportedVersions: ver,
+			})
+		},
+		DroppedPacket: func(addr net.Addr, p logging.PacketType, count logging.ByteCount, reason logging.PacketDropReason) {
+			wr.RecordEvent(time.Now(), eventPacketDropped{
+				PacketType:   p,
+				PacketNumber: protocol.InvalidPacketNumber,
+				PacketSize:   count,
+				Trigger:      packetDropReason(reason),
+			})
+		},
+		Debug: func(name, msg string) {
+			wr.RecordEvent(time.Now(), &eventGeneric{
+				name: name,
+				msg:  msg,
+			})
+		},
+		Close: func() { wr.Close() },
+	}
+}


Test patch:
diff --git a/integrationtests/self/conn_id_test.go b/integrationtests/self/conn_id_test.go
index 0d8c4b44..24047bce 100644
--- a/integrationtests/self/conn_id_test.go
+++ b/integrationtests/self/conn_id_test.go
@@ -50,6 +50,7 @@ var _ = Describe("Connection ID lengths tests", func() {
 			ConnectionIDLength:    connIDLen,
 			ConnectionIDGenerator: connIDGenerator,
 		}
+		addTracer(tr)
 		ln, err := tr.Listen(getTLSConfig(), getQuicConfig(nil))
 		Expect(err).ToNot(HaveOccurred())
 		go func() {
@@ -92,6 +93,7 @@ var _ = Describe("Connection ID lengths tests", func() {
 			ConnectionIDLength:    connIDLen,
 			ConnectionIDGenerator: connIDGenerator,
 		}
+		addTracer(tr)
 		defer tr.Close()
 		cl, err := tr.Dial(
 			context.Background(),
diff --git a/integrationtests/self/handshake_rtt_test.go b/integrationtests/self/handshake_rtt_test.go
index 40e541ab..3e2a210f 100644
--- a/integrationtests/self/handshake_rtt_test.go
+++ b/integrationtests/self/handshake_rtt_test.go
@@ -64,6 +64,7 @@ var _ = Describe("Handshake RTT tests", func() {
 			Conn:                     udpConn,
 			MaxUnvalidatedHandshakes: -1,
 		}
+		addTracer(tr)
 		defer tr.Close()
 		ln, err := tr.Listen(serverTLSConfig, serverConfig)
 		Expect(err).ToNot(HaveOccurred())
diff --git a/integrationtests/self/handshake_test.go b/integrationtests/self/handshake_test.go
index 5d7f5868..7ffdd57d 100644
--- a/integrationtests/self/handshake_test.go
+++ b/integrationtests/self/handshake_test.go
@@ -328,7 +328,10 @@ var _ = Describe("Handshake tests", func() {
 			Expect(err).ToNot(HaveOccurred())
 			pconn, err = net.ListenUDP("udp", laddr)
 			Expect(err).ToNot(HaveOccurred())
-			dialer = &quic.Transport{Conn: pconn, ConnectionIDLength: 4}
+			dialer = &quic.Transport{
+				Conn:               pconn,
+				ConnectionIDLength: 4,
+			}
 		})
 
 		AfterEach(func() {
@@ -431,9 +434,8 @@ var _ = Describe("Handshake tests", func() {
 			Expect(err).ToNot(HaveOccurred())
 			udpConn, err := net.ListenUDP("udp", laddr)
 			Expect(err).ToNot(HaveOccurred())
-			tr := quic.Transport{
-				Conn: udpConn,
-			}
+			tr := &quic.Transport{Conn: udpConn}
+			addTracer(tr)
 			defer tr.Close()
 			tlsConf := &tls.Config{}
 			done := make(chan struct{})
@@ -476,10 +478,11 @@ var _ = Describe("Handshake tests", func() {
 
 		It("sends a Retry when the number of handshakes reaches MaxUnvalidatedHandshakes", func() {
 			const limit = 3
-			tr := quic.Transport{
+			tr := &quic.Transport{
 				Conn:                     conn,
 				MaxUnvalidatedHandshakes: limit,
 			}
+			addTracer(tr)
 			defer tr.Close()
 
 			// Block all handshakes.
@@ -541,10 +544,11 @@ var _ = Describe("Handshake tests", func() {
 
 		It("rejects connections when the number of handshakes reaches MaxHandshakes", func() {
 			const limit = 3
-			tr := quic.Transport{
+			tr := &quic.Transport{
 				Conn:          conn,
 				MaxHandshakes: limit,
 			}
+			addTracer(tr)
 			defer tr.Close()
 
 			// Block all handshakes.
@@ -717,6 +721,7 @@ var _ = Describe("Handshake tests", func() {
 				Conn:                     udpConn,
 				MaxUnvalidatedHandshakes: -1,
 			}
+			addTracer(tr)
 			defer tr.Close()
 			server, err := tr.Listen(getTLSConfig(), serverConfig)
 			Expect(err).ToNot(HaveOccurred())
diff --git a/integrationtests/self/mitm_test.go b/integrationtests/self/mitm_test.go
index b0b247ba..be35d7da 100644
--- a/integrationtests/self/mitm_test.go
+++ b/integrationtests/self/mitm_test.go
@@ -41,6 +41,7 @@ var _ = Describe("MITM test", func() {
 			Conn:               c,
 			ConnectionIDLength: connIDLen,
 		}
+		addTracer(serverTransport)
 		if forceAddressValidation {
 			serverTransport.MaxUnvalidatedHandshakes = -1
 		}
@@ -86,6 +87,7 @@ var _ = Describe("MITM test", func() {
 			Conn:               clientUDPConn,
 			ConnectionIDLength: connIDLen,
 		}
+		addTracer(clientTransport)
 	})
 
 	Context("unsuccessful attacks", func() {
diff --git a/integrationtests/self/multiplex_test.go b/integrationtests/self/multiplex_test.go
index dace9a8c..7b202c71 100644
--- a/integrationtests/self/multiplex_test.go
+++ b/integrationtests/self/multiplex_test.go
@@ -74,6 +74,7 @@ var _ = Describe("Multiplexing", func() {
 			Expect(err).ToNot(HaveOccurred())
 			defer conn.Close()
 			tr := &quic.Transport{Conn: conn}
+			addTracer(tr)
 
 			done1 := make(chan struct{})
 			done2 := make(chan struct{})
@@ -109,6 +110,7 @@ var _ = Describe("Multiplexing", func() {
 			Expect(err).ToNot(HaveOccurred())
 			defer conn.Close()
 			tr := &quic.Transport{Conn: conn}
+			addTracer(tr)
 
 			done1 := make(chan struct{})
 			done2 := make(chan struct{})
@@ -139,6 +141,7 @@ var _ = Describe("Multiplexing", func() {
 			Expect(err).ToNot(HaveOccurred())
 			defer conn.Close()
 			tr := &quic.Transport{Conn: conn}
+			addTracer(tr)
 			server, err := tr.Listen(
 				getTLSConfig(),
 				getQuicConfig(nil),
@@ -167,6 +170,7 @@ var _ = Describe("Multiplexing", func() {
 				Expect(err).ToNot(HaveOccurred())
 				defer conn1.Close()
 				tr1 := &quic.Transport{Conn: conn1}
+				addTracer(tr1)
 
 				addr2, err := net.ResolveUDPAddr("udp", "localhost:0")
 				Expect(err).ToNot(HaveOccurred())
@@ -174,6 +178,7 @@ var _ = Describe("Multiplexing", func() {
 				Expect(err).ToNot(HaveOccurred())
 				defer conn2.Close()
 				tr2 := &quic.Transport{Conn: conn2}
+				addTracer(tr2)
 
 				server1, err := tr1.Listen(
 					getTLSConfig(),
@@ -220,6 +225,7 @@ var _ = Describe("Multiplexing", func() {
 		Expect(err).ToNot(HaveOccurred())
 		defer conn1.Close()
 		tr1 := &quic.Transport{Conn: conn1}
+		addTracer(tr1)
 
 		addr2, err := net.ResolveUDPAddr("udp", "localhost:0")
 		Expect(err).ToNot(HaveOccurred())
@@ -227,6 +233,7 @@ var _ = Describe("Multiplexing", func() {
 		Expect(err).ToNot(HaveOccurred())
 		defer conn2.Close()
 		tr2 := &quic.Transport{Conn: conn2}
+		addTracer(tr2)
 
 		server, err := tr1.Listen(getTLSConfig(), getQuicConfig(nil))
 		Expect(err).ToNot(HaveOccurred())
diff --git a/integrationtests/self/self_suite_test.go b/integrationtests/self/self_suite_test.go
index 276adf32..42c8d944 100644
--- a/integrationtests/self/self_suite_test.go
+++ b/integrationtests/self/self_suite_test.go
@@ -86,7 +86,6 @@ var (
 	logBuf       *syncedBuffer
 	versionParam string
 
-	qlogTracer func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer
 	enableQlog bool
 
 	version                          quic.Version
@@ -138,9 +137,6 @@ func init() {
 }
 
 var _ = BeforeSuite(func() {
-	if enableQlog {
-		qlogTracer = tools.NewQlogger(GinkgoWriter)
-	}
 	switch versionParam {
 	case "1":
 		version = quic.Version1
@@ -175,28 +171,48 @@ func getQuicConfig(conf *quic.Config) *quic.Config {
 	} else {
 		conf = conf.Clone()
 	}
-	if enableQlog {
-		if conf.Tracer == nil {
-			conf.Tracer = func(ctx context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
-				return logging.NewMultiplexedConnectionTracer(
-					qlogTracer(ctx, p, connID),
-					// multiplex it with an empty tracer to check that we're correctly ignoring unset callbacks everywhere
-					&logging.ConnectionTracer{},
-				)
-			}
-		} else if qlogTracer != nil {
-			origTracer := conf.Tracer
-			conf.Tracer = func(ctx context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
-				return logging.NewMultiplexedConnectionTracer(
-					qlogTracer(ctx, p, connID),
-					origTracer(ctx, p, connID),
-				)
-			}
+	if !enableQlog {
+		return conf
+	}
+	if conf.Tracer == nil {
+		conf.Tracer = func(ctx context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
+			return logging.NewMultiplexedConnectionTracer(
+				tools.NewQlogConnectionTracer(GinkgoWriter)(ctx, p, connID),
+				// multiplex it with an empty tracer to check that we're correctly ignoring unset callbacks everywhere
+				&logging.ConnectionTracer{},
+			)
 		}
+		return conf
+	}
+	origTracer := conf.Tracer
+	conf.Tracer = func(ctx context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
+		return logging.NewMultiplexedConnectionTracer(
+			tools.NewQlogConnectionTracer(GinkgoWriter)(ctx, p, connID),
+			origTracer(ctx, p, connID),
+		)
 	}
 	return conf
 }
 
+func addTracer(tr *quic.Transport) {
+	if !enableQlog {
+		return
+	}
+	if tr.Tracer == nil {
+		tr.Tracer = logging.NewMultiplexedTracer(
+			tools.QlogTracer(GinkgoWriter),
+			// multiplex it with an empty tracer to check that we're correctly ignoring unset callbacks everywhere
+			&logging.Tracer{},
+		)
+		return
+	}
+	origTracer := tr.Tracer
+	tr.Tracer = logging.NewMultiplexedTracer(
+		tools.QlogTracer(GinkgoWriter),
+		origTracer,
+	)
+}
+
 var _ = BeforeEach(func() {
 	log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds)
 
diff --git a/integrationtests/self/zero_rtt_test.go b/integrationtests/self/zero_rtt_test.go
index 55307679..d25b0482 100644
--- a/integrationtests/self/zero_rtt_test.go
+++ b/integrationtests/self/zero_rtt_test.go
@@ -175,6 +175,7 @@ var _ = Describe("0-RTT", func() {
 				Conn:               udpConn,
 				ConnectionIDLength: connIDLen,
 			}
+			addTracer(tr)
 			defer tr.Close()
 			conn, err = tr.DialEarly(
 				context.Background(),
@@ -463,6 +464,7 @@ var _ = Describe("0-RTT", func() {
 			Conn:                     udpConn,
 			MaxUnvalidatedHandshakes: -1,
 		}
+		addTracer(tr)
 		defer tr.Close()
 		ln, err := tr.ListenEarly(
 			tlsConf,
diff --git a/integrationtests/tools/qlog.go b/integrationtests/tools/qlog.go
index 049432cc..ae19ef4b 100644
--- a/integrationtests/tools/qlog.go
+++ b/integrationtests/tools/qlog.go
@@ -7,6 +7,7 @@ import (
 	"io"
 	"log"
 	"os"
+	"time"
 
 	"github.com/quic-go/quic-go"
 	"github.com/quic-go/quic-go/internal/utils"
@@ -14,13 +15,21 @@ import (
 	"github.com/quic-go/quic-go/qlog"
 )
 
-func NewQlogger(logger io.Writer) func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer {
+func QlogTracer(logger io.Writer) *logging.Tracer {
+	filename := fmt.Sprintf("log_%s_transport.qlog", time.Now().Format("2006-01-02T15:04:05"))
+	fmt.Fprintf(logger, "Creating %s.\n", filename)
+	f, err := os.Create(filename)
+	if err != nil {
+		log.Fatalf("failed to create qlog file: %s", err)
+		return nil
+	}
+	bw := bufio.NewWriter(f)
+	return qlog.NewTracer(utils.NewBufferedWriteCloser(bw, f))
+}
+
+func NewQlogConnectionTracer(logger io.Writer) func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer {
 	return func(_ context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
-		role := "server"
-		if p == logging.PerspectiveClient {
-			role = "client"
-		}
-		filename := fmt.Sprintf("log_%s_%s.qlog", connID, role)
+		filename := fmt.Sprintf("log_%s_%s.qlog", connID, p.String())
 		fmt.Fprintf(logger, "Creating %s.\n", filename)
 		f, err := os.Create(filename)
 		if err != nil {
diff --git a/integrationtests/versionnegotiation/versionnegotiation_suite_test.go b/integrationtests/versionnegotiation/versionnegotiation_suite_test.go
index 150181f2..2cb3f865 100644
--- a/integrationtests/versionnegotiation/versionnegotiation_suite_test.go
+++ b/integrationtests/versionnegotiation/versionnegotiation_suite_test.go
@@ -65,7 +65,7 @@ func maybeAddQLOGTracer(c *quic.Config) *quic.Config {
 	if !enableQlog {
 		return c
 	}
-	qlogger := tools.NewQlogger(GinkgoWriter)
+	qlogger := tools.NewQlogConnectionTracer(GinkgoWriter)
 	if c.Tracer == nil {
 		c.Tracer = qlogger
 	} else if qlogger != nil {
diff --git a/qlog/connection_tracer_test.go b/qlog/connection_tracer_test.go
index dd4b800f..e2c27e07 100644
--- a/qlog/connection_tracer_test.go
+++ b/qlog/connection_tracer_test.go
@@ -32,6 +32,44 @@ type entry struct {
 	Event map[string]interface{}
 }
 
+func exportAndParse(buf *bytes.Buffer) []entry {
+	m := make(map[string]interface{})
+	line, err := buf.ReadBytes('\n')
+	Expect(err).ToNot(HaveOccurred())
+	Expect(json.Unmarshal(line, &m)).To(Succeed())
+	Expect(m).To(HaveKey("trace"))
+	var entries []entry
+	trace := m["trace"].(map[string]interface{})
+	Expect(trace).To(HaveKey("common_fields"))
+	commonFields := trace["common_fields"].(map[string]interface{})
+	Expect(commonFields).To(HaveKey("reference_time"))
+	referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
+	Expect(trace).ToNot(HaveKey("events"))
+
+	for buf.Len() > 0 {
+		line, err := buf.ReadBytes('\n')
+		Expect(err).ToNot(HaveOccurred())
+		ev := make(map[string]interface{})
+		Expect(json.Unmarshal(line, &ev)).To(Succeed())
+		Expect(ev).To(HaveLen(3))
+		Expect(ev).To(HaveKey("time"))
+		Expect(ev).To(HaveKey("name"))
+		Expect(ev).To(HaveKey("data"))
+		entries = append(entries, entry{
+			Time:  referenceTime.Add(time.Duration(ev["time"].(float64)*1e6) * time.Nanosecond),
+			Name:  ev["name"].(string),
+			Event: ev["data"].(map[string]interface{}),
+		})
+	}
+	return entries
+}
+
+func exportAndParseSingle(buf *bytes.Buffer) entry {
+	entries := exportAndParse(buf)
+	Expect(entries).To(HaveLen(1))
+	return entries[0]
+}
+
 var _ = Describe("Tracing", func() {
 	var (
 		tracer *logging.ConnectionTracer
@@ -70,46 +108,6 @@ var _ = Describe("Tracing", func() {
 	})
 
 	Context("Events", func() {
-		exportAndParse := func() []entry {
-			tracer.Close()
-
-			m := make(map[string]interface{})
-			line, err := buf.ReadBytes('\n')
-			Expect(err).ToNot(HaveOccurred())
-			Expect(json.Unmarshal(line, &m)).To(Succeed())
-			Expect(m).To(HaveKey("trace"))
-			var entries []entry
-			trace := m["trace"].(map[string]interface{})
-			Expect(trace).To(HaveKey("common_fields"))
-			commonFields := trace["common_fields"].(map[string]interface{})
-			Expect(commonFields).To(HaveKey("reference_time"))
-			referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
-			Expect(trace).ToNot(HaveKey("events"))
-
-			for buf.Len() > 0 {
-				line, err := buf.ReadBytes('\n')
-				Expect(err).ToNot(HaveOccurred())
-				ev := make(map[string]interface{})
-				Expect(json.Unmarshal(line, &ev)).To(Succeed())
-				Expect(ev).To(HaveLen(3))
-				Expect(ev).To(HaveKey("time"))
-				Expect(ev).To(HaveKey("name"))
-				Expect(ev).To(HaveKey("data"))
-				entries = append(entries, entry{
-					Time:  referenceTime.Add(time.Duration(ev["time"].(float64)*1e6) * time.Nanosecond),
-					Name:  ev["name"].(string),
-					Event: ev["data"].(map[string]interface{}),
-				})
-			}
-			return entries
-		}
-
-		exportAndParseSingle := func() entry {
-			entries := exportAndParse()
-			Expect(entries).To(HaveLen(1))
-			return entries[0]
-		}
-
 		It("records connection starts", func() {
 			tracer.StartedConnection(
 				&net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42},
@@ -117,7 +115,8 @@ var _ = Describe("Tracing", func() {
 				protocol.ParseConnectionID([]byte{1, 2, 3, 4}),
 				protocol.ParseConnectionID([]byte{5, 6, 7, 8}),
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_started"))
 			ev := entry.Event
@@ -132,7 +131,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records the version, if no version negotiation happened", func() {
 			tracer.NegotiatedVersion(0x1337, nil, nil)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:version_information"))
 			ev := entry.Event
@@ -142,7 +142,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records the version, if version negotiation happened", func() {
 			tracer.NegotiatedVersion(0x1337, []logging.VersionNumber{1, 2, 3}, []logging.VersionNumber{4, 5, 6})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:version_information"))
 			ev := entry.Event
@@ -156,7 +157,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records idle timeouts", func() {
 			tracer.ClosedConnection(&quic.IdleTimeoutError{})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_closed"))
 			ev := entry.Event
@@ -167,7 +169,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records handshake timeouts", func() {
 			tracer.ClosedConnection(&quic.HandshakeTimeoutError{})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_closed"))
 			ev := entry.Event
@@ -180,7 +183,8 @@ var _ = Describe("Tracing", func() {
 			tracer.ClosedConnection(&quic.StatelessResetError{
 				Token: protocol.StatelessResetToken{0x00, 0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff},
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_closed"))
 			ev := entry.Event
@@ -192,7 +196,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records connection closing due to version negotiation failure", func() {
 			tracer.ClosedConnection(&quic.VersionNegotiationError{})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_closed"))
 			ev := entry.Event
@@ -206,7 +211,8 @@ var _ = Describe("Tracing", func() {
 				ErrorCode:    1337,
 				ErrorMessage: "foobar",
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_closed"))
 			ev := entry.Event
@@ -221,7 +227,8 @@ var _ = Describe("Tracing", func() {
 				ErrorCode:    qerr.AEADLimitReached,
 				ErrorMessage: "foobar",
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:connection_closed"))
 			ev := entry.Event
@@ -252,7 +259,8 @@ var _ = Describe("Tracing", func() {
 				ActiveConnectionIDLimit:         7,
 				MaxDatagramFrameSize:            protocol.InvalidByteCount,
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_set"))
 			ev := entry.Event
@@ -280,7 +288,8 @@ var _ = Describe("Tracing", func() {
 				OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}),
 				ActiveConnectionIDLimit:         7,
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_set"))
 			ev := entry.Event
@@ -291,7 +300,8 @@ var _ = Describe("Tracing", func() {
 			tracer.SentTransportParameters(&logging.TransportParameters{
 				StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00},
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_set"))
 			ev := entry.Event
@@ -308,7 +318,8 @@ var _ = Describe("Tracing", func() {
 					StatelessResetToken: protocol.StatelessResetToken{15, 14, 13, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0},
 				},
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_set"))
 			ev := entry.Event
@@ -327,7 +338,8 @@ var _ = Describe("Tracing", func() {
 			tracer.SentTransportParameters(&logging.TransportParameters{
 				MaxDatagramFrameSize: 1337,
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_set"))
 			ev := entry.Event
@@ -336,7 +348,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records received transport parameters", func() {
 			tracer.ReceivedTransportParameters(&logging.TransportParameters{})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_set"))
 			ev := entry.Event
@@ -352,7 +365,8 @@ var _ = Describe("Tracing", func() {
 				InitialMaxData:                 400,
 				MaxIdleTimeout:                 123 * time.Millisecond,
 			})
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:parameters_restored"))
 			ev := entry.Event
@@ -388,7 +402,8 @@ var _ = Describe("Tracing", func() {
 					&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
 				},
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_sent"))
 			ev := entry.Event
@@ -420,7 +435,8 @@ var _ = Describe("Tracing", func() {
 				&logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}},
 				[]logging.Frame{&logging.MaxDataFrame{MaximumData: 987}},
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			ev := entry.Event
 			raw := ev["raw"].(map[string]interface{})
 			Expect(raw).To(HaveKeyWithValue("length", float64(123)))
@@ -457,7 +473,8 @@ var _ = Describe("Tracing", func() {
 					&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
 				},
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_received"))
 			ev := entry.Event
@@ -494,7 +511,8 @@ var _ = Describe("Tracing", func() {
 					&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
 				},
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_received"))
 			ev := entry.Event
@@ -522,7 +540,8 @@ var _ = Describe("Tracing", func() {
 					Version:          protocol.Version1,
 				},
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_received"))
 			ev := entry.Event
@@ -546,7 +565,8 @@ var _ = Describe("Tracing", func() {
 				protocol.ArbitraryLenConnectionID{4, 3, 2, 1},
 				[]protocol.Version{0xdeadbeef, 0xdecafbad},
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_received"))
 			ev := entry.Event
@@ -564,7 +584,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records buffered packets", func() {
 			tracer.BufferedPacket(logging.PacketTypeHandshake, 1337)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_buffered"))
 			ev := entry.Event
@@ -579,7 +600,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records dropped packets", func() {
 			tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_dropped"))
 			ev := entry.Event
@@ -594,7 +616,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records dropped packets with a packet number", func() {
 			tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:packet_dropped"))
 			ev := entry.Event
@@ -626,7 +649,8 @@ var _ = Describe("Tracing", func() {
 				1234,
 				42,
 			)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:metrics_updated"))
 			ev := entry.Event
@@ -668,7 +692,8 @@ var _ = Describe("Tracing", func() {
 				12345, // changed
 				42,
 			)
-			entries := exportAndParse()
+			tracer.Close()
+			entries := exportAndParse(buf)
 			Expect(entries).To(HaveLen(2))
 			Expect(entries[0].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entries[0].Name).To(Equal("recovery:metrics_updated"))
@@ -685,7 +710,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records lost packets", func() {
 			tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:packet_lost"))
 			ev := entry.Event
@@ -699,7 +725,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records congestion state updates", func() {
 			tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:congestion_state_updated"))
 			ev := entry.Event
@@ -708,7 +735,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records PTO changes", func() {
 			tracer.UpdatedPTOCount(42)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:metrics_updated"))
 			Expect(entry.Event).To(HaveKeyWithValue("pto_count", float64(42)))
@@ -716,7 +744,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records TLS key updates", func() {
 			tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("security:key_updated"))
 			ev := entry.Event
@@ -729,7 +758,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records TLS key updates, for 1-RTT keys", func() {
 			tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("security:key_updated"))
 			ev := entry.Event
@@ -742,7 +772,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records QUIC key updates", func() {
 			tracer.UpdatedKey(1337, true)
-			entries := exportAndParse()
+			tracer.Close()
+			entries := exportAndParse(buf)
 			Expect(entries).To(HaveLen(2))
 			var keyTypes []string
 			for _, entry := range entries {
@@ -760,7 +791,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records dropped encryption levels", func() {
 			tracer.DroppedEncryptionLevel(protocol.EncryptionInitial)
-			entries := exportAndParse()
+			tracer.Close()
+			entries := exportAndParse(buf)
 			Expect(entries).To(HaveLen(2))
 			var keyTypes []string
 			for _, entry := range entries {
@@ -777,7 +809,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records dropped 0-RTT keys", func() {
 			tracer.DroppedEncryptionLevel(protocol.Encryption0RTT)
-			entries := exportAndParse()
+			tracer.Close()
+			entries := exportAndParse(buf)
 			Expect(entries).To(HaveLen(1))
 			entry := entries[0]
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
@@ -789,7 +822,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records dropped keys", func() {
 			tracer.DroppedKey(42)
-			entries := exportAndParse()
+			tracer.Close()
+			entries := exportAndParse(buf)
 			Expect(entries).To(HaveLen(2))
 			var keyTypes []string
 			for _, entry := range entries {
@@ -808,7 +842,8 @@ var _ = Describe("Tracing", func() {
 		It("records when the timer is set", func() {
 			timeout := time.Now().Add(137 * time.Millisecond)
 			tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:loss_timer_updated"))
 			ev := entry.Event
@@ -823,7 +858,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records when the loss timer expires", func() {
 			tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:loss_timer_updated"))
 			ev := entry.Event
@@ -835,7 +871,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records when the timer is canceled", func() {
 			tracer.LossTimerCanceled()
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:loss_timer_updated"))
 			ev := entry.Event
@@ -845,7 +882,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records an ECN state transition, without a trigger", func() {
 			tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:ecn_state_updated"))
 			ev := entry.Event
@@ -855,7 +893,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records an ECN state transition, with a trigger", func() {
 			tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts)
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("recovery:ecn_state_updated"))
 			ev := entry.Event
@@ -866,7 +905,8 @@ var _ = Describe("Tracing", func() {
 
 		It("records a generic event", func() {
 			tracer.Debug("foo", "bar")
-			entry := exportAndParseSingle()
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
 			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 			Expect(entry.Name).To(Equal("transport:foo"))
 			ev := entry.Event
diff --git a/qlog/tracer_test.go b/qlog/tracer_test.go
new file mode 100644
index 00000000..8aa8faa5
--- /dev/null
+++ b/qlog/tracer_test.go
@@ -0,0 +1,137 @@
+package qlog
+
+import (
+	"bytes"
+	"encoding/json"
+	"net"
+	"time"
+
+	"github.com/quic-go/quic-go/internal/protocol"
+	"github.com/quic-go/quic-go/logging"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+)
+
+var _ = Describe("Tracing", func() {
+	var (
+		tracer *logging.Tracer
+		buf    *bytes.Buffer
+	)
+
+	BeforeEach(func() {
+		buf = &bytes.Buffer{}
+		tracer = NewTracer(nopWriteCloser(buf))
+	})
+
+	It("exports a trace that has the right metadata", func() {
+		tracer.Close()
+
+		m := make(map[string]interface{})
+		Expect(json.Unmarshal(buf.Bytes(), &m)).To(Succeed())
+		Expect(m).To(HaveKeyWithValue("qlog_version", "draft-02"))
+		Expect(m).To(HaveKey("title"))
+		Expect(m).To(HaveKey("trace"))
+		trace := m["trace"].(map[string]interface{})
+		Expect(trace).To(HaveKey(("common_fields")))
+		commonFields := trace["common_fields"].(map[string]interface{})
+		Expect(commonFields).ToNot(HaveKey("ODCID"))
+		Expect(commonFields).ToNot(HaveKey("group_id"))
+		Expect(commonFields).To(HaveKey("reference_time"))
+		referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
+		Expect(referenceTime).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+		Expect(commonFields).To(HaveKeyWithValue("time_format", "relative"))
+		Expect(trace).To(HaveKey("vantage_point"))
+		vantagePoint := trace["vantage_point"].(map[string]interface{})
+		Expect(vantagePoint).To(HaveKeyWithValue("type", "transport"))
+	})
+
+	Context("Events", func() {
+		It("records a sent long header packet, without an ACK", func() {
+			tracer.SentPacket(
+				nil,
+				&logging.Header{
+					Type:             protocol.PacketTypeHandshake,
+					DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}),
+					SrcConnectionID:  protocol.ParseConnectionID([]byte{4, 3, 2, 1}),
+					Length:           1337,
+					Version:          protocol.Version1,
+				},
+				1234,
+				[]logging.Frame{
+					&logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987},
+					&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
+				},
+			)
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
+			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+			Expect(entry.Name).To(Equal("transport:packet_sent"))
+			ev := entry.Event
+			Expect(ev).To(HaveKey("raw"))
+			raw := ev["raw"].(map[string]interface{})
+			Expect(raw).To(HaveKeyWithValue("length", float64(1234)))
+			Expect(ev).To(HaveKey("header"))
+			hdr := ev["header"].(map[string]interface{})
+			Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake"))
+			Expect(hdr).To(HaveKeyWithValue("scid", "04030201"))
+			Expect(ev).To(HaveKey("frames"))
+			frames := ev["frames"].([]interface{})
+			Expect(frames).To(HaveLen(2))
+			Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_stream_data"))
+			Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream"))
+		})
+
+		It("records sending of a Version Negotiation packet", func() {
+			tracer.SentVersionNegotiationPacket(
+				nil,
+				protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8},
+				protocol.ArbitraryLenConnectionID{4, 3, 2, 1},
+				[]protocol.Version{0xdeadbeef, 0xdecafbad},
+			)
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
+			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+			Expect(entry.Name).To(Equal("transport:packet_sent"))
+			ev := entry.Event
+			Expect(ev).To(HaveKey("header"))
+			Expect(ev).ToNot(HaveKey("frames"))
+			Expect(ev).To(HaveKey("supported_versions"))
+			Expect(ev["supported_versions"].([]interface{})).To(Equal([]interface{}{"deadbeef", "decafbad"}))
+			header := ev["header"]
+			Expect(header).To(HaveKeyWithValue("packet_type", "version_negotiation"))
+			Expect(header).ToNot(HaveKey("packet_number"))
+			Expect(header).ToNot(HaveKey("version"))
+			Expect(header).To(HaveKeyWithValue("dcid", "0102030405060708"))
+			Expect(header).To(HaveKeyWithValue("scid", "04030201"))
+		})
+
+		It("records dropped packets", func() {
+			addr := net.UDPAddr{IP: net.IPv4(1, 2, 3, 4), Port: 1234}
+			tracer.DroppedPacket(&addr, logging.PacketTypeInitial, 1337, logging.PacketDropPayloadDecryptError)
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
+			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+			Expect(entry.Name).To(Equal("transport:packet_dropped"))
+			ev := entry.Event
+			Expect(ev).To(HaveKey("raw"))
+			Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337)))
+			Expect(ev).To(HaveKey("header"))
+			hdr := ev["header"].(map[string]interface{})
+			Expect(hdr).To(HaveLen(1))
+			Expect(hdr).To(HaveKeyWithValue("packet_type", "initial"))
+			Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error"))
+		})
+
+		It("records a generic event", func() {
+			tracer.Debug("foo", "bar")
+			tracer.Close()
+			entry := exportAndParseSingle(buf)
+			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+			Expect(entry.Name).To(Equal("transport:foo"))
+			ev := entry.Event
+			Expect(ev).To(HaveLen(1))
+			Expect(ev).To(HaveKeyWithValue("details", "bar"))
+		})
+	})
+})