use the current timestamp of every event in qlog

This commit is contained in:
Marten Seemann 2020-03-22 13:00:26 +07:00
parent afc34127b0
commit ef901e3435
8 changed files with 167 additions and 232 deletions

View file

@ -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()

View file

@ -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 {

View file

@ -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{}{}
}

View file

@ -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()
}

View file

@ -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)})
}

View file

@ -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

View file

@ -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},

View file

@ -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)
}