From d83c51b50d3a2f6706d34bd34bec2cd8f75c1d63 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 07:44:07 +0700 Subject: [PATCH 1/2] qlog: disentangle the ConnectionTracer from the qlog writer 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/{qlog.go => connection_tracer.go} | 125 +++--------------- ...qlog_test.go => connection_tracer_test.go} | 0 qlog/trace.go | 29 ++++ qlog/writer.go | 84 ++++++++++++ 4 files changed, 131 insertions(+), 107 deletions(-) rename qlog/{qlog.go => connection_tracer.go} (84%) rename qlog/{qlog_test.go => connection_tracer_test.go} (100%) create mode 100644 qlog/writer.go diff --git a/qlog/qlog.go b/qlog/connection_tracer.go similarity index 84% rename from qlog/qlog.go rename to qlog/connection_tracer.go index 39c54af796a..ae328a385d5 100644 --- a/qlog/qlog.go +++ b/qlog/connection_tracer.go @@ -1,12 +1,8 @@ package qlog import ( - "bytes" - "fmt" "io" - "log" "net" - "runtime/debug" "time" "github.com/quic-go/quic-go/internal/protocol" @@ -17,60 +13,28 @@ 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 { - 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) @@ -154,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/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 } 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() +} From e93189dc2bccc43c254229613da20892930144a1 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Fri, 2 Feb 2024 06:11:02 +0700 Subject: [PATCH 2/2] 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) + } + } + }, } }