From 2abbd41806e6fa36f87469d7ae62f42b8b7b4df4 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 17:08:44 +0700 Subject: [PATCH 1/5] qlog: introduce a basic tracer for non-connection events --- qlog/connection_tracer.go | 6 +- qlog/connection_tracer_test.go | 204 ++++++++++++++++++++------------- qlog/trace.go | 20 ++-- qlog/tracer.go | 29 +++++ qlog/tracer_test.go | 59 ++++++++++ 5 files changed, 221 insertions(+), 97 deletions(-) create mode 100644 qlog/tracer.go create mode 100644 qlog/tracer_test.go 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/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/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..4d567875 --- /dev/null +++ b/qlog/tracer.go @@ -0,0 +1,29 @@ +package qlog + +import ( + "io" + "time" + + "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: nil, + SentVersionNegotiationPacket: nil, + DroppedPacket: nil, + Debug: func(name, msg string) { + wr.RecordEvent(time.Now(), &eventGeneric{ + name: name, + msg: msg, + }) + }, + Close: func() { wr.Close() }, + } +} diff --git a/qlog/tracer_test.go b/qlog/tracer_test.go new file mode 100644 index 00000000..46f41522 --- /dev/null +++ b/qlog/tracer_test.go @@ -0,0 +1,59 @@ +package qlog + +import ( + "bytes" + "encoding/json" + "time" + + "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 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")) + }) + }) +}) From 3a7a53fdb919aeedef7441cb7a1618e1b88596c4 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 17:17:56 +0700 Subject: [PATCH 2/5] qlog: log packet drops outside of a QUIC connection --- qlog/tracer.go | 11 ++++++++++- qlog/tracer_test.go | 18 ++++++++++++++++++ 2 files changed, 28 insertions(+), 1 deletion(-) diff --git a/qlog/tracer.go b/qlog/tracer.go index 4d567875..85398f9f 100644 --- a/qlog/tracer.go +++ b/qlog/tracer.go @@ -2,8 +2,10 @@ package qlog import ( "io" + "net" "time" + "github.com/quic-go/quic-go/internal/protocol" "github.com/quic-go/quic-go/logging" ) @@ -17,7 +19,14 @@ func NewTracer(w io.WriteCloser) *logging.Tracer { return &logging.Tracer{ SentPacket: nil, SentVersionNegotiationPacket: nil, - DroppedPacket: nil, + 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, diff --git a/qlog/tracer_test.go b/qlog/tracer_test.go index 46f41522..990e4165 100644 --- a/qlog/tracer_test.go +++ b/qlog/tracer_test.go @@ -3,6 +3,7 @@ package qlog import ( "bytes" "encoding/json" + "net" "time" "github.com/quic-go/quic-go/logging" @@ -45,6 +46,23 @@ var _ = Describe("Tracing", func() { }) Context("Events", func() { + 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() From aff90a6ffa3b09c73386f8980d67edc3f32679a3 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 17:27:44 +0700 Subject: [PATCH 3/5] qlog: log sent Version Negotiation packets --- qlog/event.go | 14 ++++++++++++++ qlog/tracer.go | 16 ++++++++++++++-- qlog/tracer_test.go | 25 +++++++++++++++++++++++++ 3 files changed, 53 insertions(+), 2 deletions(-) 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/tracer.go b/qlog/tracer.go index 85398f9f..708e80ab 100644 --- a/qlog/tracer.go +++ b/qlog/tracer.go @@ -17,8 +17,20 @@ func NewTracer(w io.WriteCloser) *logging.Tracer { wr := *newWriter(w, tr) go wr.Run() return &logging.Tracer{ - SentPacket: nil, - SentVersionNegotiationPacket: nil, + SentPacket: nil, + 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, diff --git a/qlog/tracer_test.go b/qlog/tracer_test.go index 990e4165..75d97059 100644 --- a/qlog/tracer_test.go +++ b/qlog/tracer_test.go @@ -6,6 +6,7 @@ import ( "net" "time" + "github.com/quic-go/quic-go/internal/protocol" "github.com/quic-go/quic-go/logging" . "github.com/onsi/ginkgo/v2" @@ -46,6 +47,30 @@ var _ = Describe("Tracing", func() { }) Context("Events", func() { + 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) From 55c05aceed4bcc47219058f8d777076bb844815c Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 17:35:58 +0700 Subject: [PATCH 4/5] qlog: log sent packets outside of a QUIC connection --- qlog/tracer.go | 12 +++++++++++- qlog/tracer_test.go | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 46 insertions(+), 1 deletion(-) diff --git a/qlog/tracer.go b/qlog/tracer.go index 708e80ab..562f7a26 100644 --- a/qlog/tracer.go +++ b/qlog/tracer.go @@ -17,7 +17,17 @@ func NewTracer(w io.WriteCloser) *logging.Tracer { wr := *newWriter(w, tr) go wr.Run() return &logging.Tracer{ - SentPacket: nil, + 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 { diff --git a/qlog/tracer_test.go b/qlog/tracer_test.go index 75d97059..8aa8faa5 100644 --- a/qlog/tracer_test.go +++ b/qlog/tracer_test.go @@ -47,6 +47,41 @@ var _ = Describe("Tracing", func() { }) 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, From 30e01b9524a4a9fbbb285d2280a31ac4c427d0bd Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Sat, 3 Feb 2024 12:35:19 +0700 Subject: [PATCH 5/5] use the transport tracer in integration tests --- integrationtests/self/conn_id_test.go | 2 + integrationtests/self/handshake_rtt_test.go | 1 + integrationtests/self/handshake_test.go | 17 ++++-- integrationtests/self/mitm_test.go | 2 + integrationtests/self/multiplex_test.go | 7 +++ integrationtests/self/self_suite_test.go | 58 ++++++++++++------- integrationtests/self/zero_rtt_test.go | 2 + integrationtests/tools/qlog.go | 21 +++++-- .../versionnegotiation_suite_test.go | 2 +- 9 files changed, 78 insertions(+), 34 deletions(-) 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 {