From ef901e34358c325a08d41d0d7f12006e1284ebde Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Sun, 22 Mar 2020 13:00:26 +0700 Subject: [PATCH] use the current timestamp of every event in qlog --- client.go | 3 +- internal/ackhandler/sent_packet_handler.go | 12 +- internal/handshake/crypto_setup.go | 18 +- internal/handshake/updatable_aead.go | 7 +- qlog/qlog.go | 266 +++++++++------------ qlog/qlog_test.go | 67 ++---- server.go | 2 +- session.go | 24 +- 8 files changed, 167 insertions(+), 232 deletions(-) diff --git a/client.go b/client.go index 0f9d4ac7..5576c84b 100644 --- a/client.go +++ b/client.go @@ -8,7 +8,6 @@ import ( "net" "strings" "sync" - "time" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/utils" @@ -251,7 +250,7 @@ func newClient( func (c *client) dial(ctx context.Context, qlogger qlog.Tracer) error { c.logger.Infof("Starting new connection to %s (%s -> %s), source connection ID %s, destination connection ID %s, version %s", c.tlsConf.ServerName, c.conn.LocalAddr(), c.conn.RemoteAddr(), c.srcConnID, c.destConnID, c.version) if qlogger != nil { - qlogger.StartedConnection(time.Now(), c.conn.LocalAddr(), c.conn.LocalAddr(), c.version, c.srcConnID, c.destConnID) + qlogger.StartedConnection(c.conn.LocalAddr(), c.conn.LocalAddr(), c.version, c.srcConnID, c.destConnID) } c.mutex.Lock() diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index 19aa94d6..3ace110c 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -165,7 +165,7 @@ func (h *sentPacketHandler) dropPackets(encLevel protocol.EncryptionLevel) { } h.setLossDetectionTimer() if h.qlogger != nil && h.ptoCount != 0 { - h.qlogger.UpdatedPTOCount(time.Now(), 0) + h.qlogger.UpdatedPTOCount(0) } h.ptoCount = 0 h.ptoMode = SendNone @@ -267,7 +267,7 @@ func (h *sentPacketHandler) ReceivedAck(ack *wire.AckFrame, encLevel protocol.En if h.initialPackets != nil { packetsInFlight += h.initialPackets.history.Len() } - h.qlogger.UpdatedMetrics(rcvTime, h.rttStats, h.congestion.GetCongestionWindow(), h.bytesInFlight, packetsInFlight) + h.qlogger.UpdatedMetrics(h.rttStats, h.congestion.GetCongestionWindow(), h.bytesInFlight, packetsInFlight) } } @@ -294,7 +294,7 @@ func (h *sentPacketHandler) ReceivedAck(ack *wire.AckFrame, encLevel protocol.En } if h.qlogger != nil && h.ptoCount != 0 { - h.qlogger.UpdatedPTOCount(rcvTime, 0) + h.qlogger.UpdatedPTOCount(0) } h.ptoCount = 0 h.numProbesToSend = 0 @@ -459,12 +459,12 @@ func (h *sentPacketHandler) detectLostPackets( if packet.SendTime.Before(lostSendTime) { lostPackets = append(lostPackets, packet) if h.qlogger != nil { - h.qlogger.LostPacket(now, packet.EncryptionLevel, packet.PacketNumber, qlog.PacketLossTimeThreshold) + h.qlogger.LostPacket(packet.EncryptionLevel, packet.PacketNumber, qlog.PacketLossTimeThreshold) } } else if pnSpace.largestAcked >= packet.PacketNumber+packetThreshold { lostPackets = append(lostPackets, packet) if h.qlogger != nil { - h.qlogger.LostPacket(now, packet.EncryptionLevel, packet.PacketNumber, qlog.PacketLossReorderingThreshold) + h.qlogger.LostPacket(packet.EncryptionLevel, packet.PacketNumber, qlog.PacketLossReorderingThreshold) } } else if pnSpace.lossTime.IsZero() { // Note: This conditional is only entered once per call @@ -543,7 +543,7 @@ func (h *sentPacketHandler) onVerifiedLossDetectionTimeout() error { } h.ptoCount++ if h.qlogger != nil { - h.qlogger.UpdatedPTOCount(time.Now(), h.ptoCount) + h.qlogger.UpdatedPTOCount(h.ptoCount) } h.numProbesToSend += 2 switch encLevel { diff --git a/internal/handshake/crypto_setup.go b/internal/handshake/crypto_setup.go index 0ae4f238..c63a8665 100644 --- a/internal/handshake/crypto_setup.go +++ b/internal/handshake/crypto_setup.go @@ -202,9 +202,8 @@ func newCryptoSetup( ) (*cryptoSetup, <-chan *wire.TransportParameters /* ClientHello written. Receive nil for non-0-RTT */) { initialSealer, initialOpener := NewInitialAEAD(connID, perspective) if qlogger != nil { - now := time.Now() - qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveClient) - qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveServer) + qlogger.UpdatedKeyFromTLS(protocol.EncryptionInitial, protocol.PerspectiveClient) + qlogger.UpdatedKeyFromTLS(protocol.EncryptionInitial, protocol.PerspectiveServer) } extHandler := newExtensionHandler(tp.Marshal(), perspective) cs := &cryptoSetup{ @@ -241,9 +240,8 @@ func (h *cryptoSetup) ChangeConnectionID(id protocol.ConnectionID) { h.initialSealer = initialSealer h.initialOpener = initialOpener if h.qlogger != nil { - now := time.Now() - h.qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveClient) - h.qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveServer) + h.qlogger.UpdatedKeyFromTLS(protocol.EncryptionInitial, protocol.PerspectiveClient) + h.qlogger.UpdatedKeyFromTLS(protocol.EncryptionInitial, protocol.PerspectiveServer) } } @@ -575,7 +573,7 @@ func (h *cryptoSetup) SetReadKey(encLevel qtls.EncryptionLevel, suite *qtls.Ciph h.mutex.Unlock() h.logger.Debugf("Installed 0-RTT Read keys (using %s)", qtls.CipherSuiteName(suite.ID)) if h.qlogger != nil { - h.qlogger.UpdatedKeyFromTLS(time.Now(), protocol.Encryption0RTT, h.perspective.Opposite()) + h.qlogger.UpdatedKeyFromTLS(protocol.Encryption0RTT, h.perspective.Opposite()) } return case qtls.EncryptionHandshake: @@ -597,7 +595,7 @@ func (h *cryptoSetup) SetReadKey(encLevel qtls.EncryptionLevel, suite *qtls.Ciph } h.mutex.Unlock() if h.qlogger != nil { - h.qlogger.UpdatedKeyFromTLS(time.Now(), h.readEncLevel, h.perspective.Opposite()) + h.qlogger.UpdatedKeyFromTLS(h.readEncLevel, h.perspective.Opposite()) } h.receivedReadKey <- struct{}{} } @@ -616,7 +614,7 @@ func (h *cryptoSetup) SetWriteKey(encLevel qtls.EncryptionLevel, suite *qtls.Cip h.mutex.Unlock() h.logger.Debugf("Installed 0-RTT Write keys (using %s)", qtls.CipherSuiteName(suite.ID)) if h.qlogger != nil { - h.qlogger.UpdatedKeyFromTLS(time.Now(), protocol.Encryption0RTT, h.perspective) + h.qlogger.UpdatedKeyFromTLS(protocol.Encryption0RTT, h.perspective) } return case qtls.EncryptionHandshake: @@ -642,7 +640,7 @@ func (h *cryptoSetup) SetWriteKey(encLevel qtls.EncryptionLevel, suite *qtls.Cip } h.mutex.Unlock() if h.qlogger != nil { - h.qlogger.UpdatedKeyFromTLS(time.Now(), h.writeEncLevel, h.perspective) + h.qlogger.UpdatedKeyFromTLS(h.writeEncLevel, h.perspective) } h.receivedWriteKey <- struct{}{} } diff --git a/internal/handshake/updatable_aead.go b/internal/handshake/updatable_aead.go index 2c4a3303..8453e982 100644 --- a/internal/handshake/updatable_aead.go +++ b/internal/handshake/updatable_aead.go @@ -184,7 +184,7 @@ func (a *updatableAEAD) Open(dst, src []byte, rcvTime time.Time, pn protocol.Pac a.rollKeys(rcvTime) a.logger.Debugf("Peer updated keys to %s", a.keyPhase) if a.qlogger != nil { - a.qlogger.UpdatedKey(rcvTime, a.keyPhase, true) + a.qlogger.UpdatedKey(a.keyPhase, true) } a.firstRcvdWithCurrentKey = pn return dec, err @@ -244,11 +244,10 @@ func (a *updatableAEAD) shouldInitiateKeyUpdate() bool { func (a *updatableAEAD) KeyPhase() protocol.KeyPhaseBit { if a.shouldInitiateKeyUpdate() { - now := time.Now() if a.qlogger != nil { - a.qlogger.UpdatedKey(now, a.keyPhase, false) + a.qlogger.UpdatedKey(a.keyPhase, false) } - a.rollKeys(now) + a.rollKeys(time.Now()) } return a.keyPhase.Bit() } diff --git a/qlog/qlog.go b/qlog/qlog.go index 470b4c0b..947369c9 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -19,20 +19,20 @@ const eventChanSize = 50 // A Tracer records events to be exported to a qlog. 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) - BufferedPacket(time.Time, PacketType) - DroppedPacket(time.Time, PacketType, protocol.ByteCount, PacketDropReason) - UpdatedMetrics(t time.Time, rttStats *congestion.RTTStats, cwnd protocol.ByteCount, bytesInFLight protocol.ByteCount, packetsInFlight int) - LostPacket(time.Time, protocol.EncryptionLevel, protocol.PacketNumber, PacketLossReason) - UpdatedPTOCount(time.Time, uint32) - UpdatedKeyFromTLS(time.Time, protocol.EncryptionLevel, protocol.Perspective) - UpdatedKey(t time.Time, generation protocol.KeyPhase, remote bool) - DroppedEncryptionLevel(time.Time, protocol.EncryptionLevel) + StartedConnection(local, remote net.Addr, version protocol.VersionNumber, srcConnID, destConnID protocol.ConnectionID) + SentTransportParameters(*wire.TransportParameters) + ReceivedTransportParameters(*wire.TransportParameters) + SentPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *wire.AckFrame, frames []wire.Frame) + ReceivedRetry(*wire.Header) + ReceivedPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, frames []wire.Frame) + BufferedPacket(PacketType) + DroppedPacket(PacketType, protocol.ByteCount, PacketDropReason) + UpdatedMetrics(rttStats *congestion.RTTStats, cwnd protocol.ByteCount, bytesInFLight protocol.ByteCount, packetsInFlight int) + LostPacket(protocol.EncryptionLevel, protocol.PacketNumber, PacketLossReason) + UpdatedPTOCount(value uint32) + UpdatedKeyFromTLS(protocol.EncryptionLevel, protocol.Perspective) + UpdatedKey(generation protocol.KeyPhase, remote bool) + DroppedEncryptionLevel(protocol.EncryptionLevel) } type tracer struct { @@ -110,7 +110,14 @@ func (t *tracer) Export() error { return t.w.Close() } -func (t *tracer) StartedConnection(time time.Time, local, remote net.Addr, version protocol.VersionNumber, srcConnID, destConnID protocol.ConnectionID) { +func (t *tracer) recordEvent(details eventDetails) { + t.events <- event{ + Time: time.Now(), + eventDetails: details, + } +} + +func (t *tracer) StartedConnection(local, remote net.Addr, version protocol.VersionNumber, srcConnID, destConnID protocol.ConnectionID) { // ignore this event if we're not dealing with UDP addresses here localAddr, ok := local.(*net.UDPAddr) if !ok { @@ -120,50 +127,44 @@ func (t *tracer) StartedConnection(time time.Time, local, remote net.Addr, versi if !ok { return } - t.events <- event{ - Time: time, - eventDetails: eventConnectionStarted{ - SrcAddr: localAddr, - DestAddr: remoteAddr, - Version: version, - SrcConnectionID: srcConnID, - DestConnectionID: destConnID, - }, - } + t.recordEvent(&eventConnectionStarted{ + SrcAddr: localAddr, + DestAddr: remoteAddr, + Version: version, + SrcConnectionID: srcConnID, + DestConnectionID: destConnID, + }) } -func (t *tracer) SentTransportParameters(time time.Time, tp *wire.TransportParameters) { - t.recordTransportParameters(time, ownerLocal, tp) +func (t *tracer) SentTransportParameters(tp *wire.TransportParameters) { + t.recordTransportParameters(ownerLocal, tp) } -func (t *tracer) ReceivedTransportParameters(time time.Time, tp *wire.TransportParameters) { - t.recordTransportParameters(time, ownerRemote, tp) +func (t *tracer) ReceivedTransportParameters(tp *wire.TransportParameters) { + t.recordTransportParameters(ownerRemote, tp) } -func (t *tracer) recordTransportParameters(time time.Time, owner owner, tp *wire.TransportParameters) { - t.events <- event{ - Time: time, - eventDetails: eventTransportParameters{ - Owner: owner, - OriginalConnectionID: tp.OriginalConnectionID, - StatelessResetToken: tp.StatelessResetToken, - DisableActiveMigration: tp.DisableActiveMigration, - MaxIdleTimeout: tp.MaxIdleTimeout, - MaxUDPPayloadSize: tp.MaxUDPPayloadSize, - 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) recordTransportParameters(owner owner, tp *wire.TransportParameters) { + t.recordEvent(&eventTransportParameters{ + Owner: owner, + OriginalConnectionID: tp.OriginalConnectionID, + StatelessResetToken: tp.StatelessResetToken, + DisableActiveMigration: tp.DisableActiveMigration, + MaxIdleTimeout: tp.MaxIdleTimeout, + MaxUDPPayloadSize: tp.MaxUDPPayloadSize, + 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) { +func (t *tracer) SentPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *wire.AckFrame, frames []wire.Frame) { numFrames := len(frames) if ack != nil { numFrames++ @@ -177,137 +178,94 @@ func (t *tracer) SentPacket(time time.Time, hdr *wire.ExtendedHeader, packetSize } header := *transformExtendedHeader(hdr) header.PacketSize = packetSize - t.events <- event{ - Time: time, - eventDetails: eventPacketSent{ - PacketType: PacketTypeFromHeader(&hdr.Header), - Header: header, - Frames: fs, - }, - } + t.recordEvent(&eventPacketSent{ + PacketType: PacketTypeFromHeader(&hdr.Header), + Header: header, + Frames: fs, + }) } -func (t *tracer) ReceivedPacket(time time.Time, hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, frames []wire.Frame) { +func (t *tracer) ReceivedPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, frames []wire.Frame) { fs := make([]frame, len(frames)) for i, f := range frames { fs[i] = *transformFrame(f) } header := *transformExtendedHeader(hdr) header.PacketSize = packetSize - t.events <- event{ - Time: time, - eventDetails: eventPacketReceived{ - PacketType: PacketTypeFromHeader(&hdr.Header), - Header: header, - Frames: fs, - }, - } + t.recordEvent(&eventPacketReceived{ + PacketType: PacketTypeFromHeader(&hdr.Header), + Header: header, + Frames: fs, + }) } -func (t *tracer) ReceivedRetry(time time.Time, hdr *wire.Header) { - t.events <- event{ - Time: time, - eventDetails: eventRetryReceived{ - Header: *transformHeader(hdr), - }, - } +func (t *tracer) ReceivedRetry(hdr *wire.Header) { + t.recordEvent(&eventRetryReceived{ + Header: *transformHeader(hdr), + }) } -func (t *tracer) BufferedPacket(time time.Time, packetType PacketType) { - t.events <- event{ - Time: time, - eventDetails: eventPacketBuffered{PacketType: packetType}, - } +func (t *tracer) BufferedPacket(packetType PacketType) { + t.recordEvent(&eventPacketBuffered{PacketType: packetType}) } -func (t *tracer) DroppedPacket(time time.Time, packetType PacketType, size protocol.ByteCount, dropReason PacketDropReason) { - t.events <- event{ - Time: time, - eventDetails: eventPacketDropped{ - PacketType: packetType, - PacketSize: size, - Trigger: dropReason, - }, - } +func (t *tracer) DroppedPacket(packetType PacketType, size protocol.ByteCount, dropReason PacketDropReason) { + t.recordEvent(&eventPacketDropped{ + PacketType: packetType, + PacketSize: size, + Trigger: dropReason, + }) } -func (t *tracer) UpdatedMetrics(time time.Time, rttStats *congestion.RTTStats, cwnd, bytesInFlight protocol.ByteCount, packetsInFlight int) { - t.events <- event{ - Time: time, - eventDetails: eventMetricsUpdated{ - MinRTT: rttStats.MinRTT(), - SmoothedRTT: rttStats.SmoothedRTT(), - LatestRTT: rttStats.LatestRTT(), - RTTVariance: rttStats.MeanDeviation(), - CongestionWindow: cwnd, - BytesInFlight: bytesInFlight, - PacketsInFlight: packetsInFlight, - }, - } +func (t *tracer) UpdatedMetrics(rttStats *congestion.RTTStats, cwnd, bytesInFlight protocol.ByteCount, packetsInFlight int) { + t.recordEvent(&eventMetricsUpdated{ + MinRTT: rttStats.MinRTT(), + SmoothedRTT: rttStats.SmoothedRTT(), + LatestRTT: rttStats.LatestRTT(), + RTTVariance: rttStats.MeanDeviation(), + CongestionWindow: cwnd, + BytesInFlight: bytesInFlight, + PacketsInFlight: packetsInFlight, + }) } -func (t *tracer) LostPacket(time time.Time, encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, lossReason PacketLossReason) { - t.events <- event{ - Time: time, - eventDetails: eventPacketLost{ - PacketType: getPacketTypeFromEncryptionLevel(encLevel), - PacketNumber: pn, - Trigger: lossReason, - }, - } +func (t *tracer) LostPacket(encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, lossReason PacketLossReason) { + t.recordEvent(&eventPacketLost{ + PacketType: getPacketTypeFromEncryptionLevel(encLevel), + PacketNumber: pn, + Trigger: lossReason, + }) } -func (t *tracer) UpdatedPTOCount(time time.Time, value uint32) { - t.events <- event{ - Time: time, - eventDetails: eventUpdatedPTO{Value: value}, - } +func (t *tracer) UpdatedPTOCount(value uint32) { + t.recordEvent(&eventUpdatedPTO{Value: value}) } -func (t *tracer) UpdatedKeyFromTLS(time time.Time, encLevel protocol.EncryptionLevel, pers protocol.Perspective) { - t.events <- event{ - Time: time, - eventDetails: eventKeyUpdated{ - Trigger: keyUpdateTLS, - KeyType: encLevelToKeyType(encLevel, pers), - }, - } +func (t *tracer) UpdatedKeyFromTLS(encLevel protocol.EncryptionLevel, pers protocol.Perspective) { + t.recordEvent(&eventKeyUpdated{ + Trigger: keyUpdateTLS, + KeyType: encLevelToKeyType(encLevel, pers), + }) } -func (t *tracer) UpdatedKey(time time.Time, generation protocol.KeyPhase, remote bool) { +func (t *tracer) UpdatedKey(generation protocol.KeyPhase, remote bool) { trigger := keyUpdateLocal if remote { trigger = keyUpdateRemote } - t.events <- event{ - Time: time, - eventDetails: eventKeyUpdated{ - Trigger: trigger, - KeyType: keyTypeClient1RTT, - Generation: generation, - }, - } - t.events <- event{ - Time: time, - eventDetails: eventKeyUpdated{ - Trigger: trigger, - KeyType: keyTypeServer1RTT, - Generation: generation, - }, - } + t.recordEvent(&eventKeyUpdated{ + Trigger: trigger, + KeyType: keyTypeClient1RTT, + Generation: generation, + }) + t.recordEvent(&eventKeyUpdated{ + Trigger: trigger, + KeyType: keyTypeServer1RTT, + Generation: generation, + }) } -func (t *tracer) DroppedEncryptionLevel(time time.Time, encLevel protocol.EncryptionLevel) { - t.events <- event{ - Time: time, - eventDetails: eventKeyRetired{ - KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveServer), - }, - } - t.events <- event{ - Time: time, - eventDetails: eventKeyRetired{ - KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveClient), - }, - } +func (t *tracer) DroppedEncryptionLevel(encLevel protocol.EncryptionLevel) { + t.recordEvent(&eventKeyRetired{KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveServer)}) + t.recordEvent(&eventKeyRetired{KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveClient)}) } diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index 67bee47d..bf98f8ea 100644 --- a/qlog/qlog_test.go +++ b/qlog/qlog_test.go @@ -92,7 +92,7 @@ var _ = Describe("Tracer", func() { protocol.ConnectionID{0xde, 0xad, 0xbe, 0xef}, ) for i := uint32(0); i < 1000; i++ { - tracer.UpdatedPTOCount(time.Now(), i) + tracer.UpdatedPTOCount(i) } Expect(tracer.Export()).To(MatchError("writer full")) }) @@ -129,9 +129,7 @@ var _ = Describe("Tracer", func() { } It("records connection starts", func() { - now := time.Now() tracer.StartedConnection( - now, &net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42}, &net.UDPAddr{IP: net.IPv4(192, 168, 12, 34), Port: 24}, 0xdeadbeef, @@ -139,7 +137,7 @@ var _ = Describe("Tracer", func() { protocol.ConnectionID{5, 6, 7, 8}, ) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("connection_started")) ev := entry.Event @@ -154,8 +152,7 @@ var _ = Describe("Tracer", func() { }) It("records sent transport parameters", func() { - now := time.Now() - tracer.SentTransportParameters(now, &wire.TransportParameters{ + tracer.SentTransportParameters(&wire.TransportParameters{ InitialMaxStreamDataBidiLocal: 1000, InitialMaxStreamDataBidiRemote: 2000, InitialMaxStreamDataUni: 3000, @@ -172,7 +169,7 @@ var _ = Describe("Tracer", func() { ActiveConnectionIDLimit: 7, }) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("parameters_set")) ev := entry.Event @@ -192,10 +189,9 @@ var _ = Describe("Tracer", func() { }) It("records received transport parameters", func() { - now := time.Now() - tracer.ReceivedTransportParameters(now, &wire.TransportParameters{}) + tracer.ReceivedTransportParameters(&wire.TransportParameters{}) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("parameters_set")) ev := entry.Event @@ -203,9 +199,7 @@ var _ = Describe("Tracer", func() { }) It("records a sent packet, without an ACK", func() { - now := time.Now() tracer.SentPacket( - now, &wire.ExtendedHeader{ Header: wire.Header{ IsLongHeader: true, @@ -224,7 +218,7 @@ var _ = Describe("Tracer", func() { }, ) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("packet_sent")) ev := entry.Event @@ -243,7 +237,6 @@ var _ = Describe("Tracer", func() { It("records a sent packet, without an ACK", func() { tracer.SentPacket( - time.Now(), &wire.ExtendedHeader{ Header: wire.Header{DestConnectionID: protocol.ConnectionID{1, 2, 3, 4}}, PacketNumber: 1337, @@ -264,9 +257,7 @@ var _ = Describe("Tracer", func() { }) It("records a received packet", func() { - now := time.Now() tracer.ReceivedPacket( - now, &wire.ExtendedHeader{ Header: wire.Header{ IsLongHeader: true, @@ -284,7 +275,7 @@ var _ = Describe("Tracer", func() { }, ) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("packet_received")) ev := entry.Event @@ -299,9 +290,7 @@ var _ = Describe("Tracer", func() { }) It("records a received Retry packet", func() { - now := time.Now() tracer.ReceivedRetry( - now, &wire.Header{ IsLongHeader: true, Type: protocol.PacketTypeRetry, @@ -311,7 +300,7 @@ var _ = Describe("Tracer", func() { }, ) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("packet_received")) ev := entry.Event @@ -321,10 +310,9 @@ var _ = Describe("Tracer", func() { }) It("records buffered packets", func() { - now := time.Now() - tracer.BufferedPacket(now, PacketTypeHandshake) + tracer.BufferedPacket(PacketTypeHandshake) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("packet_buffered")) ev := entry.Event @@ -333,10 +321,9 @@ var _ = Describe("Tracer", func() { }) It("records dropped packets", func() { - now := time.Now() - tracer.DroppedPacket(now, PacketTypeHandshake, 1337, PacketDropPayloadDecryptError) + tracer.DroppedPacket(PacketTypeHandshake, 1337, PacketDropPayloadDecryptError) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("transport")) Expect(entry.Name).To(Equal("packet_dropped")) ev := entry.Event @@ -358,14 +345,13 @@ var _ = Describe("Tracer", func() { )) Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) tracer.UpdatedMetrics( - now, rttStats, 4321, 1234, 42, ) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("recovery")) Expect(entry.Name).To(Equal("metrics_updated")) ev := entry.Event @@ -381,10 +367,9 @@ var _ = Describe("Tracer", func() { }) It("records lost packets", func() { - now := time.Now() - tracer.LostPacket(now, protocol.EncryptionHandshake, 42, PacketLossReorderingThreshold) + tracer.LostPacket(protocol.EncryptionHandshake, 42, PacketLossReorderingThreshold) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("recovery")) Expect(entry.Name).To(Equal("packet_lost")) ev := entry.Event @@ -394,20 +379,18 @@ var _ = Describe("Tracer", func() { }) It("records PTO changes", func() { - now := time.Now() - tracer.UpdatedPTOCount(now, 42) + tracer.UpdatedPTOCount(42) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("recovery")) Expect(entry.Name).To(Equal("metrics_updated")) Expect(entry.Event).To(HaveKeyWithValue("pto_count", float64(42))) }) It("records TLS key updates", func() { - now := time.Now() - tracer.UpdatedKeyFromTLS(now, protocol.EncryptionHandshake, protocol.PerspectiveClient) + tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient) entry := exportAndParseSingle() - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("security")) Expect(entry.Name).To(Equal("key_updated")) ev := entry.Event @@ -419,13 +402,12 @@ var _ = Describe("Tracer", func() { }) It("records QUIC key updates", func() { - now := time.Now() - tracer.UpdatedKey(now, 1337, true) + tracer.UpdatedKey(1337, true) entries := exportAndParse() Expect(entries).To(HaveLen(2)) var keyTypes []string for _, entry := range entries { - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("security")) Expect(entry.Name).To(Equal("key_updated")) ev := entry.Event @@ -439,13 +421,12 @@ var _ = Describe("Tracer", func() { }) It("records dropped encryption levels", func() { - now := time.Now() - tracer.DroppedEncryptionLevel(now, protocol.EncryptionInitial) + tracer.DroppedEncryptionLevel(protocol.EncryptionInitial) entries := exportAndParse() Expect(entries).To(HaveLen(2)) var keyTypes []string for _, entry := range entries { - Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) Expect(entry.Category).To(Equal("security")) Expect(entry.Name).To(Equal("key_retired")) ev := entry.Event diff --git a/server.go b/server.go index 7dcd9f08..f8808d8c 100644 --- a/server.go +++ b/server.go @@ -428,7 +428,7 @@ func (s *baseServer) createNewSession( } } if qlogger != nil { - qlogger.StartedConnection(time.Now(), s.conn.LocalAddr(), remoteAddr, version, srcConnID, destConnID) + qlogger.StartedConnection(s.conn.LocalAddr(), remoteAddr, version, srcConnID, destConnID) } sess := s.newSession( &conn{pconn: s.conn, currentAddr: remoteAddr}, diff --git a/session.go b/session.go index adc1dd56..ec1842f2 100644 --- a/session.go +++ b/session.go @@ -276,7 +276,7 @@ var newSession = func( ActiveConnectionIDLimit: protocol.MaxActiveConnectionIDs, } if s.qlogger != nil { - s.qlogger.SentTransportParameters(time.Now(), params) + s.qlogger.SentTransportParameters(params) } cs := handshake.NewCryptoSetupServer( initialStream, @@ -391,7 +391,7 @@ var newClientSession = func( ActiveConnectionIDLimit: protocol.MaxActiveConnectionIDs, } if s.qlogger != nil { - s.qlogger.SentTransportParameters(time.Now(), params) + s.qlogger.SentTransportParameters(params) } cs, clientHelloWritten := handshake.NewCryptoSetupClient( initialStream, @@ -710,7 +710,7 @@ func (s *session) handlePacketImpl(rp *receivedPacket) bool { hdr, packetData, rest, err := wire.ParsePacket(p.data, s.srcConnIDLen) if err != nil { if s.qlogger != nil { - s.qlogger.DroppedPacket(p.rcvTime, qlog.PacketTypeNotDetermined, protocol.ByteCount(len(data)), qlog.PacketDropHeaderParseError) + s.qlogger.DroppedPacket(qlog.PacketTypeNotDetermined, protocol.ByteCount(len(data)), qlog.PacketDropHeaderParseError) } s.logger.Debugf("error parsing packet: %s", err) break @@ -771,7 +771,7 @@ func (s *session) handleSinglePacket(p *receivedPacket, hdr *wire.Header) bool / switch err { case handshake.ErrKeysDropped: if s.qlogger != nil { - s.qlogger.DroppedPacket(p.rcvTime, qlog.PacketTypeFromHeader(hdr), protocol.ByteCount(len(p.data)), qlog.PacketDropKeyUnavailable) + s.qlogger.DroppedPacket(qlog.PacketTypeFromHeader(hdr), protocol.ByteCount(len(p.data)), qlog.PacketDropKeyUnavailable) } s.logger.Debugf("Dropping %s packet (%d bytes) because we already dropped the keys.", hdr.PacketType(), len(p.data)) case handshake.ErrKeysNotYetAvailable: @@ -785,7 +785,7 @@ func (s *session) handleSinglePacket(p *receivedPacket, hdr *wire.Header) bool / // This might be a packet injected by an attacker. // Drop it. if s.qlogger != nil { - s.qlogger.DroppedPacket(p.rcvTime, qlog.PacketTypeFromHeader(hdr), protocol.ByteCount(len(p.data)), qlog.PacketDropPayloadDecryptError) + s.qlogger.DroppedPacket(qlog.PacketTypeFromHeader(hdr), protocol.ByteCount(len(p.data)), qlog.PacketDropPayloadDecryptError) } s.logger.Debugf("Dropping %s packet (%d bytes) that could not be unpacked. Error: %s", hdr.PacketType(), len(p.data), err) } @@ -833,7 +833,7 @@ func (s *session) handleRetryPacket(hdr *wire.Header, data []byte) bool /* was t s.logger.Debugf("<- Received Retry") s.logger.Debugf("Switching destination connection ID to: %s", hdr.SrcConnectionID) if s.qlogger != nil { - s.qlogger.ReceivedRetry(time.Now(), hdr) + s.qlogger.ReceivedRetry(hdr) } s.origDestConnID = s.handshakeDestConnID newDestConnID := hdr.SrcConnectionID @@ -907,7 +907,7 @@ func (s *session) handleUnpackedPacket(packet *unpackedPacket, rcvTime time.Time }) } if s.qlogger != nil { - s.qlogger.ReceivedPacket(rcvTime, packet.hdr, protocol.ByteCount(len(packet.data)), frames) + s.qlogger.ReceivedPacket(packet.hdr, protocol.ByteCount(len(packet.data)), frames) } return s.receivedPacketHandler.ReceivedPacket(packet.packetNumber, packet.encryptionLevel, rcvTime, isAckEliciting) @@ -1183,7 +1183,7 @@ func (s *session) dropEncryptionLevel(encLevel protocol.EncryptionLevel) { s.sentPacketHandler.DropPackets(encLevel) s.receivedPacketHandler.DropPackets(encLevel) if s.qlogger != nil { - s.qlogger.DroppedEncryptionLevel(time.Now(), encLevel) + s.qlogger.DroppedEncryptionLevel(encLevel) } } @@ -1198,7 +1198,7 @@ func (s *session) processTransportParameters(params *wire.TransportParameters) { s.logger.Debugf("Processed Transport Parameters: %s", params) } if s.qlogger != nil { - s.qlogger.ReceivedTransportParameters(time.Now(), params) + s.qlogger.ReceivedTransportParameters(params) } s.peerParams = params // Our local idle timeout will always be > 0. @@ -1406,7 +1406,7 @@ func (s *session) logPacketContents(now time.Time, p *packetContents) { for _, f := range p.frames { frames = append(frames, f.Frame) } - s.qlogger.SentPacket(now, p.header, p.length, p.ack, frames) + s.qlogger.SentPacket(p.header, p.length, p.ack, frames) } // quic-trace @@ -1521,14 +1521,14 @@ func (s *session) scheduleSending() { func (s *session) tryQueueingUndecryptablePacket(p *receivedPacket, hdr *wire.Header) { if len(s.undecryptablePackets)+1 > protocol.MaxUndecryptablePackets { if s.qlogger != nil { - s.qlogger.DroppedPacket(p.rcvTime, qlog.PacketTypeFromHeader(hdr), protocol.ByteCount(len(p.data)), qlog.PacketDropDOSPrevention) + s.qlogger.DroppedPacket(qlog.PacketTypeFromHeader(hdr), protocol.ByteCount(len(p.data)), qlog.PacketDropDOSPrevention) } s.logger.Infof("Dropping undecryptable packet (%d bytes). Undecryptable packet queue full.", len(p.data)) return } s.logger.Infof("Queueing packet (%d bytes) for later decryption", len(p.data)) if s.qlogger != nil { - s.qlogger.BufferedPacket(p.rcvTime, qlog.PacketTypeFromHeader(hdr)) + s.qlogger.BufferedPacket(qlog.PacketTypeFromHeader(hdr)) } s.undecryptablePackets = append(s.undecryptablePackets, p) }