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

Merge pull request #4305 from quic-go/qlog-tracer

Browse source 
add a qlog tracer for events outside of QUIC connections
This commit is contained in:
Marten Seemann 2024-03-09 19:59:14 +09:30 • committed by GitHub
commit 5fd5d7770d
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
15 changed files with 422 additions and 131 deletions
Download patch file Download diff file Expand all files Collapse all files

2
integrationtests/self/conn_id_test.go
View file

@ -50,6 +50,7 @@ var _ = Describe("Connection ID lengths tests", func() {
ConnectionIDLength: connIDLen,
ConnectionIDGenerator: connIDGenerator,
}
addTracer(tr)
ln, err := tr.Listen(getTLSConfig(), getQuicConfig(nil))
Expect(err).ToNot(HaveOccurred())
go func() {
@ -92,6 +93,7 @@ var _ = Describe("Connection ID lengths tests", func() {
ConnectionIDLength: connIDLen,
ConnectionIDGenerator: connIDGenerator,
}
addTracer(tr)
defer tr.Close()
cl, err := tr.Dial(
context.Background(),

1
integrationtests/self/handshake_rtt_test.go
View file

@ -64,6 +64,7 @@ var _ = Describe("Handshake RTT tests", func() {
Conn: udpConn,
MaxUnvalidatedHandshakes: -1,
}
addTracer(tr)
defer tr.Close()
ln, err := tr.Listen(serverTLSConfig, serverConfig)
Expect(err).ToNot(HaveOccurred())

17
integrationtests/self/handshake_test.go
View file

@ -328,7 +328,10 @@ var _ = Describe("Handshake tests", func() {
Expect(err).ToNot(HaveOccurred())
pconn, err = net.ListenUDP("udp", laddr)
Expect(err).ToNot(HaveOccurred())
dialer = &quic.Transport{Conn: pconn, ConnectionIDLength: 4}
dialer = &quic.Transport{
Conn: pconn,
ConnectionIDLength: 4,
}
})
AfterEach(func() {
@ -431,9 +434,8 @@ var _ = Describe("Handshake tests", func() {
Expect(err).ToNot(HaveOccurred())
udpConn, err := net.ListenUDP("udp", laddr)
Expect(err).ToNot(HaveOccurred())
tr := quic.Transport{
Conn: udpConn,
}
tr := &quic.Transport{Conn: udpConn}
addTracer(tr)
defer tr.Close()
tlsConf := &tls.Config{}
done := make(chan struct{})
@ -476,10 +478,11 @@ var _ = Describe("Handshake tests", func() {
It("sends a Retry when the number of handshakes reaches MaxUnvalidatedHandshakes", func() {
const limit = 3
tr := quic.Transport{
tr := &quic.Transport{
Conn: conn,
MaxUnvalidatedHandshakes: limit,
}
addTracer(tr)
defer tr.Close()
// Block all handshakes.
@ -541,10 +544,11 @@ var _ = Describe("Handshake tests", func() {
It("rejects connections when the number of handshakes reaches MaxHandshakes", func() {
const limit = 3
tr := quic.Transport{
tr := &quic.Transport{
Conn: conn,
MaxHandshakes: limit,
}
addTracer(tr)
defer tr.Close()
// Block all handshakes.
@ -717,6 +721,7 @@ var _ = Describe("Handshake tests", func() {
Conn: udpConn,
MaxUnvalidatedHandshakes: -1,
}
addTracer(tr)
defer tr.Close()
server, err := tr.Listen(getTLSConfig(), serverConfig)
Expect(err).ToNot(HaveOccurred())

2
integrationtests/self/mitm_test.go
View file

@ -41,6 +41,7 @@ var _ = Describe("MITM test", func() {
Conn: c,
ConnectionIDLength: connIDLen,
}
addTracer(serverTransport)
if forceAddressValidation {
serverTransport.MaxUnvalidatedHandshakes = -1
}
@ -86,6 +87,7 @@ var _ = Describe("MITM test", func() {
Conn: clientUDPConn,
ConnectionIDLength: connIDLen,
}
addTracer(clientTransport)
})
Context("unsuccessful attacks", func() {

7
integrationtests/self/multiplex_test.go
View file

@ -74,6 +74,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn.Close()
tr := &quic.Transport{Conn: conn}
addTracer(tr)
done1 := make(chan struct{})
done2 := make(chan struct{})
@ -109,6 +110,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn.Close()
tr := &quic.Transport{Conn: conn}
addTracer(tr)
done1 := make(chan struct{})
done2 := make(chan struct{})
@ -139,6 +141,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn.Close()
tr := &quic.Transport{Conn: conn}
addTracer(tr)
server, err := tr.Listen(
getTLSConfig(),
getQuicConfig(nil),
@ -167,6 +170,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn1.Close()
tr1 := &quic.Transport{Conn: conn1}
addTracer(tr1)
addr2, err := net.ResolveUDPAddr("udp", "localhost:0")
Expect(err).ToNot(HaveOccurred())
@ -174,6 +178,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn2.Close()
tr2 := &quic.Transport{Conn: conn2}
addTracer(tr2)
server1, err := tr1.Listen(
getTLSConfig(),
@ -220,6 +225,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn1.Close()
tr1 := &quic.Transport{Conn: conn1}
addTracer(tr1)
addr2, err := net.ResolveUDPAddr("udp", "localhost:0")
Expect(err).ToNot(HaveOccurred())
@ -227,6 +233,7 @@ var _ = Describe("Multiplexing", func() {
Expect(err).ToNot(HaveOccurred())
defer conn2.Close()
tr2 := &quic.Transport{Conn: conn2}
addTracer(tr2)
server, err := tr1.Listen(getTLSConfig(), getQuicConfig(nil))
Expect(err).ToNot(HaveOccurred())

36
integrationtests/self/self_suite_test.go
View file

@ -86,7 +86,6 @@ var (
logBuf *syncedBuffer
versionParam string
qlogTracer func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer
enableQlog bool
version quic.Version
@ -138,9 +137,6 @@ func init() {
}
var _ = BeforeSuite(func() {
if enableQlog {
qlogTracer = tools.NewQlogger(GinkgoWriter)
}
switch versionParam {
case "1":
version = quic.Version1
@ -175,28 +171,48 @@ func getQuicConfig(conf *quic.Config) *quic.Config {
} else {
conf = conf.Clone()
}
if enableQlog {
if !enableQlog {
return conf
}
if conf.Tracer == nil {
conf.Tracer = func(ctx context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
return logging.NewMultiplexedConnectionTracer(
qlogTracer(ctx, p, connID),
tools.NewQlogConnectionTracer(GinkgoWriter)(ctx, p, connID),
// multiplex it with an empty tracer to check that we're correctly ignoring unset callbacks everywhere
&logging.ConnectionTracer{},
)
}
} else if qlogTracer != nil {
return conf
}
origTracer := conf.Tracer
conf.Tracer = func(ctx context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
return logging.NewMultiplexedConnectionTracer(
qlogTracer(ctx, p, connID),
tools.NewQlogConnectionTracer(GinkgoWriter)(ctx, p, connID),
origTracer(ctx, p, connID),
)
}
}
}
return conf
}
func addTracer(tr *quic.Transport) {
if !enableQlog {
return
}
if tr.Tracer == nil {
tr.Tracer = logging.NewMultiplexedTracer(
tools.QlogTracer(GinkgoWriter),
// multiplex it with an empty tracer to check that we're correctly ignoring unset callbacks everywhere
&logging.Tracer{},
)
return
}
origTracer := tr.Tracer
tr.Tracer = logging.NewMultiplexedTracer(
tools.QlogTracer(GinkgoWriter),
origTracer,
)
}
var _ = BeforeEach(func() {
log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds)

2
integrationtests/self/zero_rtt_test.go
View file

@ -175,6 +175,7 @@ var _ = Describe("0-RTT", func() {
Conn: udpConn,
ConnectionIDLength: connIDLen,
}
addTracer(tr)
defer tr.Close()
conn, err = tr.DialEarly(
context.Background(),
@ -463,6 +464,7 @@ var _ = Describe("0-RTT", func() {
Conn: udpConn,
MaxUnvalidatedHandshakes: -1,
}
addTracer(tr)
defer tr.Close()
ln, err := tr.ListenEarly(
tlsConf,

21
integrationtests/tools/qlog.go
View file

@ -7,6 +7,7 @@ import (
"io"
"log"
"os"
"time"
"github.com/quic-go/quic-go"
"github.com/quic-go/quic-go/internal/utils"
@ -14,13 +15,21 @@ import (
"github.com/quic-go/quic-go/qlog"
)
func NewQlogger(logger io.Writer) func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer {
return func(_ context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
role := "server"
if p == logging.PerspectiveClient {
role = "client"
func QlogTracer(logger io.Writer) *logging.Tracer {
filename := fmt.Sprintf("log_%s_transport.qlog", time.Now().Format("2006-01-02T15:04:05"))
fmt.Fprintf(logger, "Creating %s.\n", filename)
f, err := os.Create(filename)
if err != nil {
log.Fatalf("failed to create qlog file: %s", err)
return nil
}
filename := fmt.Sprintf("log_%s_%s.qlog", connID, role)
bw := bufio.NewWriter(f)
return qlog.NewTracer(utils.NewBufferedWriteCloser(bw, f))
}
func NewQlogConnectionTracer(logger io.Writer) func(context.Context, logging.Perspective, quic.ConnectionID) *logging.ConnectionTracer {
return func(_ context.Context, p logging.Perspective, connID quic.ConnectionID) *logging.ConnectionTracer {
filename := fmt.Sprintf("log_%s_%s.qlog", connID, p.String())
fmt.Fprintf(logger, "Creating %s.\n", filename)
f, err := os.Create(filename)
if err != nil {

2
integrationtests/versionnegotiation/versionnegotiation_suite_test.go
View file

@ -65,7 +65,7 @@ func maybeAddQLOGTracer(c *quic.Config) *quic.Config {
if !enableQlog {
return c
}
qlogger := tools.NewQlogger(GinkgoWriter)
qlogger := tools.NewQlogConnectionTracer(GinkgoWriter)
if c.Tracer == nil {
c.Tracer = qlogger
} else if qlogger != nil {

6
qlog/connection_tracer.go
View file

@ -23,10 +23,10 @@ type connectionTracer struct {
// NewConnectionTracer creates a new tracer to record a qlog for a connection.
func NewConnectionTracer(w io.WriteCloser, p logging.Perspective, odcid protocol.ConnectionID) *logging.ConnectionTracer {
tr := &trace{
VantagePoint: vantagePoint{Type: p},
VantagePoint: vantagePoint{Type: p.String()},
CommonFields: commonFields{
ODCID: odcid,
GroupID: odcid,
ODCID: &odcid,
GroupID: &odcid,
ReferenceTime: time.Now(),
},
}

204
qlog/connection_tracer_test.go
View file

@ -32,6 +32,44 @@ type entry struct {
Event map[string]interface{}
}
func exportAndParse(buf *bytes.Buffer) []entry {
m := make(map[string]interface{})
line, err := buf.ReadBytes('\n')
Expect(err).ToNot(HaveOccurred())
Expect(json.Unmarshal(line, &m)).To(Succeed())
Expect(m).To(HaveKey("trace"))
var entries []entry
trace := m["trace"].(map[string]interface{})
Expect(trace).To(HaveKey("common_fields"))
commonFields := trace["common_fields"].(map[string]interface{})
Expect(commonFields).To(HaveKey("reference_time"))
referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
Expect(trace).ToNot(HaveKey("events"))
for buf.Len() > 0 {
line, err := buf.ReadBytes('\n')
Expect(err).ToNot(HaveOccurred())
ev := make(map[string]interface{})
Expect(json.Unmarshal(line, &ev)).To(Succeed())
Expect(ev).To(HaveLen(3))
Expect(ev).To(HaveKey("time"))
Expect(ev).To(HaveKey("name"))
Expect(ev).To(HaveKey("data"))
entries = append(entries, entry{
Time: referenceTime.Add(time.Duration(ev["time"].(float64)*1e6) * time.Nanosecond),
Name: ev["name"].(string),
Event: ev["data"].(map[string]interface{}),
})
}
return entries
}
func exportAndParseSingle(buf *bytes.Buffer) entry {
entries := exportAndParse(buf)
Expect(entries).To(HaveLen(1))
return entries[0]
}
var _ = Describe("Tracing", func() {
var (
tracer *logging.ConnectionTracer
@ -70,46 +108,6 @@ var _ = Describe("Tracing", func() {
})
Context("Events", func() {
exportAndParse := func() []entry {
tracer.Close()
m := make(map[string]interface{})
line, err := buf.ReadBytes('\n')
Expect(err).ToNot(HaveOccurred())
Expect(json.Unmarshal(line, &m)).To(Succeed())
Expect(m).To(HaveKey("trace"))
var entries []entry
trace := m["trace"].(map[string]interface{})
Expect(trace).To(HaveKey("common_fields"))
commonFields := trace["common_fields"].(map[string]interface{})
Expect(commonFields).To(HaveKey("reference_time"))
referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
Expect(trace).ToNot(HaveKey("events"))
for buf.Len() > 0 {
line, err := buf.ReadBytes('\n')
Expect(err).ToNot(HaveOccurred())
ev := make(map[string]interface{})
Expect(json.Unmarshal(line, &ev)).To(Succeed())
Expect(ev).To(HaveLen(3))
Expect(ev).To(HaveKey("time"))
Expect(ev).To(HaveKey("name"))
Expect(ev).To(HaveKey("data"))
entries = append(entries, entry{
Time: referenceTime.Add(time.Duration(ev["time"].(float64)*1e6) * time.Nanosecond),
Name: ev["name"].(string),
Event: ev["data"].(map[string]interface{}),
})
}
return entries
}
exportAndParseSingle := func() entry {
entries := exportAndParse()
Expect(entries).To(HaveLen(1))
return entries[0]
}
It("records connection starts", func() {
tracer.StartedConnection(
&net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42},
@ -117,7 +115,8 @@ var _ = Describe("Tracing", func() {
protocol.ParseConnectionID([]byte{1, 2, 3, 4}),
protocol.ParseConnectionID([]byte{5, 6, 7, 8}),
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_started"))
ev := entry.Event
@ -132,7 +131,8 @@ var _ = Describe("Tracing", func() {
It("records the version, if no version negotiation happened", func() {
tracer.NegotiatedVersion(0x1337, nil, nil)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:version_information"))
ev := entry.Event
@ -142,7 +142,8 @@ var _ = Describe("Tracing", func() {
It("records the version, if version negotiation happened", func() {
tracer.NegotiatedVersion(0x1337, []logging.VersionNumber{1, 2, 3}, []logging.VersionNumber{4, 5, 6})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:version_information"))
ev := entry.Event
@ -156,7 +157,8 @@ var _ = Describe("Tracing", func() {
It("records idle timeouts", func() {
tracer.ClosedConnection(&quic.IdleTimeoutError{})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_closed"))
ev := entry.Event
@ -167,7 +169,8 @@ var _ = Describe("Tracing", func() {
It("records handshake timeouts", func() {
tracer.ClosedConnection(&quic.HandshakeTimeoutError{})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_closed"))
ev := entry.Event
@ -180,7 +183,8 @@ var _ = Describe("Tracing", func() {
tracer.ClosedConnection(&quic.StatelessResetError{
Token: protocol.StatelessResetToken{0x00, 0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff},
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_closed"))
ev := entry.Event
@ -192,7 +196,8 @@ var _ = Describe("Tracing", func() {
It("records connection closing due to version negotiation failure", func() {
tracer.ClosedConnection(&quic.VersionNegotiationError{})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_closed"))
ev := entry.Event
@ -206,7 +211,8 @@ var _ = Describe("Tracing", func() {
ErrorCode: 1337,
ErrorMessage: "foobar",
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_closed"))
ev := entry.Event
@ -221,7 +227,8 @@ var _ = Describe("Tracing", func() {
ErrorCode: qerr.AEADLimitReached,
ErrorMessage: "foobar",
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:connection_closed"))
ev := entry.Event
@ -252,7 +259,8 @@ var _ = Describe("Tracing", func() {
ActiveConnectionIDLimit: 7,
MaxDatagramFrameSize: protocol.InvalidByteCount,
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_set"))
ev := entry.Event
@ -280,7 +288,8 @@ var _ = Describe("Tracing", func() {
OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}),
ActiveConnectionIDLimit: 7,
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_set"))
ev := entry.Event
@ -291,7 +300,8 @@ var _ = Describe("Tracing", func() {
tracer.SentTransportParameters(&logging.TransportParameters{
StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00},
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_set"))
ev := entry.Event
@ -308,7 +318,8 @@ var _ = Describe("Tracing", func() {
StatelessResetToken: protocol.StatelessResetToken{15, 14, 13, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0},
},
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_set"))
ev := entry.Event
@ -327,7 +338,8 @@ var _ = Describe("Tracing", func() {
tracer.SentTransportParameters(&logging.TransportParameters{
MaxDatagramFrameSize: 1337,
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_set"))
ev := entry.Event
@ -336,7 +348,8 @@ var _ = Describe("Tracing", func() {
It("records received transport parameters", func() {
tracer.ReceivedTransportParameters(&logging.TransportParameters{})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_set"))
ev := entry.Event
@ -352,7 +365,8 @@ var _ = Describe("Tracing", func() {
InitialMaxData: 400,
MaxIdleTimeout: 123 * time.Millisecond,
})
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:parameters_restored"))
ev := entry.Event
@ -388,7 +402,8 @@ var _ = Describe("Tracing", func() {
&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
},
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_sent"))
ev := entry.Event
@ -420,7 +435,8 @@ var _ = Describe("Tracing", func() {
&logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}},
[]logging.Frame{&logging.MaxDataFrame{MaximumData: 987}},
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
ev := entry.Event
raw := ev["raw"].(map[string]interface{})
Expect(raw).To(HaveKeyWithValue("length", float64(123)))
@ -457,7 +473,8 @@ var _ = Describe("Tracing", func() {
&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
},
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_received"))
ev := entry.Event
@ -494,7 +511,8 @@ var _ = Describe("Tracing", func() {
&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
},
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_received"))
ev := entry.Event
@ -522,7 +540,8 @@ var _ = Describe("Tracing", func() {
Version: protocol.Version1,
},
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_received"))
ev := entry.Event
@ -546,7 +565,8 @@ var _ = Describe("Tracing", func() {
protocol.ArbitraryLenConnectionID{4, 3, 2, 1},
[]protocol.Version{0xdeadbeef, 0xdecafbad},
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_received"))
ev := entry.Event
@ -564,7 +584,8 @@ var _ = Describe("Tracing", func() {
It("records buffered packets", func() {
tracer.BufferedPacket(logging.PacketTypeHandshake, 1337)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_buffered"))
ev := entry.Event
@ -579,7 +600,8 @@ var _ = Describe("Tracing", func() {
It("records dropped packets", func() {
tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_dropped"))
ev := entry.Event
@ -594,7 +616,8 @@ var _ = Describe("Tracing", func() {
It("records dropped packets with a packet number", func() {
tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_dropped"))
ev := entry.Event
@ -626,7 +649,8 @@ var _ = Describe("Tracing", func() {
1234,
42,
)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:metrics_updated"))
ev := entry.Event
@ -668,7 +692,8 @@ var _ = Describe("Tracing", func() {
12345, // changed
42,
)
entries := exportAndParse()
tracer.Close()
entries := exportAndParse(buf)
Expect(entries).To(HaveLen(2))
Expect(entries[0].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entries[0].Name).To(Equal("recovery:metrics_updated"))
@ -685,7 +710,8 @@ var _ = Describe("Tracing", func() {
It("records lost packets", func() {
tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:packet_lost"))
ev := entry.Event
@ -699,7 +725,8 @@ var _ = Describe("Tracing", func() {
It("records congestion state updates", func() {
tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:congestion_state_updated"))
ev := entry.Event
@ -708,7 +735,8 @@ var _ = Describe("Tracing", func() {
It("records PTO changes", func() {
tracer.UpdatedPTOCount(42)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:metrics_updated"))
Expect(entry.Event).To(HaveKeyWithValue("pto_count", float64(42)))
@ -716,7 +744,8 @@ var _ = Describe("Tracing", func() {
It("records TLS key updates", func() {
tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("security:key_updated"))
ev := entry.Event
@ -729,7 +758,8 @@ var _ = Describe("Tracing", func() {
It("records TLS key updates, for 1-RTT keys", func() {
tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("security:key_updated"))
ev := entry.Event
@ -742,7 +772,8 @@ var _ = Describe("Tracing", func() {
It("records QUIC key updates", func() {
tracer.UpdatedKey(1337, true)
entries := exportAndParse()
tracer.Close()
entries := exportAndParse(buf)
Expect(entries).To(HaveLen(2))
var keyTypes []string
for _, entry := range entries {
@ -760,7 +791,8 @@ var _ = Describe("Tracing", func() {
It("records dropped encryption levels", func() {
tracer.DroppedEncryptionLevel(protocol.EncryptionInitial)
entries := exportAndParse()
tracer.Close()
entries := exportAndParse(buf)
Expect(entries).To(HaveLen(2))
var keyTypes []string
for _, entry := range entries {
@ -777,7 +809,8 @@ var _ = Describe("Tracing", func() {
It("records dropped 0-RTT keys", func() {
tracer.DroppedEncryptionLevel(protocol.Encryption0RTT)
entries := exportAndParse()
tracer.Close()
entries := exportAndParse(buf)
Expect(entries).To(HaveLen(1))
entry := entries[0]
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
@ -789,7 +822,8 @@ var _ = Describe("Tracing", func() {
It("records dropped keys", func() {
tracer.DroppedKey(42)
entries := exportAndParse()
tracer.Close()
entries := exportAndParse(buf)
Expect(entries).To(HaveLen(2))
var keyTypes []string
for _, entry := range entries {
@ -808,7 +842,8 @@ var _ = Describe("Tracing", func() {
It("records when the timer is set", func() {
timeout := time.Now().Add(137 * time.Millisecond)
tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:loss_timer_updated"))
ev := entry.Event
@ -823,7 +858,8 @@ var _ = Describe("Tracing", func() {
It("records when the loss timer expires", func() {
tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:loss_timer_updated"))
ev := entry.Event
@ -835,7 +871,8 @@ var _ = Describe("Tracing", func() {
It("records when the timer is canceled", func() {
tracer.LossTimerCanceled()
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:loss_timer_updated"))
ev := entry.Event
@ -845,7 +882,8 @@ var _ = Describe("Tracing", func() {
It("records an ECN state transition, without a trigger", func() {
tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:ecn_state_updated"))
ev := entry.Event
@ -855,7 +893,8 @@ var _ = Describe("Tracing", func() {
It("records an ECN state transition, with a trigger", func() {
tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts)
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("recovery:ecn_state_updated"))
ev := entry.Event
@ -866,7 +905,8 @@ var _ = Describe("Tracing", func() {
It("records a generic event", func() {
tracer.Debug("foo", "bar")
entry := exportAndParseSingle()
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:foo"))
ev := entry.Event

14
qlog/event.go
View file

@ -233,6 +233,20 @@ func (e eventVersionNegotiationReceived) MarshalJSONObject(enc *gojay.Encoder) {
enc.ArrayKey("supported_versions", versions(e.SupportedVersions))
}
type eventVersionNegotiationSent struct {
Header packetHeaderVersionNegotiation
SupportedVersions []versionNumber
}
func (e eventVersionNegotiationSent) Category() category { return categoryTransport }
func (e eventVersionNegotiationSent) Name() string { return "packet_sent" }
func (e eventVersionNegotiationSent) IsNil() bool { return false }
func (e eventVersionNegotiationSent) MarshalJSONObject(enc *gojay.Encoder) {
enc.ObjectKey("header", e.Header)
enc.ArrayKey("supported_versions", versions(e.SupportedVersions))
}
type eventPacketBuffered struct {
PacketType logging.PacketType
PacketSize protocol.ByteCount

16
qlog/trace.go
View file

@ -4,7 +4,6 @@ import (
"runtime/debug"
"time"
"github.com/quic-go/quic-go/internal/protocol"
"github.com/quic-go/quic-go/logging"
"github.com/francoispqt/gojay"
@ -62,30 +61,27 @@ func (c configuration) MarshalJSONObject(enc *gojay.Encoder) {
type vantagePoint struct {
Name string
Type protocol.Perspective
Type string
}
func (p vantagePoint) IsNil() bool { return false }
func (p vantagePoint) MarshalJSONObject(enc *gojay.Encoder) {
enc.StringKeyOmitEmpty("name", p.Name)
switch p.Type {
case protocol.PerspectiveClient:
enc.StringKey("type", "client")
case protocol.PerspectiveServer:
enc.StringKey("type", "server")
}
enc.StringKeyOmitEmpty("type", p.Type)
}
type commonFields struct {
ODCID logging.ConnectionID
GroupID logging.ConnectionID
ODCID *logging.ConnectionID
GroupID *logging.ConnectionID
ProtocolType string
ReferenceTime time.Time
}
func (f commonFields) MarshalJSONObject(enc *gojay.Encoder) {
if f.ODCID != nil {
enc.StringKey("ODCID", f.ODCID.String())
enc.StringKey("group_id", f.ODCID.String())
}
enc.StringKeyOmitEmpty("protocol_type", f.ProtocolType)
enc.Float64Key("reference_time", float64(f.ReferenceTime.UnixNano())/1e6)
enc.StringKey("time_format", "relative")

60
qlog/tracer.go Normal file
View file

@ -0,0 +1,60 @@
package qlog
import (
"io"
"net"
"time"
"github.com/quic-go/quic-go/internal/protocol"
"github.com/quic-go/quic-go/logging"
)
func NewTracer(w io.WriteCloser) *logging.Tracer {
tr := &trace{
VantagePoint: vantagePoint{Type: "transport"},
CommonFields: commonFields{ReferenceTime: time.Now()},
}
wr := *newWriter(w, tr)
go wr.Run()
return &logging.Tracer{
SentPacket: func(_ net.Addr, hdr *logging.Header, size logging.ByteCount, frames []logging.Frame) {
fs := make([]frame, 0, len(frames))
for _, f := range frames {
fs = append(fs, frame{Frame: f})
}
wr.RecordEvent(time.Now(), &eventPacketSent{
Header: transformHeader(hdr),
Length: size,
Frames: fs,
})
},
SentVersionNegotiationPacket: func(_ net.Addr, dest, src logging.ArbitraryLenConnectionID, versions []logging.VersionNumber) {
ver := make([]versionNumber, len(versions))
for i, v := range versions {
ver[i] = versionNumber(v)
}
wr.RecordEvent(time.Now(), &eventVersionNegotiationSent{
Header: packetHeaderVersionNegotiation{
SrcConnectionID: src,
DestConnectionID: dest,
},
SupportedVersions: ver,
})
},
DroppedPacket: func(addr net.Addr, p logging.PacketType, count logging.ByteCount, reason logging.PacketDropReason) {
wr.RecordEvent(time.Now(), eventPacketDropped{
PacketType: p,
PacketNumber: protocol.InvalidPacketNumber,
PacketSize: count,
Trigger: packetDropReason(reason),
})
},
Debug: func(name, msg string) {
wr.RecordEvent(time.Now(), &eventGeneric{
name: name,
msg: msg,
})
},
Close: func() { wr.Close() },
}
}

137
qlog/tracer_test.go Normal file
View file

@ -0,0 +1,137 @@
package qlog
import (
"bytes"
"encoding/json"
"net"
"time"
"github.com/quic-go/quic-go/internal/protocol"
"github.com/quic-go/quic-go/logging"
. "github.com/onsi/ginkgo/v2"
. "github.com/onsi/gomega"
)
var _ = Describe("Tracing", func() {
var (
tracer *logging.Tracer
buf *bytes.Buffer
)
BeforeEach(func() {
buf = &bytes.Buffer{}
tracer = NewTracer(nopWriteCloser(buf))
})
It("exports a trace that has the right metadata", func() {
tracer.Close()
m := make(map[string]interface{})
Expect(json.Unmarshal(buf.Bytes(), &m)).To(Succeed())
Expect(m).To(HaveKeyWithValue("qlog_version", "draft-02"))
Expect(m).To(HaveKey("title"))
Expect(m).To(HaveKey("trace"))
trace := m["trace"].(map[string]interface{})
Expect(trace).To(HaveKey(("common_fields")))
commonFields := trace["common_fields"].(map[string]interface{})
Expect(commonFields).ToNot(HaveKey("ODCID"))
Expect(commonFields).ToNot(HaveKey("group_id"))
Expect(commonFields).To(HaveKey("reference_time"))
referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
Expect(referenceTime).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(commonFields).To(HaveKeyWithValue("time_format", "relative"))
Expect(trace).To(HaveKey("vantage_point"))
vantagePoint := trace["vantage_point"].(map[string]interface{})
Expect(vantagePoint).To(HaveKeyWithValue("type", "transport"))
})
Context("Events", func() {
It("records a sent long header packet, without an ACK", func() {
tracer.SentPacket(
nil,
&logging.Header{
Type: protocol.PacketTypeHandshake,
DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}),
SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}),
Length: 1337,
Version: protocol.Version1,
},
1234,
[]logging.Frame{
&logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987},
&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
},
)
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_sent"))
ev := entry.Event
Expect(ev).To(HaveKey("raw"))
raw := ev["raw"].(map[string]interface{})
Expect(raw).To(HaveKeyWithValue("length", float64(1234)))
Expect(ev).To(HaveKey("header"))
hdr := ev["header"].(map[string]interface{})
Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake"))
Expect(hdr).To(HaveKeyWithValue("scid", "04030201"))
Expect(ev).To(HaveKey("frames"))
frames := ev["frames"].([]interface{})
Expect(frames).To(HaveLen(2))
Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_stream_data"))
Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream"))
})
It("records sending of a Version Negotiation packet", func() {
tracer.SentVersionNegotiationPacket(
nil,
protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8},
protocol.ArbitraryLenConnectionID{4, 3, 2, 1},
[]protocol.Version{0xdeadbeef, 0xdecafbad},
)
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_sent"))
ev := entry.Event
Expect(ev).To(HaveKey("header"))
Expect(ev).ToNot(HaveKey("frames"))
Expect(ev).To(HaveKey("supported_versions"))
Expect(ev["supported_versions"].([]interface{})).To(Equal([]interface{}{"deadbeef", "decafbad"}))
header := ev["header"]
Expect(header).To(HaveKeyWithValue("packet_type", "version_negotiation"))
Expect(header).ToNot(HaveKey("packet_number"))
Expect(header).ToNot(HaveKey("version"))
Expect(header).To(HaveKeyWithValue("dcid", "0102030405060708"))
Expect(header).To(HaveKeyWithValue("scid", "04030201"))
})
It("records dropped packets", func() {
addr := net.UDPAddr{IP: net.IPv4(1, 2, 3, 4), Port: 1234}
tracer.DroppedPacket(&addr, logging.PacketTypeInitial, 1337, logging.PacketDropPayloadDecryptError)
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:packet_dropped"))
ev := entry.Event
Expect(ev).To(HaveKey("raw"))
Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337)))
Expect(ev).To(HaveKey("header"))
hdr := ev["header"].(map[string]interface{})
Expect(hdr).To(HaveLen(1))
Expect(hdr).To(HaveKeyWithValue("packet_type", "initial"))
Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error"))
})
It("records a generic event", func() {
tracer.Debug("foo", "bar")
tracer.Close()
entry := exportAndParseSingle(buf)
Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
Expect(entry.Name).To(Equal("transport:foo"))
ev := entry.Event
Expect(ev).To(HaveLen(1))
Expect(ev).To(HaveKeyWithValue("details", "bar"))
})
})
})