package qlog import ( "bytes" "io" "net" "net/netip" "testing" "time" "github.com/quic-go/quic-go" "github.com/quic-go/quic-go/internal/protocol" "github.com/quic-go/quic-go/internal/qerr" "github.com/quic-go/quic-go/internal/utils" "github.com/quic-go/quic-go/logging" "github.com/stretchr/testify/require" ) type nopWriteCloserImpl struct{ io.Writer } func (nopWriteCloserImpl) Close() error { return nil } func nopWriteCloser(w io.Writer) io.WriteCloser { return &nopWriteCloserImpl{Writer: w} } func newConnectionTracer() (*logging.ConnectionTracer, *bytes.Buffer) { buf := &bytes.Buffer{} tracer := NewConnectionTracer( nopWriteCloser(buf), logging.PerspectiveServer, protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), ) return tracer, buf } func TestConnectionTraceMetadata(t *testing.T) { tracer, buf := newConnectionTracer() tracer.Close() m := make(map[string]interface{}) require.NoError(t, unmarshal(buf.Bytes(), &m)) require.Equal(t, "0.3", m["qlog_version"]) require.Contains(t, m, "title") require.Contains(t, m, "trace") trace := m["trace"].(map[string]interface{}) require.Contains(t, trace, "common_fields") commonFields := trace["common_fields"].(map[string]interface{}) require.Equal(t, "deadbeef", commonFields["ODCID"]) require.Equal(t, "deadbeef", commonFields["group_id"]) require.Contains(t, commonFields, "reference_time") referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6)) require.WithinDuration(t, time.Now(), referenceTime, scaleDuration(10*time.Millisecond)) require.Equal(t, "relative", commonFields["time_format"]) require.Contains(t, trace, "vantage_point") vantagePoint := trace["vantage_point"].(map[string]interface{}) require.Equal(t, "server", vantagePoint["type"]) } func TestConnectionStarts(t *testing.T) { tracer, buf := newConnectionTracer() tracer.StartedConnection( &net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42}, &net.UDPAddr{IP: net.IPv4(192, 168, 12, 34), Port: 24}, protocol.ParseConnectionID([]byte{1, 2, 3, 4}), protocol.ParseConnectionID([]byte{5, 6, 7, 8}), ) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_started", entry.Name) ev := entry.Event require.Equal(t, "ipv4", ev["ip_version"]) require.Equal(t, "192.168.13.37", ev["src_ip"]) require.Equal(t, float64(42), ev["src_port"]) require.Equal(t, "192.168.12.34", ev["dst_ip"]) require.Equal(t, float64(24), ev["dst_port"]) require.Equal(t, "01020304", ev["src_cid"]) require.Equal(t, "05060708", ev["dst_cid"]) } func TestVersionNegotiation(t *testing.T) { tracer, buf := newConnectionTracer() tracer.NegotiatedVersion(0x1337, nil, nil) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:version_information", entry.Name) ev := entry.Event require.Len(t, ev, 1) require.Equal(t, "1337", ev["chosen_version"]) } func TestVersionNegotiationWithPriorAttempts(t *testing.T) { tracer, buf := newConnectionTracer() tracer.NegotiatedVersion(0x1337, []logging.Version{1, 2, 3}, []logging.Version{4, 5, 6}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:version_information", entry.Name) ev := entry.Event require.Len(t, ev, 3) require.Equal(t, "1337", ev["chosen_version"]) require.Equal(t, []interface{}{"1", "2", "3"}, ev["client_versions"]) require.Equal(t, []interface{}{"4", "5", "6"}, ev["server_versions"]) } func TestIdleTimeouts(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ClosedConnection(&quic.IdleTimeoutError{}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_closed", entry.Name) ev := entry.Event require.Len(t, ev, 2) require.Equal(t, "local", ev["owner"]) require.Equal(t, "idle_timeout", ev["trigger"]) } func TestHandshakeTimeouts(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ClosedConnection(&quic.HandshakeTimeoutError{}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_closed", entry.Name) ev := entry.Event require.Len(t, ev, 2) require.Equal(t, "local", ev["owner"]) require.Equal(t, "handshake_timeout", ev["trigger"]) } func TestReceivedStatelessResetPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ClosedConnection(&quic.StatelessResetError{}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_closed", entry.Name) ev := entry.Event require.Len(t, ev, 2) require.Equal(t, "remote", ev["owner"]) require.Equal(t, "stateless_reset", ev["trigger"]) } func TestVersionNegotiationFailure(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ClosedConnection(&quic.VersionNegotiationError{}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_closed", entry.Name) ev := entry.Event require.Len(t, ev, 1) require.Equal(t, "version_mismatch", ev["trigger"]) } func TestApplicationErrors(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ClosedConnection(&quic.ApplicationError{ Remote: true, ErrorCode: 1337, ErrorMessage: "foobar", }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_closed", entry.Name) ev := entry.Event require.Len(t, ev, 3) require.Equal(t, "remote", ev["owner"]) require.Equal(t, float64(1337), ev["application_code"]) require.Equal(t, "foobar", ev["reason"]) } func TestTransportErrors(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ClosedConnection(&quic.TransportError{ ErrorCode: qerr.AEADLimitReached, ErrorMessage: "foobar", }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:connection_closed", entry.Name) ev := entry.Event require.Len(t, ev, 3) require.Equal(t, "local", ev["owner"]) require.Equal(t, "aead_limit_reached", ev["connection_code"]) require.Equal(t, "foobar", ev["reason"]) } func TestSentTransportParameters(t *testing.T) { rcid := protocol.ParseConnectionID([]byte{0xde, 0xca, 0xfb, 0xad}) tracer, buf := newConnectionTracer() tracer.SentTransportParameters(&logging.TransportParameters{ InitialMaxStreamDataBidiLocal: 1000, InitialMaxStreamDataBidiRemote: 2000, InitialMaxStreamDataUni: 3000, InitialMaxData: 4000, MaxBidiStreamNum: 10, MaxUniStreamNum: 20, MaxAckDelay: 123 * time.Millisecond, AckDelayExponent: 12, DisableActiveMigration: true, MaxUDPPayloadSize: 1234, MaxIdleTimeout: 321 * time.Millisecond, StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), InitialSourceConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), RetrySourceConnectionID: &rcid, ActiveConnectionIDLimit: 7, MaxDatagramFrameSize: protocol.InvalidByteCount, }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_set", entry.Name) ev := entry.Event require.Equal(t, "local", ev["owner"]) require.Equal(t, "deadc0de", ev["original_destination_connection_id"]) require.Equal(t, "deadbeef", ev["initial_source_connection_id"]) require.Equal(t, "decafbad", ev["retry_source_connection_id"]) require.Equal(t, "112233445566778899aabbccddeeff00", ev["stateless_reset_token"]) require.Equal(t, float64(321), ev["max_idle_timeout"]) require.Equal(t, float64(1234), ev["max_udp_payload_size"]) require.Equal(t, float64(12), ev["ack_delay_exponent"]) require.Equal(t, float64(7), ev["active_connection_id_limit"]) require.Equal(t, float64(4000), ev["initial_max_data"]) require.Equal(t, float64(1000), ev["initial_max_stream_data_bidi_local"]) require.Equal(t, float64(2000), ev["initial_max_stream_data_bidi_remote"]) require.Equal(t, float64(3000), ev["initial_max_stream_data_uni"]) require.Equal(t, float64(10), ev["initial_max_streams_bidi"]) require.Equal(t, float64(20), ev["initial_max_streams_uni"]) require.NotContains(t, ev, "preferred_address") require.NotContains(t, ev, "max_datagram_frame_size") } func TestServerTransportParametersWithoutStatelessResetToken(t *testing.T) { tracer, buf := newConnectionTracer() tracer.SentTransportParameters(&logging.TransportParameters{ OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), ActiveConnectionIDLimit: 7, }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_set", entry.Name) ev := entry.Event require.NotContains(t, ev, "stateless_reset_token") } func TestTransportParametersWithoutRetrySourceConnectionID(t *testing.T) { tracer, buf := newConnectionTracer() tracer.SentTransportParameters(&logging.TransportParameters{ StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_set", entry.Name) ev := entry.Event require.Equal(t, "local", ev["owner"]) require.NotContains(t, ev, "retry_source_connection_id") } func TestTransportParametersWithPreferredAddress(t *testing.T) { t.Run("IPv4 and IPv6", func(t *testing.T) { testTransportParametersWithPreferredAddress(t, true, true) }) t.Run("IPv4 only", func(t *testing.T) { testTransportParametersWithPreferredAddress(t, true, false) }) t.Run("IPv6 only", func(t *testing.T) { testTransportParametersWithPreferredAddress(t, false, true) }) } func testTransportParametersWithPreferredAddress(t *testing.T, hasIPv4, hasIPv6 bool) { addr4 := netip.AddrPortFrom(netip.AddrFrom4([4]byte{12, 34, 56, 78}), 123) addr6 := netip.AddrPortFrom(netip.AddrFrom16([16]byte{1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16}), 456) tracer, buf := newConnectionTracer() preferredAddress := &logging.PreferredAddress{ ConnectionID: protocol.ParseConnectionID([]byte{8, 7, 6, 5, 4, 3, 2, 1}), StatelessResetToken: protocol.StatelessResetToken{15, 14, 13, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0}, } if hasIPv4 { preferredAddress.IPv4 = addr4 } if hasIPv6 { preferredAddress.IPv6 = addr6 } tracer.SentTransportParameters(&logging.TransportParameters{PreferredAddress: preferredAddress}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_set", entry.Name) ev := entry.Event require.Equal(t, "local", ev["owner"]) require.Contains(t, ev, "preferred_address") pa := ev["preferred_address"].(map[string]interface{}) if hasIPv4 { require.Equal(t, "12.34.56.78", pa["ip_v4"]) require.Equal(t, float64(123), pa["port_v4"]) } else { require.NotContains(t, pa, "ip_v4") require.NotContains(t, pa, "port_v4") } if hasIPv6 { require.Equal(t, "102:304:506:708:90a:b0c:d0e:f10", pa["ip_v6"]) require.Equal(t, float64(456), pa["port_v6"]) } else { require.NotContains(t, pa, "ip_v6") require.NotContains(t, pa, "port_v6") } require.Equal(t, "0807060504030201", pa["connection_id"]) require.Equal(t, "0f0e0d0c0b0a09080706050403020100", pa["stateless_reset_token"]) } func TestTransportParametersWithDatagramExtension(t *testing.T) { tracer, buf := newConnectionTracer() tracer.SentTransportParameters(&logging.TransportParameters{ MaxDatagramFrameSize: 1337, }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_set", entry.Name) ev := entry.Event require.Equal(t, float64(1337), ev["max_datagram_frame_size"]) } func TestReceivedTransportParameters(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ReceivedTransportParameters(&logging.TransportParameters{}) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_set", entry.Name) ev := entry.Event require.Equal(t, "remote", ev["owner"]) require.NotContains(t, ev, "original_destination_connection_id") } func TestRestoredTransportParameters(t *testing.T) { tracer, buf := newConnectionTracer() tracer.RestoredTransportParameters(&logging.TransportParameters{ InitialMaxStreamDataBidiLocal: 100, InitialMaxStreamDataBidiRemote: 200, InitialMaxStreamDataUni: 300, InitialMaxData: 400, MaxIdleTimeout: 123 * time.Millisecond, }) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:parameters_restored", entry.Name) ev := entry.Event require.NotContains(t, ev, "owner") require.NotContains(t, ev, "original_destination_connection_id") require.NotContains(t, ev, "stateless_reset_token") require.NotContains(t, ev, "retry_source_connection_id") require.NotContains(t, ev, "initial_source_connection_id") require.Equal(t, float64(123), ev["max_idle_timeout"]) require.Equal(t, float64(400), ev["initial_max_data"]) require.Equal(t, float64(100), ev["initial_max_stream_data_bidi_local"]) require.Equal(t, float64(200), ev["initial_max_stream_data_bidi_remote"]) require.Equal(t, float64(300), ev["initial_max_stream_data_uni"]) } func TestSentLongHeaderPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.SentLongHeaderPacket( &logging.ExtendedHeader{ Header: 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, }, PacketNumber: 1337, }, 987, logging.ECNCE, nil, []logging.Frame{ &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, }, ) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_sent", entry.Name) ev := entry.Event require.Contains(t, ev, "raw") raw := ev["raw"].(map[string]interface{}) require.Equal(t, float64(987), raw["length"]) require.Equal(t, float64(1337), raw["payload_length"]) require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Equal(t, "handshake", hdr["packet_type"]) require.Equal(t, float64(1337), hdr["packet_number"]) require.Equal(t, "04030201", hdr["scid"]) require.Contains(t, ev, "frames") require.Equal(t, "CE", ev["ecn"]) frames := ev["frames"].([]interface{}) require.Len(t, frames, 2) require.Equal(t, "max_stream_data", frames[0].(map[string]interface{})["frame_type"]) require.Equal(t, "stream", frames[1].(map[string]interface{})["frame_type"]) } func TestSentShortHeaderPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.SentShortHeaderPacket( &logging.ShortHeader{ DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4}), PacketNumber: 1337, }, 123, logging.ECNUnsupported, &logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}}, []logging.Frame{&logging.MaxDataFrame{MaximumData: 987}}, ) tracer.Close() entry := exportAndParseSingle(t, buf) ev := entry.Event raw := ev["raw"].(map[string]interface{}) require.Equal(t, float64(123), raw["length"]) require.NotContains(t, raw, "payload_length") require.Contains(t, ev, "header") require.NotContains(t, ev, "ecn") hdr := ev["header"].(map[string]interface{}) require.Equal(t, "1RTT", hdr["packet_type"]) require.Equal(t, float64(1337), hdr["packet_number"]) require.Contains(t, ev, "frames") frames := ev["frames"].([]interface{}) require.Len(t, frames, 2) require.Equal(t, "ack", frames[0].(map[string]interface{})["frame_type"]) require.Equal(t, "max_data", frames[1].(map[string]interface{})["frame_type"]) } func TestReceivedLongHeaderPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ReceivedLongHeaderPacket( &logging.ExtendedHeader{ Header: logging.Header{ Type: protocol.PacketTypeInitial, DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), Token: []byte{0xde, 0xad, 0xbe, 0xef}, Length: 1234, Version: protocol.Version1, }, PacketNumber: 1337, }, 789, logging.ECT0, []logging.Frame{ &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, }, ) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_received", entry.Name) ev := entry.Event require.Contains(t, ev, "raw") raw := ev["raw"].(map[string]interface{}) require.Equal(t, float64(789), raw["length"]) require.Equal(t, float64(1234), raw["payload_length"]) require.Equal(t, "ECT(0)", ev["ecn"]) require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Equal(t, "initial", hdr["packet_type"]) require.Equal(t, float64(1337), hdr["packet_number"]) require.Equal(t, "04030201", hdr["scid"]) require.Contains(t, hdr, "token") token := hdr["token"].(map[string]interface{}) require.Equal(t, "deadbeef", token["data"]) require.Contains(t, ev, "frames") require.Len(t, ev["frames"].([]interface{}), 2) } func TestReceivedShortHeaderPacket(t *testing.T) { tracer, buf := newConnectionTracer() shdr := &logging.ShortHeader{ DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), PacketNumber: 1337, PacketNumberLen: protocol.PacketNumberLen3, KeyPhase: protocol.KeyPhaseZero, } tracer.ReceivedShortHeaderPacket( shdr, 789, logging.ECT1, []logging.Frame{ &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, }, ) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_received", entry.Name) ev := entry.Event require.Contains(t, ev, "raw") raw := ev["raw"].(map[string]interface{}) require.Equal(t, float64(789), raw["length"]) require.Equal(t, float64(789-(1+8+3)), raw["payload_length"]) require.Equal(t, "ECT(1)", ev["ecn"]) require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Equal(t, "1RTT", hdr["packet_type"]) require.Equal(t, float64(1337), hdr["packet_number"]) require.Equal(t, "0", hdr["key_phase_bit"]) require.Contains(t, ev, "frames") require.Len(t, ev["frames"].([]interface{}), 2) } func TestReceivedRetryPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ReceivedRetry( &logging.Header{ Type: protocol.PacketTypeRetry, DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), Token: []byte{0xde, 0xad, 0xbe, 0xef}, Version: protocol.Version1, }, ) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_received", entry.Name) ev := entry.Event require.NotContains(t, ev, "raw") require.Contains(t, ev, "header") header := ev["header"].(map[string]interface{}) require.Equal(t, "retry", header["packet_type"]) require.NotContains(t, header, "packet_number") require.Contains(t, header, "version") require.Contains(t, header, "dcid") require.Contains(t, header, "scid") require.Contains(t, header, "token") token := header["token"].(map[string]interface{}) require.Equal(t, "deadbeef", token["data"]) require.NotContains(t, ev, "frames") } func TestReceivedVersionNegotiationPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ReceivedVersionNegotiationPacket( protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, protocol.ArbitraryLenConnectionID{4, 3, 2, 1}, []protocol.Version{0xdeadbeef, 0xdecafbad}, ) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_received", entry.Name) ev := entry.Event require.Contains(t, ev, "header") require.NotContains(t, ev, "frames") require.Contains(t, ev, "supported_versions") require.Equal(t, []interface{}{"deadbeef", "decafbad"}, ev["supported_versions"]) header := ev["header"].(map[string]interface{}) require.Equal(t, "version_negotiation", header["packet_type"]) require.NotContains(t, header, "packet_number") require.NotContains(t, header, "version") require.Equal(t, "0102030405060708", header["dcid"]) require.Equal(t, "04030201", header["scid"]) } func TestBufferedPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.BufferedPacket(logging.PacketTypeHandshake, 1337) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_buffered", entry.Name) ev := entry.Event require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Len(t, hdr, 1) require.Equal(t, "handshake", hdr["packet_type"]) require.Contains(t, ev, "raw") require.Equal(t, float64(1337), ev["raw"].(map[string]interface{})["length"]) require.Equal(t, "keys_unavailable", ev["trigger"]) } func TestDroppedPacket(t *testing.T) { tracer, buf := newConnectionTracer() tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_dropped", entry.Name) ev := entry.Event require.Contains(t, ev, "raw") require.Equal(t, float64(1337), ev["raw"].(map[string]interface{})["length"]) require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Len(t, hdr, 1) require.Equal(t, "retry", hdr["packet_type"]) require.Equal(t, "payload_decrypt_error", ev["trigger"]) } func TestDroppedPacketWithPacketNumber(t *testing.T) { tracer, buf := newConnectionTracer() tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:packet_dropped", entry.Name) ev := entry.Event require.Contains(t, ev, "raw") require.Equal(t, float64(1337), ev["raw"].(map[string]interface{})["length"]) require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Len(t, hdr, 2) require.Equal(t, "handshake", hdr["packet_type"]) require.Equal(t, float64(42), hdr["packet_number"]) require.Equal(t, "duplicate", ev["trigger"]) } func TestUpdatedMetrics(t *testing.T) { var rttStats utils.RTTStats rttStats.UpdateRTT(15*time.Millisecond, 0) rttStats.UpdateRTT(20*time.Millisecond, 0) rttStats.UpdateRTT(25*time.Millisecond, 0) tracer, buf := newConnectionTracer() tracer.UpdatedMetrics(&rttStats, 4321, 1234, 42) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:metrics_updated", entry.Name) ev := entry.Event require.Equal(t, float64(15), ev["min_rtt"]) require.Equal(t, float64(25), ev["latest_rtt"]) require.Contains(t, ev, "smoothed_rtt") require.InDelta(t, rttStats.SmoothedRTT().Milliseconds(), ev["smoothed_rtt"], float64(1)) require.Contains(t, ev, "rtt_variance") require.InDelta(t, rttStats.MeanDeviation().Milliseconds(), ev["rtt_variance"], float64(1)) require.Equal(t, float64(4321), ev["congestion_window"]) require.Equal(t, float64(1234), ev["bytes_in_flight"]) require.Equal(t, float64(42), ev["packets_in_flight"]) } func TestUpdatedMetricsDiff(t *testing.T) { var rttStats utils.RTTStats rttStats.UpdateRTT(15*time.Millisecond, 0) rttStats.UpdateRTT(20*time.Millisecond, 0) rttStats.UpdateRTT(25*time.Millisecond, 0) var rttStats2 utils.RTTStats rttStats2.UpdateRTT(15*time.Millisecond, 0) rttStats2.UpdateRTT(15*time.Millisecond, 0) rttStats2.UpdateRTT(15*time.Millisecond, 0) tracer, buf := newConnectionTracer() tracer.UpdatedMetrics(&rttStats, 4321, 1234, 42) tracer.UpdatedMetrics(&rttStats2, 4321, 12345 /* changed */, 42) tracer.UpdatedMetrics(&rttStats2, 0, 0, 0) tracer.Close() entries := exportAndParse(t, buf) require.Len(t, entries, 3) require.WithinDuration(t, time.Now(), entries[0].Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:metrics_updated", entries[0].Name) require.Len(t, entries[0].Event, 7) require.WithinDuration(t, time.Now(), entries[1].Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:metrics_updated", entries[1].Name) ev := entries[1].Event require.NotContains(t, ev, "min_rtt") require.NotContains(t, ev, "congestion_window") require.NotContains(t, ev, "packets_in_flight") require.Equal(t, float64(12345), ev["bytes_in_flight"]) require.Equal(t, float64(15), ev["smoothed_rtt"]) ev = entries[2].Event require.Contains(t, ev, "congestion_window") require.Contains(t, ev, "packets_in_flight") require.Contains(t, ev, "bytes_in_flight") require.Zero(t, ev["bytes_in_flight"]) require.Zero(t, ev["packets_in_flight"]) require.Zero(t, ev["congestion_window"]) } func TestLostPackets(t *testing.T) { tracer, buf := newConnectionTracer() tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:packet_lost", entry.Name) ev := entry.Event require.Contains(t, ev, "header") hdr := ev["header"].(map[string]interface{}) require.Len(t, hdr, 2) require.Equal(t, "handshake", hdr["packet_type"]) require.Equal(t, float64(42), hdr["packet_number"]) require.Equal(t, "reordering_threshold", ev["trigger"]) } func TestMTUUpdates(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedMTU(1337, true) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:mtu_updated", entry.Name) ev := entry.Event require.Equal(t, float64(1337), ev["mtu"]) require.Equal(t, true, ev["done"]) } func TestCongestionStateUpdates(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:congestion_state_updated", entry.Name) ev := entry.Event require.Equal(t, "congestion_avoidance", ev["new"]) } func TestPTOChanges(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedPTOCount(42) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:metrics_updated", entry.Name) require.Equal(t, float64(42), entry.Event["pto_count"]) } func TestTLSKeyUpdates(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "security:key_updated", entry.Name) ev := entry.Event require.Equal(t, "client_handshake_secret", ev["key_type"]) require.Equal(t, "tls", ev["trigger"]) require.NotContains(t, ev, "key_phase") require.NotContains(t, ev, "old") require.NotContains(t, ev, "new") } func TestTLSKeyUpdatesFor1RTTKeys(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "security:key_updated", entry.Name) ev := entry.Event require.Equal(t, "server_1rtt_secret", ev["key_type"]) require.Equal(t, "tls", ev["trigger"]) require.Equal(t, float64(0), ev["key_phase"]) require.NotContains(t, ev, "old") require.NotContains(t, ev, "new") } func TestQUICKeyUpdates(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedKey(1337, true) tracer.Close() entries := exportAndParse(t, buf) require.Len(t, entries, 2) var keyTypes []string for _, entry := range entries { require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "security:key_updated", entry.Name) ev := entry.Event require.Equal(t, float64(1337), ev["key_phase"]) require.Equal(t, "remote_update", ev["trigger"]) require.Contains(t, ev, "key_type") keyTypes = append(keyTypes, ev["key_type"].(string)) } require.Contains(t, keyTypes, "server_1rtt_secret") require.Contains(t, keyTypes, "client_1rtt_secret") } func TestDroppedEncryptionLevels(t *testing.T) { tracer, buf := newConnectionTracer() tracer.DroppedEncryptionLevel(protocol.EncryptionInitial) tracer.Close() entries := exportAndParse(t, buf) require.Len(t, entries, 2) var keyTypes []string for _, entry := range entries { require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "security:key_discarded", entry.Name) ev := entry.Event require.Equal(t, "tls", ev["trigger"]) require.Contains(t, ev, "key_type") keyTypes = append(keyTypes, ev["key_type"].(string)) } require.Contains(t, keyTypes, "server_initial_secret") require.Contains(t, keyTypes, "client_initial_secret") } func TestDropped0RTTKeys(t *testing.T) { tracer, buf := newConnectionTracer() tracer.DroppedEncryptionLevel(protocol.Encryption0RTT) tracer.Close() entries := exportAndParse(t, buf) require.Len(t, entries, 1) entry := entries[0] require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "security:key_discarded", entry.Name) ev := entry.Event require.Equal(t, "tls", ev["trigger"]) require.Equal(t, "server_0rtt_secret", ev["key_type"]) } func TestDroppedKeys(t *testing.T) { tracer, buf := newConnectionTracer() tracer.DroppedKey(42) tracer.Close() entries := exportAndParse(t, buf) require.Len(t, entries, 2) var keyTypes []string for _, entry := range entries { require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "security:key_discarded", entry.Name) ev := entry.Event require.Equal(t, float64(42), ev["key_phase"]) require.NotContains(t, ev, "trigger") require.Contains(t, ev, "key_type") keyTypes = append(keyTypes, ev["key_type"].(string)) } require.Contains(t, keyTypes, "server_1rtt_secret") require.Contains(t, keyTypes, "client_1rtt_secret") } func TestSetLossTimer(t *testing.T) { tracer, buf := newConnectionTracer() timeout := time.Now().Add(137 * time.Millisecond) tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:loss_timer_updated", entry.Name) ev := entry.Event require.Len(t, ev, 4) require.Equal(t, "set", ev["event_type"]) require.Equal(t, "pto", ev["timer_type"]) require.Equal(t, "handshake", ev["packet_number_space"]) require.Contains(t, ev, "delta") delta := time.Duration(ev["delta"].(float64)*1e6) * time.Nanosecond require.WithinDuration(t, timeout, entry.Time.Add(delta), scaleDuration(10*time.Microsecond)) } func TestExpiredLossTimer(t *testing.T) { tracer, buf := newConnectionTracer() tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:loss_timer_updated", entry.Name) ev := entry.Event require.Len(t, ev, 3) require.Equal(t, "expired", ev["event_type"]) require.Equal(t, "ack", ev["timer_type"]) require.Equal(t, "application_data", ev["packet_number_space"]) } func TestCanceledLossTimer(t *testing.T) { tracer, buf := newConnectionTracer() tracer.LossTimerCanceled() tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:loss_timer_updated", entry.Name) ev := entry.Event require.Len(t, ev, 1) require.Equal(t, "cancelled", ev["event_type"]) } func TestECNStateTransitionWithoutTrigger(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:ecn_state_updated", entry.Name) ev := entry.Event require.Len(t, ev, 1) require.Equal(t, "unknown", ev["new"]) } func TestECNStateTransitionWithTrigger(t *testing.T) { tracer, buf := newConnectionTracer() tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts) tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "recovery:ecn_state_updated", entry.Name) ev := entry.Event require.Len(t, ev, 2) require.Equal(t, "failed", ev["new"]) require.Equal(t, "ACK doesn't contain ECN marks", ev["trigger"]) } func TestGenericConnectionTracerEvent(t *testing.T) { tracer, buf := newConnectionTracer() tracer.Debug("foo", "bar") tracer.Close() entry := exportAndParseSingle(t, buf) require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) require.Equal(t, "transport:foo", entry.Name) ev := entry.Event require.Len(t, ev, 1) require.Equal(t, "bar", ev["details"]) }