mirrors/uquic
1
0
Fork 0
mirror of https://github.com/refraction-networking/uquic.git synced 2025-04-04 04:37:36 +03:00
Code Issues Projects Releases Packages Wiki Activity

Merge pull request #2434 from lucas-clemente/qlog-current-timestamp

Browse source 
use the current timestamp for logging qlog events
This commit is contained in:
Marten Seemann 2020-03-23 18:51:52 +07:00 • committed by GitHub
commit fd80fc683a
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 167 additions and 267 deletions
Download patch file Download diff file Expand all files Collapse all files

3
client.go
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()

12
internal/ackhandler/sent_packet_handler.go
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 {

18
internal/handshake/crypto_setup.go
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{}{}
}

7
internal/handshake/updatable_aead.go
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()
}

16
qlog/event.go
View file

@ -3,7 +3,6 @@ package qlog
import (
"fmt"
"net"
"sort"
"time"
"github.com/lucas-clemente/quic-go/internal/protocol"
@ -15,26 +14,11 @@ var eventFields = [4]string{"time", "category", "event", "data"}
type events []event
var _ sort.Interface = &events{}
var _ gojay.MarshalerJSONArray = events{}
func (e events) IsNil() bool { return e == nil }
func (e events) Len() int { return len(e) }
func (e events) Less(i, j int) bool {
// Don't use time.Before() here.
// Before() uses monotonic time.
// We need to make sure that the actual exported timestamp are sorted.
return e[i].Time.UnixNano() < e[j].Time.UnixNano()
}
func (e events) Swap(i, j int) { e[i], e[j] = e[j], e[i] }
func (e events) MarshalJSONArray(enc *gojay.Encoder) {
// Event timestamps are taken from multiple go routines.
// For example, the receiving go routine sets the receive time of the packet.
// Therefore, events can end up being slightly out of order.
// It turns out that Go's stable sort implementation is a lot faster in that case.
// See https://gist.github.com/marten-seemann/30251742b378318097e5400ea170c00f for benchmarking code.
sort.Stable(e)
for _, ev := range e {
enc.Array(ev)
}

19
qlog/event_test.go
View file

@ -51,23 +51,4 @@ var _ = Describe("Events", func() {
Expect(eventFields[3]).To(Equal("data"))
Expect(decoded[3].(map[string]interface{})["event"]).To(Equal("details"))
})
It("sorts events", func() {
now := time.Now()
ev := events{
event{Time: now.Add(time.Minute), eventDetails: mevent{}},
event{Time: now, eventDetails: mevent{}},
}
buf := &bytes.Buffer{}
enc := gojay.NewEncoder(buf)
Expect(enc.Encode(ev)).To(Succeed())
var decoded []interface{}
Expect(json.Unmarshal(buf.Bytes(), &decoded)).To(Succeed())
Expect(decoded).To(HaveLen(2))
t1 := time.Unix(0, int64(decoded[0].([]interface{})[0].(float64)*1e6))
t2 := time.Unix(0, int64(decoded[1].([]interface{})[0].(float64)*1e6))
Expect(t1).To(BeTemporally("~", now, time.Millisecond))
Expect(t2).To(BeTemporally("~", now.Add(time.Minute), time.Millisecond))
})
})

266
qlog/qlog.go
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)})
}

67
qlog/qlog_test.go
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

2
server.go
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},

24
session.go
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)
}