From d04662a964338d620321dfc1d03b7aca048957c0 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Sat, 9 Jan 2021 14:20:52 +0800 Subject: [PATCH 1/2] add a RestoredTransportParameters method to the logging interface --- integrationtests/self/key_update_test.go | 1 + internal/mocks/logging/connection_tracer.go | 12 ++++++++++++ logging/interface.go | 1 + logging/mock_connection_tracer_test.go | 12 ++++++++++++ logging/multiplex.go | 6 ++++++ logging/multiplex_test.go | 7 +++++++ metrics/metrics.go | 1 + qlog/qlog.go | 4 ++++ 8 files changed, 44 insertions(+) diff --git a/integrationtests/self/key_update_test.go b/integrationtests/self/key_update_test.go index 1fb5a815b..806b99ce1 100644 --- a/integrationtests/self/key_update_test.go +++ b/integrationtests/self/key_update_test.go @@ -65,6 +65,7 @@ func (t *connTracer) StartedConnection(local, remote net.Addr, version logging.V func (t *connTracer) ClosedConnection(logging.CloseReason) {} func (t *connTracer) SentTransportParameters(*logging.TransportParameters) {} func (t *connTracer) ReceivedTransportParameters(*logging.TransportParameters) {} +func (t *connTracer) RestoredTransportParameters(*logging.TransportParameters) {} func (t *connTracer) SentPacket(hdr *logging.ExtendedHeader, size logging.ByteCount, ack *logging.AckFrame, frames []logging.Frame) { sentHeaders = append(sentHeaders, hdr) } diff --git a/internal/mocks/logging/connection_tracer.go b/internal/mocks/logging/connection_tracer.go index 4236612ce..ae9eca7fd 100644 --- a/internal/mocks/logging/connection_tracer.go +++ b/internal/mocks/logging/connection_tracer.go @@ -207,6 +207,18 @@ func (mr *MockConnectionTracerMockRecorder) ReceivedVersionNegotiationPacket(arg return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "ReceivedVersionNegotiationPacket", reflect.TypeOf((*MockConnectionTracer)(nil).ReceivedVersionNegotiationPacket), arg0, arg1) } +// RestoredTransportParameters mocks base method +func (m *MockConnectionTracer) RestoredTransportParameters(arg0 *wire.TransportParameters) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "RestoredTransportParameters", arg0) +} + +// RestoredTransportParameters indicates an expected call of RestoredTransportParameters +func (mr *MockConnectionTracerMockRecorder) RestoredTransportParameters(arg0 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "RestoredTransportParameters", reflect.TypeOf((*MockConnectionTracer)(nil).RestoredTransportParameters), arg0) +} + // SentPacket mocks base method func (m *MockConnectionTracer) SentPacket(arg0 *wire.ExtendedHeader, arg1 protocol.ByteCount, arg2 *wire.AckFrame, arg3 []logging.Frame) { m.ctrl.T.Helper() diff --git a/logging/interface.go b/logging/interface.go index 908375713..cf52cc156 100644 --- a/logging/interface.go +++ b/logging/interface.go @@ -107,6 +107,7 @@ type ConnectionTracer interface { ClosedConnection(CloseReason) SentTransportParameters(*TransportParameters) ReceivedTransportParameters(*TransportParameters) + RestoredTransportParameters(parameters *TransportParameters) // for 0-RTT SentPacket(hdr *ExtendedHeader, size ByteCount, ack *AckFrame, frames []Frame) ReceivedVersionNegotiationPacket(*Header, []VersionNumber) ReceivedRetry(*Header) diff --git a/logging/mock_connection_tracer_test.go b/logging/mock_connection_tracer_test.go index 1a45a9039..c290e0c73 100644 --- a/logging/mock_connection_tracer_test.go +++ b/logging/mock_connection_tracer_test.go @@ -206,6 +206,18 @@ func (mr *MockConnectionTracerMockRecorder) ReceivedVersionNegotiationPacket(arg return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "ReceivedVersionNegotiationPacket", reflect.TypeOf((*MockConnectionTracer)(nil).ReceivedVersionNegotiationPacket), arg0, arg1) } +// RestoredTransportParameters mocks base method +func (m *MockConnectionTracer) RestoredTransportParameters(arg0 *wire.TransportParameters) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "RestoredTransportParameters", arg0) +} + +// RestoredTransportParameters indicates an expected call of RestoredTransportParameters +func (mr *MockConnectionTracerMockRecorder) RestoredTransportParameters(arg0 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "RestoredTransportParameters", reflect.TypeOf((*MockConnectionTracer)(nil).RestoredTransportParameters), arg0) +} + // SentPacket mocks base method func (m *MockConnectionTracer) SentPacket(arg0 *wire.ExtendedHeader, arg1 protocol.ByteCount, arg2 *wire.AckFrame, arg3 []Frame) { m.ctrl.T.Helper() diff --git a/logging/multiplex.go b/logging/multiplex.go index f700d880e..f219a43ab 100644 --- a/logging/multiplex.go +++ b/logging/multiplex.go @@ -84,6 +84,12 @@ func (m *connTracerMultiplexer) ReceivedTransportParameters(tp *TransportParamet } } +func (m *connTracerMultiplexer) RestoredTransportParameters(tp *TransportParameters) { + for _, t := range m.tracers { + t.RestoredTransportParameters(tp) + } +} + func (m *connTracerMultiplexer) SentPacket(hdr *ExtendedHeader, size ByteCount, ack *AckFrame, frames []Frame) { for _, t := range m.tracers { t.SentPacket(hdr, size, ack, frames) diff --git a/logging/multiplex_test.go b/logging/multiplex_test.go index 56fc8b888..dbd068ac9 100644 --- a/logging/multiplex_test.go +++ b/logging/multiplex_test.go @@ -126,6 +126,13 @@ var _ = Describe("Tracing", func() { tracer.ReceivedTransportParameters(tp) }) + It("traces the RestoredTransportParameters event", func() { + tp := &wire.TransportParameters{InitialMaxData: 1337} + tr1.EXPECT().RestoredTransportParameters(tp) + tr2.EXPECT().RestoredTransportParameters(tp) + tracer.RestoredTransportParameters(tp) + }) + It("traces the SentPacket event", func() { hdr := &ExtendedHeader{Header: Header{DestConnectionID: ConnectionID{1, 2, 3}}} ack := &AckFrame{AckRanges: []AckRange{{Smallest: 1, Largest: 10}}} diff --git a/metrics/metrics.go b/metrics/metrics.go index 8e79707ef..df53e427b 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -165,6 +165,7 @@ func (t *connTracer) ClosedConnection(r logging.CloseReason) { } func (t *connTracer) SentTransportParameters(*logging.TransportParameters) {} func (t *connTracer) ReceivedTransportParameters(*logging.TransportParameters) {} +func (t *connTracer) RestoredTransportParameters(*logging.TransportParameters) {} func (t *connTracer) SentPacket(hdr *logging.ExtendedHeader, _ logging.ByteCount, _ *logging.AckFrame, _ []logging.Frame) { typ := logging.PacketTypeFromHeader(&hdr.Header) if typ == logging.PacketType1RTT { diff --git a/qlog/qlog.go b/qlog/qlog.go index dd4848d27..96ccf2fd7 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -168,6 +168,10 @@ func (t *connectionTracer) ReceivedTransportParameters(tp *wire.TransportParamet t.recordTransportParameters(t.perspective.Opposite(), tp) } +func (t *connectionTracer) RestoredTransportParameters(tp *wire.TransportParameters) { + // TODO: implement +} + func (t *connectionTracer) recordTransportParameters(sentBy protocol.Perspective, tp *wire.TransportParameters) { owner := ownerLocal if sentBy != t.perspective { From 60805d887fa5e0826f6a7e25af89e9a19c3771d6 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Sat, 9 Jan 2021 14:26:54 +0800 Subject: [PATCH 2/2] implement qlogging of the parameters_restored event --- qlog/event.go | 34 +++++++++++++++++++++------------- qlog/qlog.go | 28 +++++++++++++++++++--------- qlog/qlog_test.go | 24 ++++++++++++++++++++++++ 3 files changed, 64 insertions(+), 22 deletions(-) diff --git a/qlog/event.go b/qlog/event.go index 2ab225e13..93aa58589 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -338,8 +338,9 @@ func (e eventKeyRetired) MarshalJSONObject(enc *gojay.Encoder) { } type eventTransportParameters struct { - Owner owner - SentBy protocol.Perspective + Restore bool + Owner owner + SentBy protocol.Perspective OriginalDestinationConnectionID protocol.ConnectionID InitialSourceConnectionID protocol.ConnectionID @@ -366,21 +367,28 @@ type eventTransportParameters struct { } func (e eventTransportParameters) Category() category { return categoryTransport } -func (e eventTransportParameters) Name() string { return "parameters_set" } -func (e eventTransportParameters) IsNil() bool { return false } +func (e eventTransportParameters) Name() string { + if e.Restore { + return "parameters_restored" + } + return "parameters_set" +} +func (e eventTransportParameters) IsNil() bool { return false } func (e eventTransportParameters) MarshalJSONObject(enc *gojay.Encoder) { - enc.StringKey("owner", e.Owner.String()) - if e.SentBy == protocol.PerspectiveServer { - enc.StringKey("original_destination_connection_id", connectionID(e.OriginalDestinationConnectionID).String()) - if e.StatelessResetToken != nil { - enc.StringKey("stateless_reset_token", fmt.Sprintf("%x", e.StatelessResetToken[:])) - } - if e.RetrySourceConnectionID != nil { - enc.StringKey("retry_source_connection_id", connectionID(*e.RetrySourceConnectionID).String()) + if !e.Restore { + enc.StringKey("owner", e.Owner.String()) + if e.SentBy == protocol.PerspectiveServer { + enc.StringKey("original_destination_connection_id", connectionID(e.OriginalDestinationConnectionID).String()) + if e.StatelessResetToken != nil { + enc.StringKey("stateless_reset_token", fmt.Sprintf("%x", e.StatelessResetToken[:])) + } + if e.RetrySourceConnectionID != nil { + enc.StringKey("retry_source_connection_id", connectionID(*e.RetrySourceConnectionID).String()) + } } + enc.StringKey("initial_source_connection_id", connectionID(e.InitialSourceConnectionID).String()) } - enc.StringKey("initial_source_connection_id", connectionID(e.InitialSourceConnectionID).String()) enc.BoolKey("disable_active_migration", e.DisableActiveMigration) enc.FloatKeyOmitEmpty("max_idle_timeout", milliseconds(e.MaxIdleTimeout)) enc.Int64KeyNullEmpty("max_udp_payload_size", int64(e.MaxUDPPayloadSize)) diff --git a/qlog/qlog.go b/qlog/qlog.go index 96ccf2fd7..696b2f65a 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -169,14 +169,28 @@ func (t *connectionTracer) ReceivedTransportParameters(tp *wire.TransportParamet } func (t *connectionTracer) RestoredTransportParameters(tp *wire.TransportParameters) { - // TODO: implement + ev := t.toTransportParameters(tp) + ev.Restore = true + + t.mutex.Lock() + t.recordEvent(time.Now(), ev) + t.mutex.Unlock() } func (t *connectionTracer) recordTransportParameters(sentBy protocol.Perspective, tp *wire.TransportParameters) { - owner := ownerLocal + ev := t.toTransportParameters(tp) + ev.Owner = ownerLocal if sentBy != t.perspective { - owner = ownerRemote + ev.Owner = ownerRemote } + ev.SentBy = sentBy + + t.mutex.Lock() + t.recordEvent(time.Now(), ev) + t.mutex.Unlock() +} + +func (t *connectionTracer) toTransportParameters(tp *wire.TransportParameters) *eventTransportParameters { var pa *preferredAddress if tp.PreferredAddress != nil { pa = &preferredAddress{ @@ -188,10 +202,7 @@ func (t *connectionTracer) recordTransportParameters(sentBy protocol.Perspective StatelessResetToken: tp.PreferredAddress.StatelessResetToken, } } - t.mutex.Lock() - t.recordEvent(time.Now(), &eventTransportParameters{ - Owner: owner, - SentBy: sentBy, + return &eventTransportParameters{ OriginalDestinationConnectionID: tp.OriginalDestinationConnectionID, InitialSourceConnectionID: tp.InitialSourceConnectionID, RetrySourceConnectionID: tp.RetrySourceConnectionID, @@ -210,8 +221,7 @@ func (t *connectionTracer) recordTransportParameters(sentBy protocol.Perspective InitialMaxStreamsUni: int64(tp.MaxUniStreamNum), PreferredAddress: pa, MaxDatagramFrameSize: tp.MaxDatagramFrameSize, - }) - t.mutex.Unlock() + } } func (t *connectionTracer) SentPacket(hdr *wire.ExtendedHeader, packetSize logging.ByteCount, ack *logging.AckFrame, frames []logging.Frame) { diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index 9890492a3..fa1789968 100644 --- a/qlog/qlog_test.go +++ b/qlog/qlog_test.go @@ -340,6 +340,30 @@ var _ = Describe("Tracing", func() { Expect(ev).ToNot(HaveKey("original_destination_connection_id")) }) + 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 sent packet, without an ACK", func() { tracer.SentPacket( &logging.ExtendedHeader{