From 0344401de52529914aaa4892d5d736f569d3ef36 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 16:45:51 +0700 Subject: [PATCH 1/3] qlog: rename qlog.go to connection_tracer.go (#4301) --- qlog/{qlog.go => connection_tracer.go} | 29 ------------------- ...qlog_test.go => connection_tracer_test.go} | 0 qlog/trace.go | 29 +++++++++++++++++++ 3 files changed, 29 insertions(+), 29 deletions(-) rename qlog/{qlog.go => connection_tracer.go} (95%) rename qlog/{qlog_test.go => connection_tracer_test.go} (100%) diff --git a/qlog/qlog.go b/qlog/connection_tracer.go similarity index 95% rename from qlog/qlog.go rename to qlog/connection_tracer.go index 39c54af796a..e9e88e88088 100644 --- a/qlog/qlog.go +++ b/qlog/connection_tracer.go @@ -6,7 +6,6 @@ import ( "io" "log" "net" - "runtime/debug" "time" "github.com/quic-go/quic-go/internal/protocol" @@ -17,34 +16,6 @@ import ( "github.com/francoispqt/gojay" ) -// Setting of this only works when quic-go is used as a library. -// When building a binary from this repository, the version can be set using the following go build flag: -// -ldflags="-X github.com/quic-go/quic-go/qlog.quicGoVersion=foobar" -var quicGoVersion = "(devel)" - -func init() { - if quicGoVersion != "(devel)" { // variable set by ldflags - return - } - info, ok := debug.ReadBuildInfo() - if !ok { // no build info available. This happens when quic-go is not used as a library. - return - } - for _, d := range info.Deps { - if d.Path == "github.com/quic-go/quic-go" { - quicGoVersion = d.Version - if d.Replace != nil { - if len(d.Replace.Version) > 0 { - quicGoVersion = d.Version - } else { - quicGoVersion += " (replaced)" - } - } - break - } - } -} - const eventChanSize = 50 type connectionTracer struct { diff --git a/qlog/qlog_test.go b/qlog/connection_tracer_test.go similarity index 100% rename from qlog/qlog_test.go rename to qlog/connection_tracer_test.go diff --git a/qlog/trace.go b/qlog/trace.go index bb1d5bb8ff3..dcb7da6fc6c 100644 --- a/qlog/trace.go +++ b/qlog/trace.go @@ -1,6 +1,7 @@ package qlog import ( + "runtime/debug" "time" "github.com/quic-go/quic-go/internal/protocol" @@ -9,6 +10,34 @@ import ( "github.com/francoispqt/gojay" ) +// Setting of this only works when quic-go is used as a library. +// When building a binary from this repository, the version can be set using the following go build flag: +// -ldflags="-X github.com/quic-go/quic-go/qlog.quicGoVersion=foobar" +var quicGoVersion = "(devel)" + +func init() { + if quicGoVersion != "(devel)" { // variable set by ldflags + return + } + info, ok := debug.ReadBuildInfo() + if !ok { // no build info available. This happens when quic-go is not used as a library. + return + } + for _, d := range info.Deps { + if d.Path == "github.com/quic-go/quic-go" { + quicGoVersion = d.Version + if d.Replace != nil { + if len(d.Replace.Version) > 0 { + quicGoVersion = d.Version + } else { + quicGoVersion += " (replaced)" + } + } + break + } + } +} + type topLevel struct { trace trace } From 225d2a3926a92af476d669fe051925702855ac75 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 17:00:15 +0700 Subject: [PATCH 2/3] qlog: disentangle the ConnectionTracer from the qlog writer (#4300) The qlog writer simply records events, puts them into a channel, and consumes these events in a separate Go routine (by serializing them). The ConnectionTracer is the one generating those events. --- qlog/connection_tracer.go | 96 +- qlog/connection_tracer_test.go | 1566 ++++++++++++++++---------------- qlog/writer.go | 84 ++ qlog/writer_test.go | 49 + 4 files changed, 915 insertions(+), 880 deletions(-) create mode 100644 qlog/writer.go create mode 100644 qlog/writer_test.go diff --git a/qlog/connection_tracer.go b/qlog/connection_tracer.go index e9e88e88088..ae328a385d5 100644 --- a/qlog/connection_tracer.go +++ b/qlog/connection_tracer.go @@ -1,10 +1,7 @@ package qlog import ( - "bytes" - "fmt" "io" - "log" "net" "time" @@ -16,32 +13,28 @@ import ( "github.com/francoispqt/gojay" ) -const eventChanSize = 50 - type connectionTracer struct { - w io.WriteCloser - odcid protocol.ConnectionID - perspective protocol.Perspective - referenceTime time.Time - - events chan event - encodeErr error - runStopped chan struct{} - + w writer lastMetrics *metrics + + perspective logging.Perspective } // NewConnectionTracer creates a new tracer to record a qlog for a connection. -func NewConnectionTracer(w io.WriteCloser, p protocol.Perspective, odcid protocol.ConnectionID) *logging.ConnectionTracer { +func NewConnectionTracer(w io.WriteCloser, p logging.Perspective, odcid protocol.ConnectionID) *logging.ConnectionTracer { + tr := &trace{ + VantagePoint: vantagePoint{Type: p}, + CommonFields: commonFields{ + ODCID: odcid, + GroupID: odcid, + ReferenceTime: time.Now(), + }, + } t := connectionTracer{ - w: w, - perspective: p, - odcid: odcid, - runStopped: make(chan struct{}), - events: make(chan event, eventChanSize), - referenceTime: time.Now(), + w: *newWriter(w, tr), + perspective: p, } - go t.run() + go t.w.Run() return &logging.ConnectionTracer{ StartedConnection: func(local, remote net.Addr, srcConnID, destConnID logging.ConnectionID) { t.StartedConnection(local, remote, srcConnID, destConnID) @@ -125,65 +118,12 @@ func NewConnectionTracer(w io.WriteCloser, p protocol.Perspective, odcid protoco } } -func (t *connectionTracer) run() { - defer close(t.runStopped) - buf := &bytes.Buffer{} - enc := gojay.NewEncoder(buf) - tl := &topLevel{ - trace: trace{ - VantagePoint: vantagePoint{Type: t.perspective}, - CommonFields: commonFields{ - ODCID: t.odcid, - GroupID: t.odcid, - ReferenceTime: t.referenceTime, - }, - }, - } - if err := enc.Encode(tl); err != nil { - panic(fmt.Sprintf("qlog encoding into a bytes.Buffer failed: %s", err)) - } - if err := buf.WriteByte('\n'); err != nil { - panic(fmt.Sprintf("qlog encoding into a bytes.Buffer failed: %s", err)) - } - if _, err := t.w.Write(buf.Bytes()); err != nil { - t.encodeErr = err - } - enc = gojay.NewEncoder(t.w) - for ev := range t.events { - if t.encodeErr != nil { // if encoding failed, just continue draining the event channel - continue - } - if err := enc.Encode(ev); err != nil { - t.encodeErr = err - continue - } - if _, err := t.w.Write([]byte{'\n'}); err != nil { - t.encodeErr = err - } - } +func (t *connectionTracer) recordEvent(eventTime time.Time, details eventDetails) { + t.w.RecordEvent(eventTime, details) } func (t *connectionTracer) Close() { - if err := t.export(); err != nil { - log.Printf("exporting qlog failed: %s\n", err) - } -} - -// export writes a qlog. -func (t *connectionTracer) export() error { - close(t.events) - <-t.runStopped - if t.encodeErr != nil { - return t.encodeErr - } - return t.w.Close() -} - -func (t *connectionTracer) recordEvent(eventTime time.Time, details eventDetails) { - t.events <- event{ - RelativeTime: eventTime.Sub(t.referenceTime), - eventDetails: details, - } + t.w.Close() } func (t *connectionTracer) StartedConnection(local, remote net.Addr, srcConnID, destConnID protocol.ConnectionID) { diff --git a/qlog/connection_tracer_test.go b/qlog/connection_tracer_test.go index 29de43e8794..1e879ad91e8 100644 --- a/qlog/connection_tracer_test.go +++ b/qlog/connection_tracer_test.go @@ -3,12 +3,9 @@ package qlog import ( "bytes" "encoding/json" - "errors" "io" - "log" "net" "net/netip" - "os" "time" "github.com/quic-go/quic-go" @@ -29,21 +26,6 @@ func nopWriteCloser(w io.Writer) io.WriteCloser { return &nopWriteCloserImpl{Writer: w} } -type limitedWriter struct { - io.WriteCloser - N int - written int -} - -func (w *limitedWriter) Write(p []byte) (int, error) { - if w.written+len(p) > w.N { - return 0, errors.New("writer full") - } - n, err := w.WriteCloser.Write(p) - w.written += n - return n, err -} - type entry struct { Time time.Time Name string @@ -51,865 +33,845 @@ type entry struct { } var _ = Describe("Tracing", func() { - It("stops writing when encountering an error", func() { - buf := &bytes.Buffer{} - t := NewConnectionTracer( - &limitedWriter{WriteCloser: nopWriteCloser(buf), N: 250}, - protocol.PerspectiveServer, + var ( + tracer *logging.ConnectionTracer + buf *bytes.Buffer + ) + + BeforeEach(func() { + buf = &bytes.Buffer{} + tracer = NewConnectionTracer( + nopWriteCloser(buf), + logging.PerspectiveServer, protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), ) - for i := uint32(0); i < 1000; i++ { - t.UpdatedPTOCount(i) - } - - b := &bytes.Buffer{} - log.SetOutput(b) - defer log.SetOutput(os.Stdout) - t.Close() - Expect(b.String()).To(ContainSubstring("writer full")) }) - Context("connection tracer", func() { - var ( - tracer *logging.ConnectionTracer - buf *bytes.Buffer - ) - - BeforeEach(func() { - buf = &bytes.Buffer{} - tracer = NewConnectionTracer( - nopWriteCloser(buf), - logging.PerspectiveServer, - protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), - ) - }) + 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).To(HaveKeyWithValue("ODCID", "deadbeef")) + Expect(commonFields).To(HaveKeyWithValue("group_id", "deadbeef")) + 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", "server")) + }) - It("exports a trace that has the right metadata", func() { + Context("Events", func() { + exportAndParse := func() []entry { 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")) + 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"))) + Expect(trace).To(HaveKey("common_fields")) commonFields := trace["common_fields"].(map[string]interface{}) - Expect(commonFields).To(HaveKeyWithValue("ODCID", "deadbeef")) - Expect(commonFields).To(HaveKeyWithValue("group_id", "deadbeef")) 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", "server")) - }) - - Context("Events", func() { - exportAndParse := func() []entry { - tracer.Close() + Expect(trace).ToNot(HaveKey("events")) - m := make(map[string]interface{}) + for buf.Len() > 0 { 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] + 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 + } - It("records connection starts", func() { - tracer.StartedConnection( - &net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42}, - &net.UDPAddr{IP: net.IPv4(192, 168, 12, 34), Port: 24}, - protocol.ParseConnectionID([]byte{1, 2, 3, 4}), - protocol.ParseConnectionID([]byte{5, 6, 7, 8}), - ) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_started")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("ip_version", "ipv4")) - Expect(ev).To(HaveKeyWithValue("src_ip", "192.168.13.37")) - Expect(ev).To(HaveKeyWithValue("src_port", float64(42))) - Expect(ev).To(HaveKeyWithValue("dst_ip", "192.168.12.34")) - Expect(ev).To(HaveKeyWithValue("dst_port", float64(24))) - Expect(ev).To(HaveKeyWithValue("src_cid", "01020304")) - Expect(ev).To(HaveKeyWithValue("dst_cid", "05060708")) - }) - - It("records the version, if no version negotiation happened", func() { - tracer.NegotiatedVersion(0x1337, nil, nil) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:version_information")) - ev := entry.Event - Expect(ev).To(HaveLen(1)) - Expect(ev).To(HaveKeyWithValue("chosen_version", "1337")) - }) + exportAndParseSingle := func() entry { + entries := exportAndParse() + Expect(entries).To(HaveLen(1)) + return entries[0] + } - It("records the version, if version negotiation happened", func() { - tracer.NegotiatedVersion(0x1337, []logging.VersionNumber{1, 2, 3}, []logging.VersionNumber{4, 5, 6}) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:version_information")) - ev := entry.Event - Expect(ev).To(HaveLen(3)) - Expect(ev).To(HaveKeyWithValue("chosen_version", "1337")) - Expect(ev).To(HaveKey("client_versions")) - Expect(ev["client_versions"].([]interface{})).To(Equal([]interface{}{"1", "2", "3"})) - Expect(ev).To(HaveKey("server_versions")) - Expect(ev["server_versions"].([]interface{})).To(Equal([]interface{}{"4", "5", "6"})) - }) + It("records connection starts", func() { + tracer.StartedConnection( + &net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42}, + &net.UDPAddr{IP: net.IPv4(192, 168, 12, 34), Port: 24}, + protocol.ParseConnectionID([]byte{1, 2, 3, 4}), + protocol.ParseConnectionID([]byte{5, 6, 7, 8}), + ) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_started")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("ip_version", "ipv4")) + Expect(ev).To(HaveKeyWithValue("src_ip", "192.168.13.37")) + Expect(ev).To(HaveKeyWithValue("src_port", float64(42))) + Expect(ev).To(HaveKeyWithValue("dst_ip", "192.168.12.34")) + Expect(ev).To(HaveKeyWithValue("dst_port", float64(24))) + Expect(ev).To(HaveKeyWithValue("src_cid", "01020304")) + Expect(ev).To(HaveKeyWithValue("dst_cid", "05060708")) + }) - It("records idle timeouts", func() { - tracer.ClosedConnection(&quic.IdleTimeoutError{}) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_closed")) - ev := entry.Event - Expect(ev).To(HaveLen(2)) - Expect(ev).To(HaveKeyWithValue("owner", "local")) - Expect(ev).To(HaveKeyWithValue("trigger", "idle_timeout")) - }) + It("records the version, if no version negotiation happened", func() { + tracer.NegotiatedVersion(0x1337, nil, nil) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:version_information")) + ev := entry.Event + Expect(ev).To(HaveLen(1)) + Expect(ev).To(HaveKeyWithValue("chosen_version", "1337")) + }) - It("records handshake timeouts", func() { - tracer.ClosedConnection(&quic.HandshakeTimeoutError{}) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_closed")) - ev := entry.Event - Expect(ev).To(HaveLen(2)) - Expect(ev).To(HaveKeyWithValue("owner", "local")) - Expect(ev).To(HaveKeyWithValue("trigger", "handshake_timeout")) - }) + It("records the version, if version negotiation happened", func() { + tracer.NegotiatedVersion(0x1337, []logging.VersionNumber{1, 2, 3}, []logging.VersionNumber{4, 5, 6}) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:version_information")) + ev := entry.Event + Expect(ev).To(HaveLen(3)) + Expect(ev).To(HaveKeyWithValue("chosen_version", "1337")) + Expect(ev).To(HaveKey("client_versions")) + Expect(ev["client_versions"].([]interface{})).To(Equal([]interface{}{"1", "2", "3"})) + Expect(ev).To(HaveKey("server_versions")) + Expect(ev["server_versions"].([]interface{})).To(Equal([]interface{}{"4", "5", "6"})) + }) - It("records a received stateless reset packet", 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() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_closed")) - ev := entry.Event - Expect(ev).To(HaveLen(3)) - Expect(ev).To(HaveKeyWithValue("owner", "remote")) - Expect(ev).To(HaveKeyWithValue("trigger", "stateless_reset")) - Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "00112233445566778899aabbccddeeff")) - }) + It("records idle timeouts", func() { + tracer.ClosedConnection(&quic.IdleTimeoutError{}) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_closed")) + ev := entry.Event + Expect(ev).To(HaveLen(2)) + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).To(HaveKeyWithValue("trigger", "idle_timeout")) + }) - It("records connection closing due to version negotiation failure", func() { - tracer.ClosedConnection(&quic.VersionNegotiationError{}) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_closed")) - ev := entry.Event - Expect(ev).To(HaveLen(1)) - Expect(ev).To(HaveKeyWithValue("trigger", "version_mismatch")) - }) + It("records handshake timeouts", func() { + tracer.ClosedConnection(&quic.HandshakeTimeoutError{}) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_closed")) + ev := entry.Event + Expect(ev).To(HaveLen(2)) + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).To(HaveKeyWithValue("trigger", "handshake_timeout")) + }) - It("records application errors", func() { - tracer.ClosedConnection(&quic.ApplicationError{ - Remote: true, - ErrorCode: 1337, - ErrorMessage: "foobar", - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_closed")) - ev := entry.Event - Expect(ev).To(HaveLen(3)) - Expect(ev).To(HaveKeyWithValue("owner", "remote")) - Expect(ev).To(HaveKeyWithValue("application_code", float64(1337))) - Expect(ev).To(HaveKeyWithValue("reason", "foobar")) - }) + It("records a received stateless reset packet", 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() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_closed")) + ev := entry.Event + Expect(ev).To(HaveLen(3)) + Expect(ev).To(HaveKeyWithValue("owner", "remote")) + Expect(ev).To(HaveKeyWithValue("trigger", "stateless_reset")) + Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "00112233445566778899aabbccddeeff")) + }) - It("records transport errors", func() { - tracer.ClosedConnection(&quic.TransportError{ - ErrorCode: qerr.AEADLimitReached, - ErrorMessage: "foobar", - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:connection_closed")) - ev := entry.Event - Expect(ev).To(HaveLen(3)) - Expect(ev).To(HaveKeyWithValue("owner", "local")) - Expect(ev).To(HaveKeyWithValue("connection_code", "aead_limit_reached")) - Expect(ev).To(HaveKeyWithValue("reason", "foobar")) - }) + It("records connection closing due to version negotiation failure", func() { + tracer.ClosedConnection(&quic.VersionNegotiationError{}) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_closed")) + ev := entry.Event + Expect(ev).To(HaveLen(1)) + Expect(ev).To(HaveKeyWithValue("trigger", "version_mismatch")) + }) - It("records sent transport parameters", func() { - rcid := protocol.ParseConnectionID([]byte{0xde, 0xca, 0xfb, 0xad}) - tracer.SentTransportParameters(&logging.TransportParameters{ - InitialMaxStreamDataBidiLocal: 1000, - InitialMaxStreamDataBidiRemote: 2000, - InitialMaxStreamDataUni: 3000, - InitialMaxData: 4000, - MaxBidiStreamNum: 10, - MaxUniStreamNum: 20, - MaxAckDelay: 123 * time.Millisecond, - AckDelayExponent: 12, - DisableActiveMigration: true, - MaxUDPPayloadSize: 1234, - MaxIdleTimeout: 321 * time.Millisecond, - StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, - OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), - InitialSourceConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), - RetrySourceConnectionID: &rcid, - ActiveConnectionIDLimit: 7, - MaxDatagramFrameSize: protocol.InvalidByteCount, - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_set")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("owner", "local")) - Expect(ev).To(HaveKeyWithValue("original_destination_connection_id", "deadc0de")) - Expect(ev).To(HaveKeyWithValue("initial_source_connection_id", "deadbeef")) - Expect(ev).To(HaveKeyWithValue("retry_source_connection_id", "decafbad")) - Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "112233445566778899aabbccddeeff00")) - Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(321))) - Expect(ev).To(HaveKeyWithValue("max_udp_payload_size", float64(1234))) - Expect(ev).To(HaveKeyWithValue("ack_delay_exponent", float64(12))) - Expect(ev).To(HaveKeyWithValue("active_connection_id_limit", float64(7))) - Expect(ev).To(HaveKeyWithValue("initial_max_data", float64(4000))) - Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_local", float64(1000))) - Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_remote", float64(2000))) - Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_uni", float64(3000))) - Expect(ev).To(HaveKeyWithValue("initial_max_streams_bidi", float64(10))) - Expect(ev).To(HaveKeyWithValue("initial_max_streams_uni", float64(20))) - Expect(ev).ToNot(HaveKey("preferred_address")) - Expect(ev).ToNot(HaveKey("max_datagram_frame_size")) - }) + It("records application errors", func() { + tracer.ClosedConnection(&quic.ApplicationError{ + Remote: true, + ErrorCode: 1337, + ErrorMessage: "foobar", + }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_closed")) + ev := entry.Event + Expect(ev).To(HaveLen(3)) + Expect(ev).To(HaveKeyWithValue("owner", "remote")) + Expect(ev).To(HaveKeyWithValue("application_code", float64(1337))) + Expect(ev).To(HaveKeyWithValue("reason", "foobar")) + }) - It("records the server's transport parameters, without a stateless reset token", func() { - tracer.SentTransportParameters(&logging.TransportParameters{ - OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), - ActiveConnectionIDLimit: 7, - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_set")) - ev := entry.Event - Expect(ev).ToNot(HaveKey("stateless_reset_token")) - }) + It("records transport errors", func() { + tracer.ClosedConnection(&quic.TransportError{ + ErrorCode: qerr.AEADLimitReached, + ErrorMessage: "foobar", + }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:connection_closed")) + ev := entry.Event + Expect(ev).To(HaveLen(3)) + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).To(HaveKeyWithValue("connection_code", "aead_limit_reached")) + Expect(ev).To(HaveKeyWithValue("reason", "foobar")) + }) - It("records transport parameters without retry_source_connection_id", 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() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_set")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("owner", "local")) - Expect(ev).ToNot(HaveKey("retry_source_connection_id")) - }) + It("records sent transport parameters", func() { + rcid := protocol.ParseConnectionID([]byte{0xde, 0xca, 0xfb, 0xad}) + tracer.SentTransportParameters(&logging.TransportParameters{ + InitialMaxStreamDataBidiLocal: 1000, + InitialMaxStreamDataBidiRemote: 2000, + InitialMaxStreamDataUni: 3000, + InitialMaxData: 4000, + MaxBidiStreamNum: 10, + MaxUniStreamNum: 20, + MaxAckDelay: 123 * time.Millisecond, + AckDelayExponent: 12, + DisableActiveMigration: true, + MaxUDPPayloadSize: 1234, + MaxIdleTimeout: 321 * time.Millisecond, + StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, + OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), + InitialSourceConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), + RetrySourceConnectionID: &rcid, + ActiveConnectionIDLimit: 7, + MaxDatagramFrameSize: protocol.InvalidByteCount, + }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).To(HaveKeyWithValue("original_destination_connection_id", "deadc0de")) + Expect(ev).To(HaveKeyWithValue("initial_source_connection_id", "deadbeef")) + Expect(ev).To(HaveKeyWithValue("retry_source_connection_id", "decafbad")) + Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "112233445566778899aabbccddeeff00")) + Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(321))) + Expect(ev).To(HaveKeyWithValue("max_udp_payload_size", float64(1234))) + Expect(ev).To(HaveKeyWithValue("ack_delay_exponent", float64(12))) + Expect(ev).To(HaveKeyWithValue("active_connection_id_limit", float64(7))) + Expect(ev).To(HaveKeyWithValue("initial_max_data", float64(4000))) + Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_local", float64(1000))) + Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_remote", float64(2000))) + Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_uni", float64(3000))) + Expect(ev).To(HaveKeyWithValue("initial_max_streams_bidi", float64(10))) + Expect(ev).To(HaveKeyWithValue("initial_max_streams_uni", float64(20))) + Expect(ev).ToNot(HaveKey("preferred_address")) + Expect(ev).ToNot(HaveKey("max_datagram_frame_size")) + }) - It("records transport parameters with a preferred address", func() { - tracer.SentTransportParameters(&logging.TransportParameters{ - PreferredAddress: &logging.PreferredAddress{ - IPv4: netip.AddrPortFrom(netip.AddrFrom4([4]byte{12, 34, 56, 78}), 123), - IPv6: netip.AddrPortFrom(netip.AddrFrom16([16]byte{1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16}), 456), - ConnectionID: protocol.ParseConnectionID([]byte{8, 7, 6, 5, 4, 3, 2, 1}), - StatelessResetToken: protocol.StatelessResetToken{15, 14, 13, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0}, - }, - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_set")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("owner", "local")) - Expect(ev).To(HaveKey("preferred_address")) - pa := ev["preferred_address"].(map[string]interface{}) - Expect(pa).To(HaveKeyWithValue("ip_v4", "12.34.56.78")) - Expect(pa).To(HaveKeyWithValue("port_v4", float64(123))) - Expect(pa).To(HaveKeyWithValue("ip_v6", "102:304:506:708:90a:b0c:d0e:f10")) - Expect(pa).To(HaveKeyWithValue("port_v6", float64(456))) - Expect(pa).To(HaveKeyWithValue("connection_id", "0807060504030201")) - Expect(pa).To(HaveKeyWithValue("stateless_reset_token", "0f0e0d0c0b0a09080706050403020100")) + It("records the server's transport parameters, without a stateless reset token", func() { + tracer.SentTransportParameters(&logging.TransportParameters{ + OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), + ActiveConnectionIDLimit: 7, }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_set")) + ev := entry.Event + Expect(ev).ToNot(HaveKey("stateless_reset_token")) + }) - It("records transport parameters that enable the datagram extension", func() { - tracer.SentTransportParameters(&logging.TransportParameters{ - MaxDatagramFrameSize: 1337, - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_set")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("max_datagram_frame_size", float64(1337))) + It("records transport parameters without retry_source_connection_id", 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() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).ToNot(HaveKey("retry_source_connection_id")) + }) - It("records received transport parameters", func() { - tracer.ReceivedTransportParameters(&logging.TransportParameters{}) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_set")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("owner", "remote")) - Expect(ev).ToNot(HaveKey("original_destination_connection_id")) - }) + It("records transport parameters with a preferred address", func() { + tracer.SentTransportParameters(&logging.TransportParameters{ + PreferredAddress: &logging.PreferredAddress{ + IPv4: netip.AddrPortFrom(netip.AddrFrom4([4]byte{12, 34, 56, 78}), 123), + IPv6: netip.AddrPortFrom(netip.AddrFrom16([16]byte{1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16}), 456), + ConnectionID: protocol.ParseConnectionID([]byte{8, 7, 6, 5, 4, 3, 2, 1}), + StatelessResetToken: protocol.StatelessResetToken{15, 14, 13, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0}, + }, + }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).To(HaveKey("preferred_address")) + pa := ev["preferred_address"].(map[string]interface{}) + Expect(pa).To(HaveKeyWithValue("ip_v4", "12.34.56.78")) + Expect(pa).To(HaveKeyWithValue("port_v4", float64(123))) + Expect(pa).To(HaveKeyWithValue("ip_v6", "102:304:506:708:90a:b0c:d0e:f10")) + Expect(pa).To(HaveKeyWithValue("port_v6", float64(456))) + Expect(pa).To(HaveKeyWithValue("connection_id", "0807060504030201")) + Expect(pa).To(HaveKeyWithValue("stateless_reset_token", "0f0e0d0c0b0a09080706050403020100")) + }) - It("records restored transport parameters", func() { - tracer.RestoredTransportParameters(&logging.TransportParameters{ - InitialMaxStreamDataBidiLocal: 100, - InitialMaxStreamDataBidiRemote: 200, - InitialMaxStreamDataUni: 300, - InitialMaxData: 400, - MaxIdleTimeout: 123 * time.Millisecond, - }) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:parameters_restored")) - ev := entry.Event - Expect(ev).ToNot(HaveKey("owner")) - Expect(ev).ToNot(HaveKey("original_destination_connection_id")) - Expect(ev).ToNot(HaveKey("stateless_reset_token")) - Expect(ev).ToNot(HaveKey("retry_source_connection_id")) - Expect(ev).ToNot(HaveKey("initial_source_connection_id")) - Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(123))) - Expect(ev).To(HaveKeyWithValue("initial_max_data", float64(400))) - Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_local", float64(100))) - Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_remote", float64(200))) - Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_uni", float64(300))) + It("records transport parameters that enable the datagram extension", func() { + tracer.SentTransportParameters(&logging.TransportParameters{ + MaxDatagramFrameSize: 1337, }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("max_datagram_frame_size", float64(1337))) + }) - It("records a sent long header packet, without an ACK", func() { - tracer.SentLongHeaderPacket( - &logging.ExtendedHeader{ - Header: 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, - }, - PacketNumber: 1337, - }, - 987, - logging.ECNCE, - nil, - []logging.Frame{ - &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, - &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, - }, - ) - entry := exportAndParseSingle() - 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(987))) - Expect(raw).To(HaveKeyWithValue("payload_length", float64(1337))) - Expect(ev).To(HaveKey("header")) - hdr := ev["header"].(map[string]interface{}) - Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) - Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) - Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) - Expect(ev).To(HaveKey("frames")) - Expect(ev).To(HaveKeyWithValue("ecn", "CE")) - 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 received transport parameters", func() { + tracer.ReceivedTransportParameters(&logging.TransportParameters{}) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("owner", "remote")) + Expect(ev).ToNot(HaveKey("original_destination_connection_id")) + }) - It("records a sent short header packet, without an ACK", func() { - tracer.SentShortHeaderPacket( - &logging.ShortHeader{ - DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4}), - PacketNumber: 1337, - }, - 123, - logging.ECNUnsupported, - &logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}}, - []logging.Frame{&logging.MaxDataFrame{MaximumData: 987}}, - ) - entry := exportAndParseSingle() - ev := entry.Event - raw := ev["raw"].(map[string]interface{}) - Expect(raw).To(HaveKeyWithValue("length", float64(123))) - Expect(raw).ToNot(HaveKey("payload_length")) - Expect(ev).To(HaveKey("header")) - Expect(ev).ToNot(HaveKey("ecn")) - hdr := ev["header"].(map[string]interface{}) - Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) - Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) - Expect(ev).To(HaveKey("frames")) - frames := ev["frames"].([]interface{}) - Expect(frames).To(HaveLen(2)) - Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "ack")) - Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_data")) - }) + It("records restored transport parameters", func() { + tracer.RestoredTransportParameters(&logging.TransportParameters{ + InitialMaxStreamDataBidiLocal: 100, + InitialMaxStreamDataBidiRemote: 200, + InitialMaxStreamDataUni: 300, + InitialMaxData: 400, + MaxIdleTimeout: 123 * time.Millisecond, + }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:parameters_restored")) + ev := entry.Event + Expect(ev).ToNot(HaveKey("owner")) + Expect(ev).ToNot(HaveKey("original_destination_connection_id")) + Expect(ev).ToNot(HaveKey("stateless_reset_token")) + Expect(ev).ToNot(HaveKey("retry_source_connection_id")) + Expect(ev).ToNot(HaveKey("initial_source_connection_id")) + Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(123))) + Expect(ev).To(HaveKeyWithValue("initial_max_data", float64(400))) + Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_local", float64(100))) + Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_remote", float64(200))) + Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_uni", float64(300))) + }) - It("records a received Long Header packet", func() { - tracer.ReceivedLongHeaderPacket( - &logging.ExtendedHeader{ - Header: logging.Header{ - Type: protocol.PacketTypeInitial, - DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), - SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), - Token: []byte{0xde, 0xad, 0xbe, 0xef}, - Length: 1234, - Version: protocol.Version1, - }, - PacketNumber: 1337, - }, - 789, - logging.ECT0, - []logging.Frame{ - &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, - &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, + It("records a sent long header packet, without an ACK", func() { + tracer.SentLongHeaderPacket( + &logging.ExtendedHeader{ + Header: 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, }, - ) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:packet_received")) - ev := entry.Event - Expect(ev).To(HaveKey("raw")) - raw := ev["raw"].(map[string]interface{}) - Expect(raw).To(HaveKeyWithValue("length", float64(789))) - Expect(raw).To(HaveKeyWithValue("payload_length", float64(1234))) - Expect(ev).To(HaveKeyWithValue("ecn", "ECT(0)")) - Expect(ev).To(HaveKey("header")) - hdr := ev["header"].(map[string]interface{}) - Expect(hdr).To(HaveKeyWithValue("packet_type", "initial")) - Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) - Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) - Expect(hdr).To(HaveKey("token")) - token := hdr["token"].(map[string]interface{}) - Expect(token).To(HaveKeyWithValue("data", "deadbeef")) - Expect(ev).To(HaveKey("frames")) - Expect(ev["frames"].([]interface{})).To(HaveLen(2)) - }) + PacketNumber: 1337, + }, + 987, + logging.ECNCE, + nil, + []logging.Frame{ + &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, + &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, + }, + ) + entry := exportAndParseSingle() + 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(987))) + Expect(raw).To(HaveKeyWithValue("payload_length", float64(1337))) + Expect(ev).To(HaveKey("header")) + hdr := ev["header"].(map[string]interface{}) + Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) + Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) + Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) + Expect(ev).To(HaveKey("frames")) + Expect(ev).To(HaveKeyWithValue("ecn", "CE")) + 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 a received Short Header packet", func() { - shdr := &logging.ShortHeader{ - DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), + It("records a sent short header packet, without an ACK", func() { + tracer.SentShortHeaderPacket( + &logging.ShortHeader{ + DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4}), PacketNumber: 1337, - PacketNumberLen: protocol.PacketNumberLen3, - KeyPhase: protocol.KeyPhaseZero, - } - tracer.ReceivedShortHeaderPacket( - shdr, - 789, - logging.ECT1, - []logging.Frame{ - &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, - &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, - }, - ) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:packet_received")) - ev := entry.Event - Expect(ev).To(HaveKey("raw")) - raw := ev["raw"].(map[string]interface{}) - Expect(raw).To(HaveKeyWithValue("length", float64(789))) - Expect(raw).To(HaveKeyWithValue("payload_length", float64(789-(1+8+3)))) - Expect(ev).To(HaveKeyWithValue("ecn", "ECT(1)")) - Expect(ev).To(HaveKey("header")) - hdr := ev["header"].(map[string]interface{}) - Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) - Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) - Expect(hdr).To(HaveKeyWithValue("key_phase_bit", "0")) - Expect(ev).To(HaveKey("frames")) - Expect(ev["frames"].([]interface{})).To(HaveLen(2)) - }) + }, + 123, + logging.ECNUnsupported, + &logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}}, + []logging.Frame{&logging.MaxDataFrame{MaximumData: 987}}, + ) + entry := exportAndParseSingle() + ev := entry.Event + raw := ev["raw"].(map[string]interface{}) + Expect(raw).To(HaveKeyWithValue("length", float64(123))) + Expect(raw).ToNot(HaveKey("payload_length")) + Expect(ev).To(HaveKey("header")) + Expect(ev).ToNot(HaveKey("ecn")) + hdr := ev["header"].(map[string]interface{}) + Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) + Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) + Expect(ev).To(HaveKey("frames")) + frames := ev["frames"].([]interface{}) + Expect(frames).To(HaveLen(2)) + Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "ack")) + Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_data")) + }) - It("records a received Retry packet", func() { - tracer.ReceivedRetry( - &logging.Header{ - Type: protocol.PacketTypeRetry, + It("records a received Long Header packet", func() { + tracer.ReceivedLongHeaderPacket( + &logging.ExtendedHeader{ + Header: logging.Header{ + Type: protocol.PacketTypeInitial, DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), Token: []byte{0xde, 0xad, 0xbe, 0xef}, + Length: 1234, Version: protocol.Version1, }, - ) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:packet_received")) - ev := entry.Event - Expect(ev).ToNot(HaveKey("raw")) - Expect(ev).To(HaveKey("header")) - header := ev["header"].(map[string]interface{}) - Expect(header).To(HaveKeyWithValue("packet_type", "retry")) - Expect(header).ToNot(HaveKey("packet_number")) - Expect(header).To(HaveKey("version")) - Expect(header).To(HaveKey("dcid")) - Expect(header).To(HaveKey("scid")) - Expect(header).To(HaveKey("token")) - token := header["token"].(map[string]interface{}) - Expect(token).To(HaveKeyWithValue("data", "deadbeef")) - Expect(ev).ToNot(HaveKey("frames")) - }) + PacketNumber: 1337, + }, + 789, + logging.ECT0, + []logging.Frame{ + &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, + &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, + }, + ) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:packet_received")) + ev := entry.Event + Expect(ev).To(HaveKey("raw")) + raw := ev["raw"].(map[string]interface{}) + Expect(raw).To(HaveKeyWithValue("length", float64(789))) + Expect(raw).To(HaveKeyWithValue("payload_length", float64(1234))) + Expect(ev).To(HaveKeyWithValue("ecn", "ECT(0)")) + Expect(ev).To(HaveKey("header")) + hdr := ev["header"].(map[string]interface{}) + Expect(hdr).To(HaveKeyWithValue("packet_type", "initial")) + Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) + Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) + Expect(hdr).To(HaveKey("token")) + token := hdr["token"].(map[string]interface{}) + Expect(token).To(HaveKeyWithValue("data", "deadbeef")) + Expect(ev).To(HaveKey("frames")) + Expect(ev["frames"].([]interface{})).To(HaveLen(2)) + }) - It("records a received Version Negotiation packet", func() { - tracer.ReceivedVersionNegotiationPacket( - protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, - protocol.ArbitraryLenConnectionID{4, 3, 2, 1}, - []protocol.Version{0xdeadbeef, 0xdecafbad}, - ) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:packet_received")) - 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 a received Short Header packet", func() { + shdr := &logging.ShortHeader{ + DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), + PacketNumber: 1337, + PacketNumberLen: protocol.PacketNumberLen3, + KeyPhase: protocol.KeyPhaseZero, + } + tracer.ReceivedShortHeaderPacket( + shdr, + 789, + logging.ECT1, + []logging.Frame{ + &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, + &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, + }, + ) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:packet_received")) + ev := entry.Event + Expect(ev).To(HaveKey("raw")) + raw := ev["raw"].(map[string]interface{}) + Expect(raw).To(HaveKeyWithValue("length", float64(789))) + Expect(raw).To(HaveKeyWithValue("payload_length", float64(789-(1+8+3)))) + Expect(ev).To(HaveKeyWithValue("ecn", "ECT(1)")) + Expect(ev).To(HaveKey("header")) + hdr := ev["header"].(map[string]interface{}) + Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) + Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) + Expect(hdr).To(HaveKeyWithValue("key_phase_bit", "0")) + Expect(ev).To(HaveKey("frames")) + Expect(ev["frames"].([]interface{})).To(HaveLen(2)) + }) - It("records buffered packets", func() { - tracer.BufferedPacket(logging.PacketTypeHandshake, 1337) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("transport:packet_buffered")) - ev := entry.Event - Expect(ev).To(HaveKey("header")) - hdr := ev["header"].(map[string]interface{}) - Expect(hdr).To(HaveLen(1)) - Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) - Expect(ev).To(HaveKey("raw")) - Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) - Expect(ev).To(HaveKeyWithValue("trigger", "keys_unavailable")) - }) + It("records a received Retry packet", func() { + tracer.ReceivedRetry( + &logging.Header{ + Type: protocol.PacketTypeRetry, + DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), + SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), + Token: []byte{0xde, 0xad, 0xbe, 0xef}, + Version: protocol.Version1, + }, + ) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:packet_received")) + ev := entry.Event + Expect(ev).ToNot(HaveKey("raw")) + Expect(ev).To(HaveKey("header")) + header := ev["header"].(map[string]interface{}) + Expect(header).To(HaveKeyWithValue("packet_type", "retry")) + Expect(header).ToNot(HaveKey("packet_number")) + Expect(header).To(HaveKey("version")) + Expect(header).To(HaveKey("dcid")) + Expect(header).To(HaveKey("scid")) + Expect(header).To(HaveKey("token")) + token := header["token"].(map[string]interface{}) + Expect(token).To(HaveKeyWithValue("data", "deadbeef")) + Expect(ev).ToNot(HaveKey("frames")) + }) - It("records dropped packets", func() { - tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError) - entry := exportAndParseSingle() - 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", "retry")) - Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error")) - }) + It("records a received Version Negotiation packet", func() { + tracer.ReceivedVersionNegotiationPacket( + protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, + protocol.ArbitraryLenConnectionID{4, 3, 2, 1}, + []protocol.Version{0xdeadbeef, 0xdecafbad}, + ) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:packet_received")) + 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 with a packet number", func() { - tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate) - entry := exportAndParseSingle() - 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(2)) - Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) - Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) - Expect(ev).To(HaveKeyWithValue("trigger", "duplicate")) - }) + It("records buffered packets", func() { + tracer.BufferedPacket(logging.PacketTypeHandshake, 1337) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("transport:packet_buffered")) + ev := entry.Event + Expect(ev).To(HaveKey("header")) + hdr := ev["header"].(map[string]interface{}) + Expect(hdr).To(HaveLen(1)) + Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) + Expect(ev).To(HaveKey("raw")) + Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) + Expect(ev).To(HaveKeyWithValue("trigger", "keys_unavailable")) + }) - It("records metrics updates", func() { - now := time.Now() - rttStats := utils.NewRTTStats() - rttStats.UpdateRTT(15*time.Millisecond, 0, now) - rttStats.UpdateRTT(20*time.Millisecond, 0, now) - rttStats.UpdateRTT(25*time.Millisecond, 0, now) - Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) - Expect(rttStats.SmoothedRTT()).To(And( - BeNumerically(">", 15*time.Millisecond), - BeNumerically("<", 25*time.Millisecond), - )) - Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) - tracer.UpdatedMetrics( - rttStats, - 4321, - 1234, - 42, - ) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:metrics_updated")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("min_rtt", float64(15))) - Expect(ev).To(HaveKeyWithValue("latest_rtt", float64(25))) - Expect(ev).To(HaveKey("smoothed_rtt")) - Expect(time.Duration(ev["smoothed_rtt"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.SmoothedRTT(), time.Millisecond)) - Expect(ev).To(HaveKey("rtt_variance")) - Expect(time.Duration(ev["rtt_variance"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.MeanDeviation(), time.Millisecond)) - Expect(ev).To(HaveKeyWithValue("congestion_window", float64(4321))) - Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(1234))) - Expect(ev).To(HaveKeyWithValue("packets_in_flight", float64(42))) - }) + It("records dropped packets", func() { + tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError) + entry := exportAndParseSingle() + 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", "retry")) + Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error")) + }) - It("only logs the diff between two metrics updates", func() { - now := time.Now() - rttStats := utils.NewRTTStats() - rttStats.UpdateRTT(15*time.Millisecond, 0, now) - rttStats.UpdateRTT(20*time.Millisecond, 0, now) - rttStats.UpdateRTT(25*time.Millisecond, 0, now) - Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) - - rttStats2 := utils.NewRTTStats() - rttStats2.UpdateRTT(15*time.Millisecond, 0, now) - rttStats2.UpdateRTT(15*time.Millisecond, 0, now) - rttStats2.UpdateRTT(15*time.Millisecond, 0, now) - Expect(rttStats2.MinRTT()).To(Equal(15 * time.Millisecond)) - - Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) - tracer.UpdatedMetrics( - rttStats, - 4321, - 1234, - 42, - ) - tracer.UpdatedMetrics( - rttStats2, - 4321, - 12345, // changed - 42, - ) - entries := exportAndParse() - 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")) - Expect(entries[0].Event).To(HaveLen(7)) - Expect(entries[1].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entries[1].Name).To(Equal("recovery:metrics_updated")) - ev := entries[1].Event - Expect(ev).ToNot(HaveKey("min_rtt")) - Expect(ev).ToNot(HaveKey("congestion_window")) - Expect(ev).ToNot(HaveKey("packets_in_flight")) - Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(12345))) - Expect(ev).To(HaveKeyWithValue("smoothed_rtt", float64(15))) - }) + It("records dropped packets with a packet number", func() { + tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate) + entry := exportAndParseSingle() + 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(2)) + Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) + Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) + Expect(ev).To(HaveKeyWithValue("trigger", "duplicate")) + }) - It("records lost packets", func() { - tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:packet_lost")) - ev := entry.Event - Expect(ev).To(HaveKey("header")) - hdr := ev["header"].(map[string]interface{}) - Expect(hdr).To(HaveLen(2)) - Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) - Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) - Expect(ev).To(HaveKeyWithValue("trigger", "reordering_threshold")) - }) + It("records metrics updates", func() { + now := time.Now() + rttStats := utils.NewRTTStats() + rttStats.UpdateRTT(15*time.Millisecond, 0, now) + rttStats.UpdateRTT(20*time.Millisecond, 0, now) + rttStats.UpdateRTT(25*time.Millisecond, 0, now) + Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) + Expect(rttStats.SmoothedRTT()).To(And( + BeNumerically(">", 15*time.Millisecond), + BeNumerically("<", 25*time.Millisecond), + )) + Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) + tracer.UpdatedMetrics( + rttStats, + 4321, + 1234, + 42, + ) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:metrics_updated")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("min_rtt", float64(15))) + Expect(ev).To(HaveKeyWithValue("latest_rtt", float64(25))) + Expect(ev).To(HaveKey("smoothed_rtt")) + Expect(time.Duration(ev["smoothed_rtt"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.SmoothedRTT(), time.Millisecond)) + Expect(ev).To(HaveKey("rtt_variance")) + Expect(time.Duration(ev["rtt_variance"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.MeanDeviation(), time.Millisecond)) + Expect(ev).To(HaveKeyWithValue("congestion_window", float64(4321))) + Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(1234))) + Expect(ev).To(HaveKeyWithValue("packets_in_flight", float64(42))) + }) - It("records congestion state updates", func() { - tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:congestion_state_updated")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("new", "congestion_avoidance")) - }) + It("only logs the diff between two metrics updates", func() { + now := time.Now() + rttStats := utils.NewRTTStats() + rttStats.UpdateRTT(15*time.Millisecond, 0, now) + rttStats.UpdateRTT(20*time.Millisecond, 0, now) + rttStats.UpdateRTT(25*time.Millisecond, 0, now) + Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) + + rttStats2 := utils.NewRTTStats() + rttStats2.UpdateRTT(15*time.Millisecond, 0, now) + rttStats2.UpdateRTT(15*time.Millisecond, 0, now) + rttStats2.UpdateRTT(15*time.Millisecond, 0, now) + Expect(rttStats2.MinRTT()).To(Equal(15 * time.Millisecond)) + + Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) + tracer.UpdatedMetrics( + rttStats, + 4321, + 1234, + 42, + ) + tracer.UpdatedMetrics( + rttStats2, + 4321, + 12345, // changed + 42, + ) + entries := exportAndParse() + 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")) + Expect(entries[0].Event).To(HaveLen(7)) + Expect(entries[1].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entries[1].Name).To(Equal("recovery:metrics_updated")) + ev := entries[1].Event + Expect(ev).ToNot(HaveKey("min_rtt")) + Expect(ev).ToNot(HaveKey("congestion_window")) + Expect(ev).ToNot(HaveKey("packets_in_flight")) + Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(12345))) + Expect(ev).To(HaveKeyWithValue("smoothed_rtt", float64(15))) + }) - It("records PTO changes", func() { - tracer.UpdatedPTOCount(42) - entry := exportAndParseSingle() - 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))) - }) + It("records lost packets", func() { + tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:packet_lost")) + ev := entry.Event + Expect(ev).To(HaveKey("header")) + hdr := ev["header"].(map[string]interface{}) + Expect(hdr).To(HaveLen(2)) + Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) + Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) + Expect(ev).To(HaveKeyWithValue("trigger", "reordering_threshold")) + }) - It("records TLS key updates", func() { - tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("security:key_updated")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("key_type", "client_handshake_secret")) - Expect(ev).To(HaveKeyWithValue("trigger", "tls")) - Expect(ev).ToNot(HaveKey("generation")) - Expect(ev).ToNot(HaveKey("old")) - Expect(ev).ToNot(HaveKey("new")) - }) + It("records congestion state updates", func() { + tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:congestion_state_updated")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("new", "congestion_avoidance")) + }) + + It("records PTO changes", func() { + tracer.UpdatedPTOCount(42) + entry := exportAndParseSingle() + 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))) + }) - It("records TLS key updates, for 1-RTT keys", func() { - tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer) - entry := exportAndParseSingle() + It("records TLS key updates", func() { + tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("security:key_updated")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("key_type", "client_handshake_secret")) + Expect(ev).To(HaveKeyWithValue("trigger", "tls")) + Expect(ev).ToNot(HaveKey("generation")) + Expect(ev).ToNot(HaveKey("old")) + Expect(ev).ToNot(HaveKey("new")) + }) + + It("records TLS key updates, for 1-RTT keys", func() { + tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("security:key_updated")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("key_type", "server_1rtt_secret")) + Expect(ev).To(HaveKeyWithValue("trigger", "tls")) + Expect(ev).To(HaveKeyWithValue("generation", float64(0))) + Expect(ev).ToNot(HaveKey("old")) + Expect(ev).ToNot(HaveKey("new")) + }) + + It("records QUIC key updates", func() { + tracer.UpdatedKey(1337, true) + entries := exportAndParse() + Expect(entries).To(HaveLen(2)) + var keyTypes []string + for _, entry := range entries { Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) Expect(entry.Name).To(Equal("security:key_updated")) ev := entry.Event - Expect(ev).To(HaveKeyWithValue("key_type", "server_1rtt_secret")) - Expect(ev).To(HaveKeyWithValue("trigger", "tls")) - Expect(ev).To(HaveKeyWithValue("generation", float64(0))) - Expect(ev).ToNot(HaveKey("old")) - Expect(ev).ToNot(HaveKey("new")) - }) - - It("records QUIC key updates", func() { - tracer.UpdatedKey(1337, true) - entries := exportAndParse() - Expect(entries).To(HaveLen(2)) - var keyTypes []string - for _, entry := range entries { - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("security:key_updated")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("generation", float64(1337))) - Expect(ev).To(HaveKeyWithValue("trigger", "remote_update")) - Expect(ev).To(HaveKey("key_type")) - keyTypes = append(keyTypes, ev["key_type"].(string)) - } - Expect(keyTypes).To(ContainElement("server_1rtt_secret")) - Expect(keyTypes).To(ContainElement("client_1rtt_secret")) - }) - - It("records dropped encryption levels", func() { - tracer.DroppedEncryptionLevel(protocol.EncryptionInitial) - entries := exportAndParse() - Expect(entries).To(HaveLen(2)) - var keyTypes []string - for _, entry := range entries { - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("security:key_discarded")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("trigger", "tls")) - Expect(ev).To(HaveKey("key_type")) - keyTypes = append(keyTypes, ev["key_type"].(string)) - } - Expect(keyTypes).To(ContainElement("server_initial_secret")) - Expect(keyTypes).To(ContainElement("client_initial_secret")) - }) + Expect(ev).To(HaveKeyWithValue("generation", float64(1337))) + Expect(ev).To(HaveKeyWithValue("trigger", "remote_update")) + Expect(ev).To(HaveKey("key_type")) + keyTypes = append(keyTypes, ev["key_type"].(string)) + } + Expect(keyTypes).To(ContainElement("server_1rtt_secret")) + Expect(keyTypes).To(ContainElement("client_1rtt_secret")) + }) - It("records dropped 0-RTT keys", func() { - tracer.DroppedEncryptionLevel(protocol.Encryption0RTT) - entries := exportAndParse() - Expect(entries).To(HaveLen(1)) - entry := entries[0] + It("records dropped encryption levels", func() { + tracer.DroppedEncryptionLevel(protocol.EncryptionInitial) + entries := exportAndParse() + Expect(entries).To(HaveLen(2)) + var keyTypes []string + for _, entry := range entries { Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) Expect(entry.Name).To(Equal("security:key_discarded")) ev := entry.Event Expect(ev).To(HaveKeyWithValue("trigger", "tls")) - Expect(ev).To(HaveKeyWithValue("key_type", "server_0rtt_secret")) - }) + Expect(ev).To(HaveKey("key_type")) + keyTypes = append(keyTypes, ev["key_type"].(string)) + } + Expect(keyTypes).To(ContainElement("server_initial_secret")) + Expect(keyTypes).To(ContainElement("client_initial_secret")) + }) - It("records dropped keys", func() { - tracer.DroppedKey(42) - entries := exportAndParse() - Expect(entries).To(HaveLen(2)) - var keyTypes []string - for _, entry := range entries { - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("security:key_discarded")) - ev := entry.Event - Expect(ev).To(HaveKeyWithValue("generation", float64(42))) - Expect(ev).ToNot(HaveKey("trigger")) - Expect(ev).To(HaveKey("key_type")) - keyTypes = append(keyTypes, ev["key_type"].(string)) - } - Expect(keyTypes).To(ContainElement("server_1rtt_secret")) - Expect(keyTypes).To(ContainElement("client_1rtt_secret")) - }) + It("records dropped 0-RTT keys", func() { + tracer.DroppedEncryptionLevel(protocol.Encryption0RTT) + entries := exportAndParse() + Expect(entries).To(HaveLen(1)) + entry := entries[0] + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("security:key_discarded")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("trigger", "tls")) + Expect(ev).To(HaveKeyWithValue("key_type", "server_0rtt_secret")) + }) - It("records when the timer is set", func() { - timeout := time.Now().Add(137 * time.Millisecond) - tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout) - entry := exportAndParseSingle() + It("records dropped keys", func() { + tracer.DroppedKey(42) + entries := exportAndParse() + Expect(entries).To(HaveLen(2)) + var keyTypes []string + for _, entry := range entries { Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) + Expect(entry.Name).To(Equal("security:key_discarded")) ev := entry.Event - Expect(ev).To(HaveLen(4)) - Expect(ev).To(HaveKeyWithValue("event_type", "set")) - Expect(ev).To(HaveKeyWithValue("timer_type", "pto")) - Expect(ev).To(HaveKeyWithValue("packet_number_space", "handshake")) - Expect(ev).To(HaveKey("delta")) - delta := time.Duration(ev["delta"].(float64)*1e6) * time.Nanosecond - Expect(entry.Time.Add(delta)).To(BeTemporally("~", timeout, scaleDuration(10*time.Microsecond))) - }) + Expect(ev).To(HaveKeyWithValue("generation", float64(42))) + Expect(ev).ToNot(HaveKey("trigger")) + Expect(ev).To(HaveKey("key_type")) + keyTypes = append(keyTypes, ev["key_type"].(string)) + } + Expect(keyTypes).To(ContainElement("server_1rtt_secret")) + Expect(keyTypes).To(ContainElement("client_1rtt_secret")) + }) - It("records when the loss timer expires", func() { - tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) - ev := entry.Event - Expect(ev).To(HaveLen(3)) - Expect(ev).To(HaveKeyWithValue("event_type", "expired")) - Expect(ev).To(HaveKeyWithValue("timer_type", "ack")) - Expect(ev).To(HaveKeyWithValue("packet_number_space", "application_data")) - }) + It("records when the timer is set", func() { + timeout := time.Now().Add(137 * time.Millisecond) + tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(4)) + Expect(ev).To(HaveKeyWithValue("event_type", "set")) + Expect(ev).To(HaveKeyWithValue("timer_type", "pto")) + Expect(ev).To(HaveKeyWithValue("packet_number_space", "handshake")) + Expect(ev).To(HaveKey("delta")) + delta := time.Duration(ev["delta"].(float64)*1e6) * time.Nanosecond + Expect(entry.Time.Add(delta)).To(BeTemporally("~", timeout, scaleDuration(10*time.Microsecond))) + }) - It("records when the timer is canceled", func() { - tracer.LossTimerCanceled() - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) - ev := entry.Event - Expect(ev).To(HaveLen(1)) - Expect(ev).To(HaveKeyWithValue("event_type", "cancelled")) - }) + It("records when the loss timer expires", func() { + tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(3)) + Expect(ev).To(HaveKeyWithValue("event_type", "expired")) + Expect(ev).To(HaveKeyWithValue("timer_type", "ack")) + Expect(ev).To(HaveKeyWithValue("packet_number_space", "application_data")) + }) - It("records an ECN state transition, without a trigger", func() { - tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:ecn_state_updated")) - ev := entry.Event - Expect(ev).To(HaveLen(1)) - Expect(ev).To(HaveKeyWithValue("new", "unknown")) - }) + It("records when the timer is canceled", func() { + tracer.LossTimerCanceled() + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(1)) + Expect(ev).To(HaveKeyWithValue("event_type", "cancelled")) + }) - It("records an ECN state transition, with a trigger", func() { - tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts) - entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) - Expect(entry.Name).To(Equal("recovery:ecn_state_updated")) - ev := entry.Event - Expect(ev).To(HaveLen(2)) - Expect(ev).To(HaveKeyWithValue("new", "failed")) - Expect(ev).To(HaveKeyWithValue("trigger", "ACK doesn't contain ECN marks")) - }) + It("records an ECN state transition, without a trigger", func() { + tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:ecn_state_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(1)) + Expect(ev).To(HaveKeyWithValue("new", "unknown")) + }) - It("records a generic event", func() { - tracer.Debug("foo", "bar") - entry := exportAndParseSingle() - 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")) - }) + It("records an ECN state transition, with a trigger", func() { + tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) + Expect(entry.Name).To(Equal("recovery:ecn_state_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(2)) + Expect(ev).To(HaveKeyWithValue("new", "failed")) + Expect(ev).To(HaveKeyWithValue("trigger", "ACK doesn't contain ECN marks")) + }) + + It("records a generic event", func() { + tracer.Debug("foo", "bar") + entry := exportAndParseSingle() + 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")) }) }) }) diff --git a/qlog/writer.go b/qlog/writer.go new file mode 100644 index 00000000000..10cb649943f --- /dev/null +++ b/qlog/writer.go @@ -0,0 +1,84 @@ +package qlog + +import ( + "bytes" + "fmt" + "io" + "log" + "time" + + "github.com/francoispqt/gojay" +) + +const eventChanSize = 50 + +type writer struct { + w io.WriteCloser + + referenceTime time.Time + tr *trace + + events chan event + encodeErr error + runStopped chan struct{} +} + +func newWriter(w io.WriteCloser, tr *trace) *writer { + return &writer{ + w: w, + tr: tr, + referenceTime: tr.CommonFields.ReferenceTime, + runStopped: make(chan struct{}), + events: make(chan event, eventChanSize), + } +} + +func (w *writer) RecordEvent(eventTime time.Time, details eventDetails) { + w.events <- event{ + RelativeTime: eventTime.Sub(w.referenceTime), + eventDetails: details, + } +} + +func (w *writer) Run() { + defer close(w.runStopped) + buf := &bytes.Buffer{} + enc := gojay.NewEncoder(buf) + if err := enc.Encode(&topLevel{trace: *w.tr}); err != nil { + panic(fmt.Sprintf("qlog encoding into a bytes.Buffer failed: %s", err)) + } + if err := buf.WriteByte('\n'); err != nil { + panic(fmt.Sprintf("qlog encoding into a bytes.Buffer failed: %s", err)) + } + if _, err := w.w.Write(buf.Bytes()); err != nil { + w.encodeErr = err + } + enc = gojay.NewEncoder(w.w) + for ev := range w.events { + if w.encodeErr != nil { // if encoding failed, just continue draining the event channel + continue + } + if err := enc.Encode(ev); err != nil { + w.encodeErr = err + continue + } + if _, err := w.w.Write([]byte{'\n'}); err != nil { + w.encodeErr = err + } + } +} + +func (w *writer) Close() { + if err := w.close(); err != nil { + log.Printf("exporting qlog failed: %s\n", err) + } +} + +func (w *writer) close() error { + close(w.events) + <-w.runStopped + if w.encodeErr != nil { + return w.encodeErr + } + return w.w.Close() +} diff --git a/qlog/writer_test.go b/qlog/writer_test.go new file mode 100644 index 00000000000..8b4437ed93d --- /dev/null +++ b/qlog/writer_test.go @@ -0,0 +1,49 @@ +package qlog + +import ( + "bytes" + "errors" + "io" + "log" + "os" + + "github.com/quic-go/quic-go/internal/protocol" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +type limitedWriter struct { + io.WriteCloser + N int + written int +} + +func (w *limitedWriter) Write(p []byte) (int, error) { + if w.written+len(p) > w.N { + return 0, errors.New("writer full") + } + n, err := w.WriteCloser.Write(p) + w.written += n + return n, err +} + +var _ = Describe("Writing", func() { + It("stops writing when encountering an error", func() { + buf := &bytes.Buffer{} + t := NewConnectionTracer( + &limitedWriter{WriteCloser: nopWriteCloser(buf), N: 250}, + protocol.PerspectiveServer, + protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), + ) + for i := uint32(0); i < 1000; i++ { + t.UpdatedPTOCount(i) + } + + b := &bytes.Buffer{} + log.SetOutput(b) + defer log.SetOutput(os.Stdout) + t.Close() + Expect(b.String()).To(ContainSubstring("writer full")) + }) +}) From fc634a60d04824873481bc51dc3ddf6982d87d96 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 06:11:02 +0700 Subject: [PATCH 3/3] logging: add a Debug function to the Tracer --- internal/mocks/logging/internal/tracer.go | 36 +++++++++++++++++++++++ internal/mocks/logging/mockgen.go | 1 + internal/mocks/logging/tracer.go | 3 ++ logging/multiplex_test.go | 6 ++++ logging/tracer.go | 8 +++++ 5 files changed, 54 insertions(+) diff --git a/internal/mocks/logging/internal/tracer.go b/internal/mocks/logging/internal/tracer.go index e11764c2110..88c3b64570c 100644 --- a/internal/mocks/logging/internal/tracer.go +++ b/internal/mocks/logging/internal/tracer.go @@ -41,6 +41,42 @@ func (m *MockTracer) EXPECT() *MockTracerMockRecorder { return m.recorder } +// Debug mocks base method. +func (m *MockTracer) Debug(arg0, arg1 string) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "Debug", arg0, arg1) +} + +// Debug indicates an expected call of Debug. +func (mr *MockTracerMockRecorder) Debug(arg0, arg1 any) *TracerDebugCall { + mr.mock.ctrl.T.Helper() + call := mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Debug", reflect.TypeOf((*MockTracer)(nil).Debug), arg0, arg1) + return &TracerDebugCall{Call: call} +} + +// TracerDebugCall wrap *gomock.Call +type TracerDebugCall struct { + *gomock.Call +} + +// Return rewrite *gomock.Call.Return +func (c *TracerDebugCall) Return() *TracerDebugCall { + c.Call = c.Call.Return() + return c +} + +// Do rewrite *gomock.Call.Do +func (c *TracerDebugCall) Do(f func(string, string)) *TracerDebugCall { + c.Call = c.Call.Do(f) + return c +} + +// DoAndReturn rewrite *gomock.Call.DoAndReturn +func (c *TracerDebugCall) DoAndReturn(f func(string, string)) *TracerDebugCall { + c.Call = c.Call.DoAndReturn(f) + return c +} + // DroppedPacket mocks base method. func (m *MockTracer) DroppedPacket(arg0 net.Addr, arg1 logging.PacketType, arg2 protocol.ByteCount, arg3 logging.PacketDropReason) { m.ctrl.T.Helper() diff --git a/internal/mocks/logging/mockgen.go b/internal/mocks/logging/mockgen.go index a86be9b1a1d..fb58e1174a9 100644 --- a/internal/mocks/logging/mockgen.go +++ b/internal/mocks/logging/mockgen.go @@ -14,6 +14,7 @@ type Tracer interface { SentPacket(net.Addr, *logging.Header, logging.ByteCount, []logging.Frame) SentVersionNegotiationPacket(_ net.Addr, dest, src logging.ArbitraryLenConnectionID, _ []logging.VersionNumber) DroppedPacket(net.Addr, logging.PacketType, logging.ByteCount, logging.PacketDropReason) + Debug(name, msg string) } //go:generate sh -c "go run go.uber.org/mock/mockgen -typed -build_flags=\"-tags=gomock\" -package internal -destination internal/connection_tracer.go github.com/quic-go/quic-go/internal/mocks/logging ConnectionTracer" diff --git a/internal/mocks/logging/tracer.go b/internal/mocks/logging/tracer.go index 115f578a2c7..66e210a53f9 100644 --- a/internal/mocks/logging/tracer.go +++ b/internal/mocks/logging/tracer.go @@ -25,5 +25,8 @@ func NewMockTracer(ctrl *gomock.Controller) (*logging.Tracer, *MockTracer) { DroppedPacket: func(remote net.Addr, typ logging.PacketType, size logging.ByteCount, reason logging.PacketDropReason) { t.DroppedPacket(remote, typ, size, reason) }, + Debug: func(name, msg string) { + t.Debug(name, msg) + }, }, t } diff --git a/logging/multiplex_test.go b/logging/multiplex_test.go index 946040963a2..96cd1185361 100644 --- a/logging/multiplex_test.go +++ b/logging/multiplex_test.go @@ -64,6 +64,12 @@ var _ = Describe("Tracing", func() { tr2.EXPECT().DroppedPacket(remote, PacketTypeRetry, ByteCount(1024), PacketDropDuplicate) tracer.DroppedPacket(remote, PacketTypeRetry, 1024, PacketDropDuplicate) }) + + It("traces the Debug event", func() { + tr1.EXPECT().Debug("foo", "bar") + tr2.EXPECT().Debug("foo", "bar") + tracer.Debug("foo", "bar") + }) }) }) diff --git a/logging/tracer.go b/logging/tracer.go index 5918f30f842..735ec3de05c 100644 --- a/logging/tracer.go +++ b/logging/tracer.go @@ -7,6 +7,7 @@ type Tracer struct { SentPacket func(net.Addr, *Header, ByteCount, []Frame) SentVersionNegotiationPacket func(_ net.Addr, dest, src ArbitraryLenConnectionID, _ []VersionNumber) DroppedPacket func(net.Addr, PacketType, ByteCount, PacketDropReason) + Debug func(name, msg string) } // NewMultiplexedTracer creates a new tracer that multiplexes events to multiple tracers. @@ -39,5 +40,12 @@ func NewMultiplexedTracer(tracers ...*Tracer) *Tracer { } } }, + Debug: func(name, msg string) { + for _, t := range tracers { + if t.Debug != nil { + t.Debug(name, msg) + } + } + }, } }