From c8d434305ce4560e32cfd278d60311f0dfaed834 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Thu, 9 Jul 2020 14:47:02 +0700 Subject: [PATCH] add a multiplexer for the logging.Tracer --- logging/interface.go | 4 + logging/mock_tracer_test.go | 62 ++++++++ logging/mockgen.go | 1 + logging/multiplex.go | 41 ++++- logging/multiplex_test.go | 300 +++++++++++++++++++++--------------- 5 files changed, 283 insertions(+), 125 deletions(-) create mode 100644 logging/mock_tracer_test.go diff --git a/logging/interface.go b/logging/interface.go index e9dc93d0..621c7577 100644 --- a/logging/interface.go +++ b/logging/interface.go @@ -79,7 +79,11 @@ const ( // A Tracer traces events. type Tracer interface { + // TracerForServer requests a new tracer for a connection that was accepted by the server. + // If nil is returned, tracing will be disabled for this connection. TracerForServer(odcid ConnectionID) ConnectionTracer + // TracerForServer requests a new tracer for a connection that was dialed by the client. + // If nil is returned, tracing will be disabled for this connection. TracerForClient(odcid ConnectionID) ConnectionTracer } diff --git a/logging/mock_tracer_test.go b/logging/mock_tracer_test.go new file mode 100644 index 00000000..f1918802 --- /dev/null +++ b/logging/mock_tracer_test.go @@ -0,0 +1,62 @@ +// Code generated by MockGen. DO NOT EDIT. +// Source: github.com/lucas-clemente/quic-go/logging (interfaces: Tracer) + +// Package logging is a generated GoMock package. +package logging + +import ( + gomock "github.com/golang/mock/gomock" + protocol "github.com/lucas-clemente/quic-go/internal/protocol" + reflect "reflect" +) + +// MockTracer is a mock of Tracer interface +type MockTracer struct { + ctrl *gomock.Controller + recorder *MockTracerMockRecorder +} + +// MockTracerMockRecorder is the mock recorder for MockTracer +type MockTracerMockRecorder struct { + mock *MockTracer +} + +// NewMockTracer creates a new mock instance +func NewMockTracer(ctrl *gomock.Controller) *MockTracer { + mock := &MockTracer{ctrl: ctrl} + mock.recorder = &MockTracerMockRecorder{mock} + return mock +} + +// EXPECT returns an object that allows the caller to indicate expected use +func (m *MockTracer) EXPECT() *MockTracerMockRecorder { + return m.recorder +} + +// TracerForClient mocks base method +func (m *MockTracer) TracerForClient(arg0 protocol.ConnectionID) ConnectionTracer { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "TracerForClient", arg0) + ret0, _ := ret[0].(ConnectionTracer) + return ret0 +} + +// TracerForClient indicates an expected call of TracerForClient +func (mr *MockTracerMockRecorder) TracerForClient(arg0 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "TracerForClient", reflect.TypeOf((*MockTracer)(nil).TracerForClient), arg0) +} + +// TracerForServer mocks base method +func (m *MockTracer) TracerForServer(arg0 protocol.ConnectionID) ConnectionTracer { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "TracerForServer", arg0) + ret0, _ := ret[0].(ConnectionTracer) + return ret0 +} + +// TracerForServer indicates an expected call of TracerForServer +func (mr *MockTracerMockRecorder) TracerForServer(arg0 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "TracerForServer", reflect.TypeOf((*MockTracer)(nil).TracerForServer), arg0) +} diff --git a/logging/mockgen.go b/logging/mockgen.go index 9e43528a..9237e40e 100644 --- a/logging/mockgen.go +++ b/logging/mockgen.go @@ -1,3 +1,4 @@ package logging //go:generate sh -c "mockgen -package logging -destination mock_connection_tracer_test.go github.com/lucas-clemente/quic-go/logging ConnectionTracer" +//go:generate sh -c "mockgen -package logging -destination mock_tracer_test.go github.com/lucas-clemente/quic-go/logging Tracer" diff --git a/logging/multiplex.go b/logging/multiplex.go index a7f06b22..6df06cbe 100644 --- a/logging/multiplex.go +++ b/logging/multiplex.go @@ -5,15 +5,52 @@ import ( "time" ) +type tracerMultiplexer struct { + tracers []Tracer +} + +var _ Tracer = &tracerMultiplexer{} + +// NewMultiplexedTracer creates a new tracer that multiplexes all events to multiple tracers. +func NewMultiplexedTracer(tracers ...Tracer) Tracer { + if len(tracers) == 0 { + return nil + } + if len(tracers) == 1 { + return tracers[1] + } + return &tracerMultiplexer{tracers} +} + +func (m *tracerMultiplexer) TracerForServer(odcid ConnectionID) ConnectionTracer { + var connTracers []ConnectionTracer + for _, t := range m.tracers { + if ct := t.TracerForServer(odcid); ct != nil { + connTracers = append(connTracers, ct) + } + } + return newConnectionMultiplexer(connTracers...) +} + +func (m *tracerMultiplexer) TracerForClient(odcid ConnectionID) ConnectionTracer { + var connTracers []ConnectionTracer + for _, t := range m.tracers { + if ct := t.TracerForClient(odcid); ct != nil { + connTracers = append(connTracers, ct) + } + } + return newConnectionMultiplexer(connTracers...) +} + type connTracerMultiplexer struct { tracers []ConnectionTracer } var _ ConnectionTracer = &connTracerMultiplexer{} -func NewConnectionMultiplexer(tracers ...ConnectionTracer) ConnectionTracer { +func newConnectionMultiplexer(tracers ...ConnectionTracer) ConnectionTracer { if len(tracers) == 0 { - panic("no tracers") + return nil } if len(tracers) == 1 { return tracers[0] diff --git a/logging/multiplex_test.go b/logging/multiplex_test.go index ccd968c8..ffcb9dd2 100644 --- a/logging/multiplex_test.go +++ b/logging/multiplex_test.go @@ -7,153 +7,207 @@ import ( "github.com/lucas-clemente/quic-go/internal/wire" . "github.com/onsi/ginkgo" + . "github.com/onsi/gomega" ) var _ = Describe("Tracing", func() { - var ( - tracer ConnectionTracer - tr1 *MockConnectionTracer - tr2 *MockConnectionTracer - ) + Context("Tracer", func() { + var ( + tracer Tracer + tr1, tr2 *MockTracer + ) - BeforeEach(func() { - tr1 = NewMockConnectionTracer(mockCtrl) - tr2 = NewMockConnectionTracer(mockCtrl) - tracer = NewConnectionMultiplexer(tr1, tr2) + BeforeEach(func() { + tr1 = NewMockTracer(mockCtrl) + tr2 = NewMockTracer(mockCtrl) + tracer = NewMultiplexedTracer(tr1, tr2) + }) + + It("multiplexes the TracerForServer call", func() { + tr1.EXPECT().TracerForServer(ConnectionID{1, 2, 3}) + tr2.EXPECT().TracerForServer(ConnectionID{1, 2, 3}) + tracer.TracerForServer(ConnectionID{1, 2, 3}) + }) + + It("multiplexes the TracerForClient call", func() { + tr1.EXPECT().TracerForClient(ConnectionID{1, 2, 3}) + tr2.EXPECT().TracerForClient(ConnectionID{1, 2, 3}) + tracer.TracerForClient(ConnectionID{1, 2, 3}) + }) + + It("uses multiple connection tracers", func() { + ctr1 := NewMockConnectionTracer(mockCtrl) + ctr2 := NewMockConnectionTracer(mockCtrl) + tr1.EXPECT().TracerForClient(ConnectionID{1, 2, 3}).Return(ctr1) + tr2.EXPECT().TracerForClient(ConnectionID{1, 2, 3}).Return(ctr2) + tr := tracer.TracerForClient(ConnectionID{1, 2, 3}) + ctr1.EXPECT().LossTimerCanceled() + ctr2.EXPECT().LossTimerCanceled() + tr.LossTimerCanceled() + }) + + It("handles tracers that return a nil ConnectionTracer", func() { + ctr1 := NewMockConnectionTracer(mockCtrl) + tr1.EXPECT().TracerForClient(ConnectionID{1, 2, 3}).Return(ctr1) + tr2.EXPECT().TracerForClient(ConnectionID{1, 2, 3}) + tr := tracer.TracerForClient(ConnectionID{1, 2, 3}) + ctr1.EXPECT().LossTimerCanceled() + tr.LossTimerCanceled() + }) + + It("returns nil when all tracers return a nil ConnectionTracer", func() { + tr1.EXPECT().TracerForClient(ConnectionID{1, 2, 3}) + tr2.EXPECT().TracerForClient(ConnectionID{1, 2, 3}) + Expect(tracer.TracerForClient(ConnectionID{1, 2, 3})).To(BeNil()) + }) }) - It("trace the ConnectionStarted event", func() { - local := &net.UDPAddr{IP: net.IPv4(1, 2, 3, 4)} - remote := &net.UDPAddr{IP: net.IPv4(4, 3, 2, 1)} - tr1.EXPECT().StartedConnection(local, remote, VersionNumber(1234), ConnectionID{1, 2, 3, 4}, ConnectionID{4, 3, 2, 1}) - tr2.EXPECT().StartedConnection(local, remote, VersionNumber(1234), ConnectionID{1, 2, 3, 4}, ConnectionID{4, 3, 2, 1}) - tracer.StartedConnection(local, remote, VersionNumber(1234), ConnectionID{1, 2, 3, 4}, ConnectionID{4, 3, 2, 1}) - }) + Context("Connection Tracer", func() { + var ( + tracer ConnectionTracer + tr1 *MockConnectionTracer + tr2 *MockConnectionTracer + ) - It("traces the ClosedConnection event", func() { - reason := NewTimeoutCloseReason(TimeoutReasonIdle) - tr1.EXPECT().ClosedConnection(reason) - tr2.EXPECT().ClosedConnection(reason) - tracer.ClosedConnection(reason) - }) + BeforeEach(func() { + tr1 = NewMockConnectionTracer(mockCtrl) + tr2 = NewMockConnectionTracer(mockCtrl) + tracer = newConnectionMultiplexer(tr1, tr2) + }) - It("traces the SentTransportParameters event", func() { - tp := &wire.TransportParameters{InitialMaxData: 1337} - tr1.EXPECT().SentTransportParameters(tp) - tr2.EXPECT().SentTransportParameters(tp) - tracer.SentTransportParameters(tp) - }) + It("trace the ConnectionStarted event", func() { + local := &net.UDPAddr{IP: net.IPv4(1, 2, 3, 4)} + remote := &net.UDPAddr{IP: net.IPv4(4, 3, 2, 1)} + tr1.EXPECT().StartedConnection(local, remote, VersionNumber(1234), ConnectionID{1, 2, 3, 4}, ConnectionID{4, 3, 2, 1}) + tr2.EXPECT().StartedConnection(local, remote, VersionNumber(1234), ConnectionID{1, 2, 3, 4}, ConnectionID{4, 3, 2, 1}) + tracer.StartedConnection(local, remote, VersionNumber(1234), ConnectionID{1, 2, 3, 4}, ConnectionID{4, 3, 2, 1}) + }) - It("traces the ReceivedTransportParameters event", func() { - tp := &wire.TransportParameters{InitialMaxData: 1337} - tr1.EXPECT().ReceivedTransportParameters(tp) - tr2.EXPECT().ReceivedTransportParameters(tp) - tracer.ReceivedTransportParameters(tp) - }) + It("traces the ClosedConnection event", func() { + reason := NewTimeoutCloseReason(TimeoutReasonIdle) + tr1.EXPECT().ClosedConnection(reason) + tr2.EXPECT().ClosedConnection(reason) + tracer.ClosedConnection(reason) + }) - It("traces the SentPacket event", func() { - hdr := &ExtendedHeader{Header: Header{DestConnectionID: ConnectionID{1, 2, 3}}} - ack := &AckFrame{AckRanges: []AckRange{{Smallest: 1, Largest: 10}}} - ping := &PingFrame{} - tr1.EXPECT().SentPacket(hdr, ByteCount(1337), ack, []Frame{ping}) - tr2.EXPECT().SentPacket(hdr, ByteCount(1337), ack, []Frame{ping}) - tracer.SentPacket(hdr, 1337, ack, []Frame{ping}) - }) + It("traces the SentTransportParameters event", func() { + tp := &wire.TransportParameters{InitialMaxData: 1337} + tr1.EXPECT().SentTransportParameters(tp) + tr2.EXPECT().SentTransportParameters(tp) + tracer.SentTransportParameters(tp) + }) - It("traces the ReceivedVersionNegotiationPacket event", func() { - hdr := &Header{DestConnectionID: ConnectionID{1, 2, 3}} - tr1.EXPECT().ReceivedVersionNegotiationPacket(hdr, []VersionNumber{1337}) - tr2.EXPECT().ReceivedVersionNegotiationPacket(hdr, []VersionNumber{1337}) - tracer.ReceivedVersionNegotiationPacket(hdr, []VersionNumber{1337}) - }) + It("traces the ReceivedTransportParameters event", func() { + tp := &wire.TransportParameters{InitialMaxData: 1337} + tr1.EXPECT().ReceivedTransportParameters(tp) + tr2.EXPECT().ReceivedTransportParameters(tp) + tracer.ReceivedTransportParameters(tp) + }) - It("traces the ReceivedRetry event", func() { - hdr := &Header{DestConnectionID: ConnectionID{1, 2, 3}} - tr1.EXPECT().ReceivedRetry(hdr) - tr2.EXPECT().ReceivedRetry(hdr) - tracer.ReceivedRetry(hdr) - }) + It("traces the SentPacket event", func() { + hdr := &ExtendedHeader{Header: Header{DestConnectionID: ConnectionID{1, 2, 3}}} + ack := &AckFrame{AckRanges: []AckRange{{Smallest: 1, Largest: 10}}} + ping := &PingFrame{} + tr1.EXPECT().SentPacket(hdr, ByteCount(1337), ack, []Frame{ping}) + tr2.EXPECT().SentPacket(hdr, ByteCount(1337), ack, []Frame{ping}) + tracer.SentPacket(hdr, 1337, ack, []Frame{ping}) + }) - It("traces the ReceivedPacket event", func() { - hdr := &ExtendedHeader{Header: Header{DestConnectionID: ConnectionID{1, 2, 3}}} - ping := &PingFrame{} - tr1.EXPECT().ReceivedPacket(hdr, ByteCount(1337), []Frame{ping}) - tr2.EXPECT().ReceivedPacket(hdr, ByteCount(1337), []Frame{ping}) - tracer.ReceivedPacket(hdr, 1337, []Frame{ping}) - }) + It("traces the ReceivedVersionNegotiationPacket event", func() { + hdr := &Header{DestConnectionID: ConnectionID{1, 2, 3}} + tr1.EXPECT().ReceivedVersionNegotiationPacket(hdr, []VersionNumber{1337}) + tr2.EXPECT().ReceivedVersionNegotiationPacket(hdr, []VersionNumber{1337}) + tracer.ReceivedVersionNegotiationPacket(hdr, []VersionNumber{1337}) + }) - It("traces the BufferedPacket event", func() { - tr1.EXPECT().BufferedPacket(PacketTypeHandshake) - tr2.EXPECT().BufferedPacket(PacketTypeHandshake) - tracer.BufferedPacket(PacketTypeHandshake) - }) + It("traces the ReceivedRetry event", func() { + hdr := &Header{DestConnectionID: ConnectionID{1, 2, 3}} + tr1.EXPECT().ReceivedRetry(hdr) + tr2.EXPECT().ReceivedRetry(hdr) + tracer.ReceivedRetry(hdr) + }) - It("traces the DroppedPacket event", func() { - tr1.EXPECT().DroppedPacket(PacketTypeInitial, ByteCount(1337), PacketDropHeaderParseError) - tr2.EXPECT().DroppedPacket(PacketTypeInitial, ByteCount(1337), PacketDropHeaderParseError) - tracer.DroppedPacket(PacketTypeInitial, 1337, PacketDropHeaderParseError) - }) + It("traces the ReceivedPacket event", func() { + hdr := &ExtendedHeader{Header: Header{DestConnectionID: ConnectionID{1, 2, 3}}} + ping := &PingFrame{} + tr1.EXPECT().ReceivedPacket(hdr, ByteCount(1337), []Frame{ping}) + tr2.EXPECT().ReceivedPacket(hdr, ByteCount(1337), []Frame{ping}) + tracer.ReceivedPacket(hdr, 1337, []Frame{ping}) + }) - It("traces the UpdatedMetrics event", func() { - rttStats := &RTTStats{} - rttStats.UpdateRTT(time.Second, 0, time.Now()) - tr1.EXPECT().UpdatedMetrics(rttStats, ByteCount(1337), ByteCount(42), 13) - tr2.EXPECT().UpdatedMetrics(rttStats, ByteCount(1337), ByteCount(42), 13) - tracer.UpdatedMetrics(rttStats, 1337, 42, 13) - }) + It("traces the BufferedPacket event", func() { + tr1.EXPECT().BufferedPacket(PacketTypeHandshake) + tr2.EXPECT().BufferedPacket(PacketTypeHandshake) + tracer.BufferedPacket(PacketTypeHandshake) + }) - It("traces the LostPacket event", func() { - tr1.EXPECT().LostPacket(EncryptionHandshake, PacketNumber(42), PacketLossReorderingThreshold) - tr2.EXPECT().LostPacket(EncryptionHandshake, PacketNumber(42), PacketLossReorderingThreshold) - tracer.LostPacket(EncryptionHandshake, 42, PacketLossReorderingThreshold) - }) + It("traces the DroppedPacket event", func() { + tr1.EXPECT().DroppedPacket(PacketTypeInitial, ByteCount(1337), PacketDropHeaderParseError) + tr2.EXPECT().DroppedPacket(PacketTypeInitial, ByteCount(1337), PacketDropHeaderParseError) + tracer.DroppedPacket(PacketTypeInitial, 1337, PacketDropHeaderParseError) + }) - It("traces the UpdatedPTOCount event", func() { - tr1.EXPECT().UpdatedPTOCount(uint32(88)) - tr2.EXPECT().UpdatedPTOCount(uint32(88)) - tracer.UpdatedPTOCount(88) - }) + It("traces the UpdatedMetrics event", func() { + rttStats := &RTTStats{} + rttStats.UpdateRTT(time.Second, 0, time.Now()) + tr1.EXPECT().UpdatedMetrics(rttStats, ByteCount(1337), ByteCount(42), 13) + tr2.EXPECT().UpdatedMetrics(rttStats, ByteCount(1337), ByteCount(42), 13) + tracer.UpdatedMetrics(rttStats, 1337, 42, 13) + }) - It("traces the UpdatedKeyFromTLS event", func() { - tr1.EXPECT().UpdatedKeyFromTLS(EncryptionHandshake, PerspectiveClient) - tr2.EXPECT().UpdatedKeyFromTLS(EncryptionHandshake, PerspectiveClient) - tracer.UpdatedKeyFromTLS(EncryptionHandshake, PerspectiveClient) - }) + It("traces the LostPacket event", func() { + tr1.EXPECT().LostPacket(EncryptionHandshake, PacketNumber(42), PacketLossReorderingThreshold) + tr2.EXPECT().LostPacket(EncryptionHandshake, PacketNumber(42), PacketLossReorderingThreshold) + tracer.LostPacket(EncryptionHandshake, 42, PacketLossReorderingThreshold) + }) - It("traces the UpdatedKey event", func() { - tr1.EXPECT().UpdatedKey(KeyPhase(42), true) - tr2.EXPECT().UpdatedKey(KeyPhase(42), true) - tracer.UpdatedKey(KeyPhase(42), true) - }) + It("traces the UpdatedPTOCount event", func() { + tr1.EXPECT().UpdatedPTOCount(uint32(88)) + tr2.EXPECT().UpdatedPTOCount(uint32(88)) + tracer.UpdatedPTOCount(88) + }) - It("traces the DroppedEncryptionLevel event", func() { - tr1.EXPECT().DroppedEncryptionLevel(EncryptionHandshake) - tr2.EXPECT().DroppedEncryptionLevel(EncryptionHandshake) - tracer.DroppedEncryptionLevel(EncryptionHandshake) - }) + It("traces the UpdatedKeyFromTLS event", func() { + tr1.EXPECT().UpdatedKeyFromTLS(EncryptionHandshake, PerspectiveClient) + tr2.EXPECT().UpdatedKeyFromTLS(EncryptionHandshake, PerspectiveClient) + tracer.UpdatedKeyFromTLS(EncryptionHandshake, PerspectiveClient) + }) - It("traces the SetLossTimer event", func() { - now := time.Now() - tr1.EXPECT().SetLossTimer(TimerTypePTO, EncryptionHandshake, now) - tr2.EXPECT().SetLossTimer(TimerTypePTO, EncryptionHandshake, now) - tracer.SetLossTimer(TimerTypePTO, EncryptionHandshake, now) - }) + It("traces the UpdatedKey event", func() { + tr1.EXPECT().UpdatedKey(KeyPhase(42), true) + tr2.EXPECT().UpdatedKey(KeyPhase(42), true) + tracer.UpdatedKey(KeyPhase(42), true) + }) - It("traces the LossTimerExpired event", func() { - tr1.EXPECT().LossTimerExpired(TimerTypePTO, EncryptionHandshake) - tr2.EXPECT().LossTimerExpired(TimerTypePTO, EncryptionHandshake) - tracer.LossTimerExpired(TimerTypePTO, EncryptionHandshake) - }) + It("traces the DroppedEncryptionLevel event", func() { + tr1.EXPECT().DroppedEncryptionLevel(EncryptionHandshake) + tr2.EXPECT().DroppedEncryptionLevel(EncryptionHandshake) + tracer.DroppedEncryptionLevel(EncryptionHandshake) + }) - It("traces the LossTimerCanceled event", func() { - tr1.EXPECT().LossTimerCanceled() - tr2.EXPECT().LossTimerCanceled() - tracer.LossTimerCanceled() - }) + It("traces the SetLossTimer event", func() { + now := time.Now() + tr1.EXPECT().SetLossTimer(TimerTypePTO, EncryptionHandshake, now) + tr2.EXPECT().SetLossTimer(TimerTypePTO, EncryptionHandshake, now) + tracer.SetLossTimer(TimerTypePTO, EncryptionHandshake, now) + }) - It("traces the Close event", func() { - tr1.EXPECT().Close() - tr2.EXPECT().Close() - tracer.Close() + It("traces the LossTimerExpired event", func() { + tr1.EXPECT().LossTimerExpired(TimerTypePTO, EncryptionHandshake) + tr2.EXPECT().LossTimerExpired(TimerTypePTO, EncryptionHandshake) + tracer.LossTimerExpired(TimerTypePTO, EncryptionHandshake) + }) + + It("traces the LossTimerCanceled event", func() { + tr1.EXPECT().LossTimerCanceled() + tr2.EXPECT().LossTimerCanceled() + tracer.LossTimerCanceled() + }) + + It("traces the Close event", func() { + tr1.EXPECT().Close() + tr2.EXPECT().Close() + tracer.Close() + }) }) })