diff --git a/qlog/event.go b/qlog/event.go index 3d56f610..4a7f5a1e 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -1,6 +1,7 @@ package qlog import ( + "fmt" "net" "sort" "time" @@ -268,3 +269,52 @@ func (e eventKeyRetired) MarshalJSONObject(enc *gojay.Encoder) { enc.StringKey("trigger", "tls") enc.StringKey("key_type", e.KeyType.String()) } + +type eventTransportParameters struct { + Owner owner + + OriginalConnectionID protocol.ConnectionID + StatelessResetToken *[16]byte + DisableActiveMigration bool + MaxIdleTimeout time.Duration + MaxPacketSize protocol.ByteCount + AckDelayExponent uint8 + MaxAckDelay time.Duration + ActiveConnectionIDLimit uint64 + + InitialMaxData protocol.ByteCount + InitialMaxStreamDataBidiLocal protocol.ByteCount + InitialMaxStreamDataBidiRemote protocol.ByteCount + InitialMaxStreamDataUni protocol.ByteCount + InitialMaxStreamsBidi int64 + InitialMaxStreamsUni int64 + + // TODO: add the preferred_address +} + +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) MarshalJSONObject(enc *gojay.Encoder) { + enc.StringKey("owner", e.Owner.String()) + if e.OriginalConnectionID != nil { + enc.StringKey("original_connection_id", connectionID(e.OriginalConnectionID).String()) + } + if e.StatelessResetToken != nil { + enc.StringKey("stateless_reset_token", fmt.Sprintf("%x", e.StatelessResetToken[:])) + } + enc.BoolKey("disable_active_migration", e.DisableActiveMigration) + enc.FloatKeyOmitEmpty("max_idle_timeout", milliseconds(e.MaxIdleTimeout)) + enc.Uint64KeyNullEmpty("max_packet_size", uint64(e.MaxPacketSize)) + enc.Uint8KeyOmitEmpty("ack_delay_exponent", e.AckDelayExponent) + enc.FloatKeyOmitEmpty("max_ack_delay", milliseconds(e.MaxAckDelay)) + enc.Uint64KeyOmitEmpty("active_connection_id_limit", e.ActiveConnectionIDLimit) + + enc.Int64KeyOmitEmpty("initial_max_data", int64(e.InitialMaxData)) + enc.Int64KeyOmitEmpty("initial_max_stream_data_bidi_local", int64(e.InitialMaxStreamDataBidiLocal)) + enc.Int64KeyOmitEmpty("initial_max_stream_data_bidi_remote", int64(e.InitialMaxStreamDataBidiRemote)) + enc.Int64KeyOmitEmpty("initial_max_stream_data_uni", int64(e.InitialMaxStreamDataUni)) + enc.Int64KeyOmitEmpty("initial_max_streams_bidi", e.InitialMaxStreamsBidi) + enc.Int64KeyOmitEmpty("initial_max_streams_uni", e.InitialMaxStreamsUni) +} diff --git a/qlog/qlog.go b/qlog/qlog.go index 4abbc960..27eda8d3 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -16,6 +16,8 @@ import ( type Tracer interface { Export() error StartedConnection(t time.Time, local, remote net.Addr, version protocol.VersionNumber, srcConnID, destConnID protocol.ConnectionID) + SentTransportParameters(time.Time, *wire.TransportParameters) + ReceivedTransportParameters(time.Time, *wire.TransportParameters) SentPacket(t time.Time, hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *wire.AckFrame, frames []wire.Frame) ReceivedRetry(time.Time, *wire.Header) ReceivedPacket(t time.Time, hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, frames []wire.Frame) @@ -90,6 +92,37 @@ func (t *tracer) StartedConnection(time time.Time, local, remote net.Addr, versi }) } +func (t *tracer) SentTransportParameters(time time.Time, tp *wire.TransportParameters) { + t.recordTransportParameters(time, ownerLocal, tp) +} + +func (t *tracer) ReceivedTransportParameters(time time.Time, tp *wire.TransportParameters) { + t.recordTransportParameters(time, ownerRemote, tp) +} + +func (t *tracer) recordTransportParameters(time time.Time, owner owner, tp *wire.TransportParameters) { + t.events = append(t.events, event{ + Time: time, + eventDetails: eventTransportParameters{ + Owner: owner, + OriginalConnectionID: tp.OriginalConnectionID, + StatelessResetToken: tp.StatelessResetToken, + DisableActiveMigration: tp.DisableActiveMigration, + MaxIdleTimeout: tp.MaxIdleTimeout, + MaxPacketSize: tp.MaxPacketSize, + AckDelayExponent: tp.AckDelayExponent, + MaxAckDelay: tp.MaxAckDelay, + ActiveConnectionIDLimit: tp.ActiveConnectionIDLimit, + InitialMaxData: tp.InitialMaxData, + InitialMaxStreamDataBidiLocal: tp.InitialMaxStreamDataBidiLocal, + InitialMaxStreamDataBidiRemote: tp.InitialMaxStreamDataBidiRemote, + InitialMaxStreamDataUni: tp.InitialMaxStreamDataUni, + InitialMaxStreamsBidi: int64(tp.MaxBidiStreamNum), + InitialMaxStreamsUni: int64(tp.MaxUniStreamNum), + }, + }) +} + func (t *tracer) SentPacket(time time.Time, hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *wire.AckFrame, frames []wire.Frame) { numFrames := len(frames) if ack != nil { diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index d1966571..4b4173c0 100644 --- a/qlog/qlog_test.go +++ b/qlog/qlog_test.go @@ -125,6 +125,55 @@ var _ = Describe("Tracer", func() { Expect(ev).To(HaveKeyWithValue("dst_cid", "05060708")) }) + It("records sent transport parameters", func() { + now := time.Now() + tracer.SentTransportParameters(now, &wire.TransportParameters{ + InitialMaxStreamDataBidiLocal: 1000, + InitialMaxStreamDataBidiRemote: 2000, + InitialMaxStreamDataUni: 3000, + InitialMaxData: 4000, + MaxBidiStreamNum: 10, + MaxUniStreamNum: 20, + MaxAckDelay: 123 * time.Millisecond, + AckDelayExponent: 12, + DisableActiveMigration: true, + MaxPacketSize: 1234, + MaxIdleTimeout: 321 * time.Millisecond, + StatelessResetToken: &[16]byte{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, + OriginalConnectionID: protocol.ConnectionID{0xde, 0xad, 0xc0, 0xde}, + ActiveConnectionIDLimit: 7, + }) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("transport")) + Expect(entry.Name).To(Equal("parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("owner", "local")) + Expect(ev).To(HaveKeyWithValue("original_connection_id", "deadc0de")) + Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "112233445566778899aabbccddeeff00")) + Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(321))) + Expect(ev).To(HaveKeyWithValue("max_packet_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))) + }) + + It("records received transport parameters", func() { + now := time.Now() + tracer.ReceivedTransportParameters(now, &wire.TransportParameters{}) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("transport")) + Expect(entry.Name).To(Equal("parameters_set")) + ev := entry.Event + Expect(ev).To(HaveKeyWithValue("owner", "remote")) + }) + It("records a sent packet, without an ACK", func() { now := time.Now() tracer.SentPacket( diff --git a/qlog/types.go b/qlog/types.go index cd6e95b6..c3557e6c 100644 --- a/qlog/types.go +++ b/qlog/types.go @@ -6,6 +6,24 @@ import ( "github.com/lucas-clemente/quic-go/internal/protocol" ) +type owner uint8 + +const ( + ownerLocal owner = iota + ownerRemote +) + +func (o owner) String() string { + switch o { + case ownerLocal: + return "local" + case ownerRemote: + return "remote" + default: + panic("unknown owner") + } +} + type versionNumber protocol.VersionNumber func (v versionNumber) String() string { diff --git a/qlog/types_test.go b/qlog/types_test.go index e349ffb2..1f13d5a2 100644 --- a/qlog/types_test.go +++ b/qlog/types_test.go @@ -7,6 +7,11 @@ import ( ) var _ = Describe("Types", func() { + It("has a string representation for the owner", func() { + Expect(ownerLocal.String()).To(Equal("local")) + Expect(ownerRemote.String()).To(Equal("remote")) + }) + It("has a string representation for the category", func() { Expect(categoryConnectivity.String()).To(Equal("connectivity")) Expect(categoryTransport.String()).To(Equal("transport")) diff --git a/session.go b/session.go index 44fd133d..d5d05694 100644 --- a/session.go +++ b/session.go @@ -275,6 +275,9 @@ var newSession = func( OriginalConnectionID: origDestConnID, ActiveConnectionIDLimit: protocol.MaxActiveConnectionIDs, } + if s.qlogger != nil { + s.qlogger.SentTransportParameters(time.Now(), params) + } cs := handshake.NewCryptoSetupServer( initialStream, handshakeStream, @@ -387,6 +390,9 @@ var newClientSession = func( DisableActiveMigration: true, ActiveConnectionIDLimit: protocol.MaxActiveConnectionIDs, } + if s.qlogger != nil { + s.qlogger.SentTransportParameters(time.Now(), params) + } cs, clientHelloWritten := handshake.NewCryptoSetupClient( initialStream, handshakeStream, @@ -1188,7 +1194,12 @@ func (s *session) processTransportParameters(params *wire.TransportParameters) { return } - s.logger.Debugf("Processed Transport Parameters: %s", params) + if s.logger.Debug() { + s.logger.Debugf("Processed Transport Parameters: %s", params) + } + if s.qlogger != nil { + s.qlogger.ReceivedTransportParameters(time.Now(), params) + } s.peerParams = params // Our local idle timeout will always be > 0. s.idleTimeout = utils.MinNonZeroDuration(s.config.MaxIdleTimeout, params.MaxIdleTimeout)