github.com/apernet/quic-go@v0.43.1-0.20240515053213-5e9e635fd9f0/qlog/tracer_test.go (about)

     1  package qlog
     2  
     3  import (
     4  	"bytes"
     5  	"encoding/json"
     6  	"net"
     7  	"time"
     8  
     9  	"github.com/apernet/quic-go/internal/protocol"
    10  	"github.com/apernet/quic-go/logging"
    11  
    12  	. "github.com/onsi/ginkgo/v2"
    13  	. "github.com/onsi/gomega"
    14  )
    15  
    16  var _ = Describe("Tracing", func() {
    17  	var (
    18  		tracer *logging.Tracer
    19  		buf    *bytes.Buffer
    20  	)
    21  
    22  	BeforeEach(func() {
    23  		buf = &bytes.Buffer{}
    24  		tracer = NewTracer(nopWriteCloser(buf))
    25  	})
    26  
    27  	It("exports a trace that has the right metadata", func() {
    28  		tracer.Close()
    29  
    30  		m := make(map[string]interface{})
    31  		Expect(json.Unmarshal(buf.Bytes(), &m)).To(Succeed())
    32  		Expect(m).To(HaveKeyWithValue("qlog_version", "draft-02"))
    33  		Expect(m).To(HaveKey("title"))
    34  		Expect(m).To(HaveKey("trace"))
    35  		trace := m["trace"].(map[string]interface{})
    36  		Expect(trace).To(HaveKey(("common_fields")))
    37  		commonFields := trace["common_fields"].(map[string]interface{})
    38  		Expect(commonFields).ToNot(HaveKey("ODCID"))
    39  		Expect(commonFields).ToNot(HaveKey("group_id"))
    40  		Expect(commonFields).To(HaveKey("reference_time"))
    41  		referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6))
    42  		Expect(referenceTime).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
    43  		Expect(commonFields).To(HaveKeyWithValue("time_format", "relative"))
    44  		Expect(trace).To(HaveKey("vantage_point"))
    45  		vantagePoint := trace["vantage_point"].(map[string]interface{})
    46  		Expect(vantagePoint).To(HaveKeyWithValue("type", "transport"))
    47  	})
    48  
    49  	Context("Events", func() {
    50  		It("records a sent long header packet, without an ACK", func() {
    51  			tracer.SentPacket(
    52  				nil,
    53  				&logging.Header{
    54  					Type:             protocol.PacketTypeHandshake,
    55  					DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}),
    56  					SrcConnectionID:  protocol.ParseConnectionID([]byte{4, 3, 2, 1}),
    57  					Length:           1337,
    58  					Version:          protocol.Version1,
    59  				},
    60  				1234,
    61  				[]logging.Frame{
    62  					&logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987},
    63  					&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
    64  				},
    65  			)
    66  			tracer.Close()
    67  			entry := exportAndParseSingle(buf)
    68  			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
    69  			Expect(entry.Name).To(Equal("transport:packet_sent"))
    70  			ev := entry.Event
    71  			Expect(ev).To(HaveKey("raw"))
    72  			raw := ev["raw"].(map[string]interface{})
    73  			Expect(raw).To(HaveKeyWithValue("length", float64(1234)))
    74  			Expect(ev).To(HaveKey("header"))
    75  			hdr := ev["header"].(map[string]interface{})
    76  			Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake"))
    77  			Expect(hdr).To(HaveKeyWithValue("scid", "04030201"))
    78  			Expect(ev).To(HaveKey("frames"))
    79  			frames := ev["frames"].([]interface{})
    80  			Expect(frames).To(HaveLen(2))
    81  			Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_stream_data"))
    82  			Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream"))
    83  		})
    84  
    85  		It("records sending of a Version Negotiation packet", func() {
    86  			tracer.SentVersionNegotiationPacket(
    87  				nil,
    88  				protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8},
    89  				protocol.ArbitraryLenConnectionID{4, 3, 2, 1},
    90  				[]protocol.Version{0xdeadbeef, 0xdecafbad},
    91  			)
    92  			tracer.Close()
    93  			entry := exportAndParseSingle(buf)
    94  			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
    95  			Expect(entry.Name).To(Equal("transport:packet_sent"))
    96  			ev := entry.Event
    97  			Expect(ev).To(HaveKey("header"))
    98  			Expect(ev).ToNot(HaveKey("frames"))
    99  			Expect(ev).To(HaveKey("supported_versions"))
   100  			Expect(ev["supported_versions"].([]interface{})).To(Equal([]interface{}{"deadbeef", "decafbad"}))
   101  			header := ev["header"]
   102  			Expect(header).To(HaveKeyWithValue("packet_type", "version_negotiation"))
   103  			Expect(header).ToNot(HaveKey("packet_number"))
   104  			Expect(header).ToNot(HaveKey("version"))
   105  			Expect(header).To(HaveKeyWithValue("dcid", "0102030405060708"))
   106  			Expect(header).To(HaveKeyWithValue("scid", "04030201"))
   107  		})
   108  
   109  		It("records dropped packets", func() {
   110  			addr := net.UDPAddr{IP: net.IPv4(1, 2, 3, 4), Port: 1234}
   111  			tracer.DroppedPacket(&addr, logging.PacketTypeInitial, 1337, logging.PacketDropPayloadDecryptError)
   112  			tracer.Close()
   113  			entry := exportAndParseSingle(buf)
   114  			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
   115  			Expect(entry.Name).To(Equal("transport:packet_dropped"))
   116  			ev := entry.Event
   117  			Expect(ev).To(HaveKey("raw"))
   118  			Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337)))
   119  			Expect(ev).To(HaveKey("header"))
   120  			hdr := ev["header"].(map[string]interface{})
   121  			Expect(hdr).To(HaveLen(1))
   122  			Expect(hdr).To(HaveKeyWithValue("packet_type", "initial"))
   123  			Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error"))
   124  		})
   125  
   126  		It("records a generic event", func() {
   127  			tracer.Debug("foo", "bar")
   128  			tracer.Close()
   129  			entry := exportAndParseSingle(buf)
   130  			Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
   131  			Expect(entry.Name).To(Equal("transport:foo"))
   132  			ev := entry.Event
   133  			Expect(ev).To(HaveLen(1))
   134  			Expect(ev).To(HaveKeyWithValue("details", "bar"))
   135  		})
   136  	})
   137  })