github.com/TugasAkhir-QUIC/quic-go@v0.0.2-0.20240215011318-d20e25a9054c/qlog/connection_tracer_test.go (about) 1 package qlog 2 3 import ( 4 "bytes" 5 "encoding/json" 6 "io" 7 "net" 8 "net/netip" 9 "time" 10 11 "github.com/TugasAkhir-QUIC/quic-go" 12 "github.com/TugasAkhir-QUIC/quic-go/internal/protocol" 13 "github.com/TugasAkhir-QUIC/quic-go/internal/qerr" 14 "github.com/TugasAkhir-QUIC/quic-go/internal/utils" 15 "github.com/TugasAkhir-QUIC/quic-go/logging" 16 17 . "github.com/onsi/ginkgo/v2" 18 . "github.com/onsi/gomega" 19 ) 20 21 type nopWriteCloserImpl struct{ io.Writer } 22 23 func (nopWriteCloserImpl) Close() error { return nil } 24 25 func nopWriteCloser(w io.Writer) io.WriteCloser { 26 return &nopWriteCloserImpl{Writer: w} 27 } 28 29 type entry struct { 30 Time time.Time 31 Name string 32 Event map[string]interface{} 33 } 34 35 var _ = Describe("Tracing", func() { 36 var ( 37 tracer *logging.ConnectionTracer 38 buf *bytes.Buffer 39 ) 40 41 BeforeEach(func() { 42 buf = &bytes.Buffer{} 43 tracer = NewConnectionTracer( 44 nopWriteCloser(buf), 45 logging.PerspectiveServer, 46 protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), 47 ) 48 }) 49 50 It("exports a trace that has the right metadata", func() { 51 tracer.Close() 52 53 m := make(map[string]interface{}) 54 Expect(json.Unmarshal(buf.Bytes(), &m)).To(Succeed()) 55 Expect(m).To(HaveKeyWithValue("qlog_version", "draft-02")) 56 Expect(m).To(HaveKey("title")) 57 Expect(m).To(HaveKey("trace")) 58 trace := m["trace"].(map[string]interface{}) 59 Expect(trace).To(HaveKey(("common_fields"))) 60 commonFields := trace["common_fields"].(map[string]interface{}) 61 Expect(commonFields).To(HaveKeyWithValue("ODCID", "deadbeef")) 62 Expect(commonFields).To(HaveKeyWithValue("group_id", "deadbeef")) 63 Expect(commonFields).To(HaveKey("reference_time")) 64 referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6)) 65 Expect(referenceTime).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 66 Expect(commonFields).To(HaveKeyWithValue("time_format", "relative")) 67 Expect(trace).To(HaveKey("vantage_point")) 68 vantagePoint := trace["vantage_point"].(map[string]interface{}) 69 Expect(vantagePoint).To(HaveKeyWithValue("type", "server")) 70 }) 71 72 Context("Events", func() { 73 exportAndParse := func() []entry { 74 tracer.Close() 75 76 m := make(map[string]interface{}) 77 line, err := buf.ReadBytes('\n') 78 Expect(err).ToNot(HaveOccurred()) 79 Expect(json.Unmarshal(line, &m)).To(Succeed()) 80 Expect(m).To(HaveKey("trace")) 81 var entries []entry 82 trace := m["trace"].(map[string]interface{}) 83 Expect(trace).To(HaveKey("common_fields")) 84 commonFields := trace["common_fields"].(map[string]interface{}) 85 Expect(commonFields).To(HaveKey("reference_time")) 86 referenceTime := time.Unix(0, int64(commonFields["reference_time"].(float64)*1e6)) 87 Expect(trace).ToNot(HaveKey("events")) 88 89 for buf.Len() > 0 { 90 line, err := buf.ReadBytes('\n') 91 Expect(err).ToNot(HaveOccurred()) 92 ev := make(map[string]interface{}) 93 Expect(json.Unmarshal(line, &ev)).To(Succeed()) 94 Expect(ev).To(HaveLen(3)) 95 Expect(ev).To(HaveKey("time")) 96 Expect(ev).To(HaveKey("name")) 97 Expect(ev).To(HaveKey("data")) 98 entries = append(entries, entry{ 99 Time: referenceTime.Add(time.Duration(ev["time"].(float64)*1e6) * time.Nanosecond), 100 Name: ev["name"].(string), 101 Event: ev["data"].(map[string]interface{}), 102 }) 103 } 104 return entries 105 } 106 107 exportAndParseSingle := func() entry { 108 entries := exportAndParse() 109 Expect(entries).To(HaveLen(1)) 110 return entries[0] 111 } 112 113 It("records connection starts", func() { 114 tracer.StartedConnection( 115 &net.UDPAddr{IP: net.IPv4(192, 168, 13, 37), Port: 42}, 116 &net.UDPAddr{IP: net.IPv4(192, 168, 12, 34), Port: 24}, 117 protocol.ParseConnectionID([]byte{1, 2, 3, 4}), 118 protocol.ParseConnectionID([]byte{5, 6, 7, 8}), 119 ) 120 entry := exportAndParseSingle() 121 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 122 Expect(entry.Name).To(Equal("transport:connection_started")) 123 ev := entry.Event 124 Expect(ev).To(HaveKeyWithValue("ip_version", "ipv4")) 125 Expect(ev).To(HaveKeyWithValue("src_ip", "192.168.13.37")) 126 Expect(ev).To(HaveKeyWithValue("src_port", float64(42))) 127 Expect(ev).To(HaveKeyWithValue("dst_ip", "192.168.12.34")) 128 Expect(ev).To(HaveKeyWithValue("dst_port", float64(24))) 129 Expect(ev).To(HaveKeyWithValue("src_cid", "01020304")) 130 Expect(ev).To(HaveKeyWithValue("dst_cid", "05060708")) 131 }) 132 133 It("records the version, if no version negotiation happened", func() { 134 tracer.NegotiatedVersion(0x1337, nil, nil) 135 entry := exportAndParseSingle() 136 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 137 Expect(entry.Name).To(Equal("transport:version_information")) 138 ev := entry.Event 139 Expect(ev).To(HaveLen(1)) 140 Expect(ev).To(HaveKeyWithValue("chosen_version", "1337")) 141 }) 142 143 It("records the version, if version negotiation happened", func() { 144 tracer.NegotiatedVersion(0x1337, []logging.VersionNumber{1, 2, 3}, []logging.VersionNumber{4, 5, 6}) 145 entry := exportAndParseSingle() 146 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 147 Expect(entry.Name).To(Equal("transport:version_information")) 148 ev := entry.Event 149 Expect(ev).To(HaveLen(3)) 150 Expect(ev).To(HaveKeyWithValue("chosen_version", "1337")) 151 Expect(ev).To(HaveKey("client_versions")) 152 Expect(ev["client_versions"].([]interface{})).To(Equal([]interface{}{"1", "2", "3"})) 153 Expect(ev).To(HaveKey("server_versions")) 154 Expect(ev["server_versions"].([]interface{})).To(Equal([]interface{}{"4", "5", "6"})) 155 }) 156 157 It("records idle timeouts", func() { 158 tracer.ClosedConnection(&quic.IdleTimeoutError{}) 159 entry := exportAndParseSingle() 160 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 161 Expect(entry.Name).To(Equal("transport:connection_closed")) 162 ev := entry.Event 163 Expect(ev).To(HaveLen(2)) 164 Expect(ev).To(HaveKeyWithValue("owner", "local")) 165 Expect(ev).To(HaveKeyWithValue("trigger", "idle_timeout")) 166 }) 167 168 It("records handshake timeouts", func() { 169 tracer.ClosedConnection(&quic.HandshakeTimeoutError{}) 170 entry := exportAndParseSingle() 171 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 172 Expect(entry.Name).To(Equal("transport:connection_closed")) 173 ev := entry.Event 174 Expect(ev).To(HaveLen(2)) 175 Expect(ev).To(HaveKeyWithValue("owner", "local")) 176 Expect(ev).To(HaveKeyWithValue("trigger", "handshake_timeout")) 177 }) 178 179 It("records a received stateless reset packet", func() { 180 tracer.ClosedConnection(&quic.StatelessResetError{ 181 Token: protocol.StatelessResetToken{0x00, 0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff}, 182 }) 183 entry := exportAndParseSingle() 184 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 185 Expect(entry.Name).To(Equal("transport:connection_closed")) 186 ev := entry.Event 187 Expect(ev).To(HaveLen(3)) 188 Expect(ev).To(HaveKeyWithValue("owner", "remote")) 189 Expect(ev).To(HaveKeyWithValue("trigger", "stateless_reset")) 190 Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "00112233445566778899aabbccddeeff")) 191 }) 192 193 It("records connection closing due to version negotiation failure", func() { 194 tracer.ClosedConnection(&quic.VersionNegotiationError{}) 195 entry := exportAndParseSingle() 196 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 197 Expect(entry.Name).To(Equal("transport:connection_closed")) 198 ev := entry.Event 199 Expect(ev).To(HaveLen(1)) 200 Expect(ev).To(HaveKeyWithValue("trigger", "version_mismatch")) 201 }) 202 203 It("records application errors", func() { 204 tracer.ClosedConnection(&quic.ApplicationError{ 205 Remote: true, 206 ErrorCode: 1337, 207 ErrorMessage: "foobar", 208 }) 209 entry := exportAndParseSingle() 210 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 211 Expect(entry.Name).To(Equal("transport:connection_closed")) 212 ev := entry.Event 213 Expect(ev).To(HaveLen(3)) 214 Expect(ev).To(HaveKeyWithValue("owner", "remote")) 215 Expect(ev).To(HaveKeyWithValue("application_code", float64(1337))) 216 Expect(ev).To(HaveKeyWithValue("reason", "foobar")) 217 }) 218 219 It("records transport errors", func() { 220 tracer.ClosedConnection(&quic.TransportError{ 221 ErrorCode: qerr.AEADLimitReached, 222 ErrorMessage: "foobar", 223 }) 224 entry := exportAndParseSingle() 225 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 226 Expect(entry.Name).To(Equal("transport:connection_closed")) 227 ev := entry.Event 228 Expect(ev).To(HaveLen(3)) 229 Expect(ev).To(HaveKeyWithValue("owner", "local")) 230 Expect(ev).To(HaveKeyWithValue("connection_code", "aead_limit_reached")) 231 Expect(ev).To(HaveKeyWithValue("reason", "foobar")) 232 }) 233 234 It("records sent transport parameters", func() { 235 rcid := protocol.ParseConnectionID([]byte{0xde, 0xca, 0xfb, 0xad}) 236 tracer.SentTransportParameters(&logging.TransportParameters{ 237 InitialMaxStreamDataBidiLocal: 1000, 238 InitialMaxStreamDataBidiRemote: 2000, 239 InitialMaxStreamDataUni: 3000, 240 InitialMaxData: 4000, 241 MaxBidiStreamNum: 10, 242 MaxUniStreamNum: 20, 243 MaxAckDelay: 123 * time.Millisecond, 244 AckDelayExponent: 12, 245 DisableActiveMigration: true, 246 MaxUDPPayloadSize: 1234, 247 MaxIdleTimeout: 321 * time.Millisecond, 248 StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, 249 OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), 250 InitialSourceConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}), 251 RetrySourceConnectionID: &rcid, 252 ActiveConnectionIDLimit: 7, 253 MaxDatagramFrameSize: protocol.InvalidByteCount, 254 }) 255 entry := exportAndParseSingle() 256 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 257 Expect(entry.Name).To(Equal("transport:parameters_set")) 258 ev := entry.Event 259 Expect(ev).To(HaveKeyWithValue("owner", "local")) 260 Expect(ev).To(HaveKeyWithValue("original_destination_connection_id", "deadc0de")) 261 Expect(ev).To(HaveKeyWithValue("initial_source_connection_id", "deadbeef")) 262 Expect(ev).To(HaveKeyWithValue("retry_source_connection_id", "decafbad")) 263 Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "112233445566778899aabbccddeeff00")) 264 Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(321))) 265 Expect(ev).To(HaveKeyWithValue("max_udp_payload_size", float64(1234))) 266 Expect(ev).To(HaveKeyWithValue("ack_delay_exponent", float64(12))) 267 Expect(ev).To(HaveKeyWithValue("active_connection_id_limit", float64(7))) 268 Expect(ev).To(HaveKeyWithValue("initial_max_data", float64(4000))) 269 Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_local", float64(1000))) 270 Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_remote", float64(2000))) 271 Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_uni", float64(3000))) 272 Expect(ev).To(HaveKeyWithValue("initial_max_streams_bidi", float64(10))) 273 Expect(ev).To(HaveKeyWithValue("initial_max_streams_uni", float64(20))) 274 Expect(ev).ToNot(HaveKey("preferred_address")) 275 Expect(ev).ToNot(HaveKey("max_datagram_frame_size")) 276 }) 277 278 It("records the server's transport parameters, without a stateless reset token", func() { 279 tracer.SentTransportParameters(&logging.TransportParameters{ 280 OriginalDestinationConnectionID: protocol.ParseConnectionID([]byte{0xde, 0xad, 0xc0, 0xde}), 281 ActiveConnectionIDLimit: 7, 282 }) 283 entry := exportAndParseSingle() 284 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 285 Expect(entry.Name).To(Equal("transport:parameters_set")) 286 ev := entry.Event 287 Expect(ev).ToNot(HaveKey("stateless_reset_token")) 288 }) 289 290 It("records transport parameters without retry_source_connection_id", func() { 291 tracer.SentTransportParameters(&logging.TransportParameters{ 292 StatelessResetToken: &protocol.StatelessResetToken{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, 293 }) 294 entry := exportAndParseSingle() 295 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 296 Expect(entry.Name).To(Equal("transport:parameters_set")) 297 ev := entry.Event 298 Expect(ev).To(HaveKeyWithValue("owner", "local")) 299 Expect(ev).ToNot(HaveKey("retry_source_connection_id")) 300 }) 301 302 It("records transport parameters with a preferred address", func() { 303 tracer.SentTransportParameters(&logging.TransportParameters{ 304 PreferredAddress: &logging.PreferredAddress{ 305 IPv4: netip.AddrPortFrom(netip.AddrFrom4([4]byte{12, 34, 56, 78}), 123), 306 IPv6: netip.AddrPortFrom(netip.AddrFrom16([16]byte{1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16}), 456), 307 ConnectionID: protocol.ParseConnectionID([]byte{8, 7, 6, 5, 4, 3, 2, 1}), 308 StatelessResetToken: protocol.StatelessResetToken{15, 14, 13, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0}, 309 }, 310 }) 311 entry := exportAndParseSingle() 312 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 313 Expect(entry.Name).To(Equal("transport:parameters_set")) 314 ev := entry.Event 315 Expect(ev).To(HaveKeyWithValue("owner", "local")) 316 Expect(ev).To(HaveKey("preferred_address")) 317 pa := ev["preferred_address"].(map[string]interface{}) 318 Expect(pa).To(HaveKeyWithValue("ip_v4", "12.34.56.78")) 319 Expect(pa).To(HaveKeyWithValue("port_v4", float64(123))) 320 Expect(pa).To(HaveKeyWithValue("ip_v6", "102:304:506:708:90a:b0c:d0e:f10")) 321 Expect(pa).To(HaveKeyWithValue("port_v6", float64(456))) 322 Expect(pa).To(HaveKeyWithValue("connection_id", "0807060504030201")) 323 Expect(pa).To(HaveKeyWithValue("stateless_reset_token", "0f0e0d0c0b0a09080706050403020100")) 324 }) 325 326 It("records transport parameters that enable the datagram extension", func() { 327 tracer.SentTransportParameters(&logging.TransportParameters{ 328 MaxDatagramFrameSize: 1337, 329 }) 330 entry := exportAndParseSingle() 331 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 332 Expect(entry.Name).To(Equal("transport:parameters_set")) 333 ev := entry.Event 334 Expect(ev).To(HaveKeyWithValue("max_datagram_frame_size", float64(1337))) 335 }) 336 337 It("records received transport parameters", func() { 338 tracer.ReceivedTransportParameters(&logging.TransportParameters{}) 339 entry := exportAndParseSingle() 340 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 341 Expect(entry.Name).To(Equal("transport:parameters_set")) 342 ev := entry.Event 343 Expect(ev).To(HaveKeyWithValue("owner", "remote")) 344 Expect(ev).ToNot(HaveKey("original_destination_connection_id")) 345 }) 346 347 It("records restored transport parameters", func() { 348 tracer.RestoredTransportParameters(&logging.TransportParameters{ 349 InitialMaxStreamDataBidiLocal: 100, 350 InitialMaxStreamDataBidiRemote: 200, 351 InitialMaxStreamDataUni: 300, 352 InitialMaxData: 400, 353 MaxIdleTimeout: 123 * time.Millisecond, 354 }) 355 entry := exportAndParseSingle() 356 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 357 Expect(entry.Name).To(Equal("transport:parameters_restored")) 358 ev := entry.Event 359 Expect(ev).ToNot(HaveKey("owner")) 360 Expect(ev).ToNot(HaveKey("original_destination_connection_id")) 361 Expect(ev).ToNot(HaveKey("stateless_reset_token")) 362 Expect(ev).ToNot(HaveKey("retry_source_connection_id")) 363 Expect(ev).ToNot(HaveKey("initial_source_connection_id")) 364 Expect(ev).To(HaveKeyWithValue("max_idle_timeout", float64(123))) 365 Expect(ev).To(HaveKeyWithValue("initial_max_data", float64(400))) 366 Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_local", float64(100))) 367 Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_bidi_remote", float64(200))) 368 Expect(ev).To(HaveKeyWithValue("initial_max_stream_data_uni", float64(300))) 369 }) 370 371 It("records a sent long header packet, without an ACK", func() { 372 tracer.SentLongHeaderPacket( 373 &logging.ExtendedHeader{ 374 Header: logging.Header{ 375 Type: protocol.PacketTypeHandshake, 376 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 377 SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), 378 Length: 1337, 379 Version: protocol.Version1, 380 }, 381 PacketNumber: 1337, 382 }, 383 987, 384 logging.ECNCE, 385 nil, 386 []logging.Frame{ 387 &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, 388 &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, 389 }, 390 ) 391 entry := exportAndParseSingle() 392 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 393 Expect(entry.Name).To(Equal("transport:packet_sent")) 394 ev := entry.Event 395 Expect(ev).To(HaveKey("raw")) 396 raw := ev["raw"].(map[string]interface{}) 397 Expect(raw).To(HaveKeyWithValue("length", float64(987))) 398 Expect(raw).To(HaveKeyWithValue("payload_length", float64(1337))) 399 Expect(ev).To(HaveKey("header")) 400 hdr := ev["header"].(map[string]interface{}) 401 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 402 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 403 Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) 404 Expect(ev).To(HaveKey("frames")) 405 Expect(ev).To(HaveKeyWithValue("ecn", "CE")) 406 frames := ev["frames"].([]interface{}) 407 Expect(frames).To(HaveLen(2)) 408 Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_stream_data")) 409 Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream")) 410 }) 411 412 It("records a sent short header packet, without an ACK", func() { 413 tracer.SentShortHeaderPacket( 414 &logging.ShortHeader{ 415 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4}), 416 PacketNumber: 1337, 417 }, 418 123, 419 logging.ECNUnsupported, 420 &logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}}, 421 []logging.Frame{&logging.MaxDataFrame{MaximumData: 987}}, 422 ) 423 entry := exportAndParseSingle() 424 ev := entry.Event 425 raw := ev["raw"].(map[string]interface{}) 426 Expect(raw).To(HaveKeyWithValue("length", float64(123))) 427 Expect(raw).ToNot(HaveKey("payload_length")) 428 Expect(ev).To(HaveKey("header")) 429 Expect(ev).ToNot(HaveKey("ecn")) 430 hdr := ev["header"].(map[string]interface{}) 431 Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) 432 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 433 Expect(ev).To(HaveKey("frames")) 434 frames := ev["frames"].([]interface{}) 435 Expect(frames).To(HaveLen(2)) 436 Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "ack")) 437 Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_data")) 438 }) 439 440 It("records a received Long Header packet", func() { 441 tracer.ReceivedLongHeaderPacket( 442 &logging.ExtendedHeader{ 443 Header: logging.Header{ 444 Type: protocol.PacketTypeInitial, 445 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 446 SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), 447 Token: []byte{0xde, 0xad, 0xbe, 0xef}, 448 Length: 1234, 449 Version: protocol.Version1, 450 }, 451 PacketNumber: 1337, 452 }, 453 789, 454 logging.ECT0, 455 []logging.Frame{ 456 &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, 457 &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, 458 }, 459 ) 460 entry := exportAndParseSingle() 461 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 462 Expect(entry.Name).To(Equal("transport:packet_received")) 463 ev := entry.Event 464 Expect(ev).To(HaveKey("raw")) 465 raw := ev["raw"].(map[string]interface{}) 466 Expect(raw).To(HaveKeyWithValue("length", float64(789))) 467 Expect(raw).To(HaveKeyWithValue("payload_length", float64(1234))) 468 Expect(ev).To(HaveKeyWithValue("ecn", "ECT(0)")) 469 Expect(ev).To(HaveKey("header")) 470 hdr := ev["header"].(map[string]interface{}) 471 Expect(hdr).To(HaveKeyWithValue("packet_type", "initial")) 472 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 473 Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) 474 Expect(hdr).To(HaveKey("token")) 475 token := hdr["token"].(map[string]interface{}) 476 Expect(token).To(HaveKeyWithValue("data", "deadbeef")) 477 Expect(ev).To(HaveKey("frames")) 478 Expect(ev["frames"].([]interface{})).To(HaveLen(2)) 479 }) 480 481 It("records a received Short Header packet", func() { 482 shdr := &logging.ShortHeader{ 483 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 484 PacketNumber: 1337, 485 PacketNumberLen: protocol.PacketNumberLen3, 486 KeyPhase: protocol.KeyPhaseZero, 487 } 488 tracer.ReceivedShortHeaderPacket( 489 shdr, 490 789, 491 logging.ECT1, 492 []logging.Frame{ 493 &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, 494 &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, 495 }, 496 ) 497 entry := exportAndParseSingle() 498 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 499 Expect(entry.Name).To(Equal("transport:packet_received")) 500 ev := entry.Event 501 Expect(ev).To(HaveKey("raw")) 502 raw := ev["raw"].(map[string]interface{}) 503 Expect(raw).To(HaveKeyWithValue("length", float64(789))) 504 Expect(raw).To(HaveKeyWithValue("payload_length", float64(789-(1+8+3)))) 505 Expect(ev).To(HaveKeyWithValue("ecn", "ECT(1)")) 506 Expect(ev).To(HaveKey("header")) 507 hdr := ev["header"].(map[string]interface{}) 508 Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) 509 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 510 Expect(hdr).To(HaveKeyWithValue("key_phase_bit", "0")) 511 Expect(ev).To(HaveKey("frames")) 512 Expect(ev["frames"].([]interface{})).To(HaveLen(2)) 513 }) 514 515 It("records a received Retry packet", func() { 516 tracer.ReceivedRetry( 517 &logging.Header{ 518 Type: protocol.PacketTypeRetry, 519 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 520 SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), 521 Token: []byte{0xde, 0xad, 0xbe, 0xef}, 522 Version: protocol.Version1, 523 }, 524 ) 525 entry := exportAndParseSingle() 526 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 527 Expect(entry.Name).To(Equal("transport:packet_received")) 528 ev := entry.Event 529 Expect(ev).ToNot(HaveKey("raw")) 530 Expect(ev).To(HaveKey("header")) 531 header := ev["header"].(map[string]interface{}) 532 Expect(header).To(HaveKeyWithValue("packet_type", "retry")) 533 Expect(header).ToNot(HaveKey("packet_number")) 534 Expect(header).To(HaveKey("version")) 535 Expect(header).To(HaveKey("dcid")) 536 Expect(header).To(HaveKey("scid")) 537 Expect(header).To(HaveKey("token")) 538 token := header["token"].(map[string]interface{}) 539 Expect(token).To(HaveKeyWithValue("data", "deadbeef")) 540 Expect(ev).ToNot(HaveKey("frames")) 541 }) 542 543 It("records a received Version Negotiation packet", func() { 544 tracer.ReceivedVersionNegotiationPacket( 545 protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, 546 protocol.ArbitraryLenConnectionID{4, 3, 2, 1}, 547 []protocol.Version{0xdeadbeef, 0xdecafbad}, 548 ) 549 entry := exportAndParseSingle() 550 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 551 Expect(entry.Name).To(Equal("transport:packet_received")) 552 ev := entry.Event 553 Expect(ev).To(HaveKey("header")) 554 Expect(ev).ToNot(HaveKey("frames")) 555 Expect(ev).To(HaveKey("supported_versions")) 556 Expect(ev["supported_versions"].([]interface{})).To(Equal([]interface{}{"deadbeef", "decafbad"})) 557 header := ev["header"] 558 Expect(header).To(HaveKeyWithValue("packet_type", "version_negotiation")) 559 Expect(header).ToNot(HaveKey("packet_number")) 560 Expect(header).ToNot(HaveKey("version")) 561 Expect(header).To(HaveKeyWithValue("dcid", "0102030405060708")) 562 Expect(header).To(HaveKeyWithValue("scid", "04030201")) 563 }) 564 565 It("records buffered packets", func() { 566 tracer.BufferedPacket(logging.PacketTypeHandshake, 1337) 567 entry := exportAndParseSingle() 568 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 569 Expect(entry.Name).To(Equal("transport:packet_buffered")) 570 ev := entry.Event 571 Expect(ev).To(HaveKey("header")) 572 hdr := ev["header"].(map[string]interface{}) 573 Expect(hdr).To(HaveLen(1)) 574 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 575 Expect(ev).To(HaveKey("raw")) 576 Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) 577 Expect(ev).To(HaveKeyWithValue("trigger", "keys_unavailable")) 578 }) 579 580 It("records dropped packets", func() { 581 tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError) 582 entry := exportAndParseSingle() 583 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 584 Expect(entry.Name).To(Equal("transport:packet_dropped")) 585 ev := entry.Event 586 Expect(ev).To(HaveKey("raw")) 587 Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) 588 Expect(ev).To(HaveKey("header")) 589 hdr := ev["header"].(map[string]interface{}) 590 Expect(hdr).To(HaveLen(1)) 591 Expect(hdr).To(HaveKeyWithValue("packet_type", "retry")) 592 Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error")) 593 }) 594 595 It("records dropped packets with a packet number", func() { 596 tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate) 597 entry := exportAndParseSingle() 598 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 599 Expect(entry.Name).To(Equal("transport:packet_dropped")) 600 ev := entry.Event 601 Expect(ev).To(HaveKey("raw")) 602 Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) 603 Expect(ev).To(HaveKey("header")) 604 hdr := ev["header"].(map[string]interface{}) 605 Expect(hdr).To(HaveLen(2)) 606 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 607 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) 608 Expect(ev).To(HaveKeyWithValue("trigger", "duplicate")) 609 }) 610 611 It("records metrics updates", func() { 612 now := time.Now() 613 rttStats := utils.NewRTTStats() 614 rttStats.UpdateRTT(15*time.Millisecond, 0, now) 615 rttStats.UpdateRTT(20*time.Millisecond, 0, now) 616 rttStats.UpdateRTT(25*time.Millisecond, 0, now) 617 Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) 618 Expect(rttStats.SmoothedRTT()).To(And( 619 BeNumerically(">", 15*time.Millisecond), 620 BeNumerically("<", 25*time.Millisecond), 621 )) 622 Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) 623 tracer.UpdatedMetrics( 624 rttStats, 625 4321, 626 1234, 627 42, 628 ) 629 entry := exportAndParseSingle() 630 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 631 Expect(entry.Name).To(Equal("recovery:metrics_updated")) 632 ev := entry.Event 633 Expect(ev).To(HaveKeyWithValue("min_rtt", float64(15))) 634 Expect(ev).To(HaveKeyWithValue("latest_rtt", float64(25))) 635 Expect(ev).To(HaveKey("smoothed_rtt")) 636 Expect(time.Duration(ev["smoothed_rtt"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.SmoothedRTT(), time.Millisecond)) 637 Expect(ev).To(HaveKey("rtt_variance")) 638 Expect(time.Duration(ev["rtt_variance"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.MeanDeviation(), time.Millisecond)) 639 Expect(ev).To(HaveKeyWithValue("congestion_window", float64(4321))) 640 Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(1234))) 641 Expect(ev).To(HaveKeyWithValue("packets_in_flight", float64(42))) 642 }) 643 644 It("only logs the diff between two metrics updates", func() { 645 now := time.Now() 646 rttStats := utils.NewRTTStats() 647 rttStats.UpdateRTT(15*time.Millisecond, 0, now) 648 rttStats.UpdateRTT(20*time.Millisecond, 0, now) 649 rttStats.UpdateRTT(25*time.Millisecond, 0, now) 650 Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) 651 652 rttStats2 := utils.NewRTTStats() 653 rttStats2.UpdateRTT(15*time.Millisecond, 0, now) 654 rttStats2.UpdateRTT(15*time.Millisecond, 0, now) 655 rttStats2.UpdateRTT(15*time.Millisecond, 0, now) 656 Expect(rttStats2.MinRTT()).To(Equal(15 * time.Millisecond)) 657 658 Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) 659 tracer.UpdatedMetrics( 660 rttStats, 661 4321, 662 1234, 663 42, 664 ) 665 tracer.UpdatedMetrics( 666 rttStats2, 667 4321, 668 12345, // changed 669 42, 670 ) 671 entries := exportAndParse() 672 Expect(entries).To(HaveLen(2)) 673 Expect(entries[0].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 674 Expect(entries[0].Name).To(Equal("recovery:metrics_updated")) 675 Expect(entries[0].Event).To(HaveLen(7)) 676 Expect(entries[1].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 677 Expect(entries[1].Name).To(Equal("recovery:metrics_updated")) 678 ev := entries[1].Event 679 Expect(ev).ToNot(HaveKey("min_rtt")) 680 Expect(ev).ToNot(HaveKey("congestion_window")) 681 Expect(ev).ToNot(HaveKey("packets_in_flight")) 682 Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(12345))) 683 Expect(ev).To(HaveKeyWithValue("smoothed_rtt", float64(15))) 684 }) 685 686 It("records lost packets", func() { 687 tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold) 688 entry := exportAndParseSingle() 689 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 690 Expect(entry.Name).To(Equal("recovery:packet_lost")) 691 ev := entry.Event 692 Expect(ev).To(HaveKey("header")) 693 hdr := ev["header"].(map[string]interface{}) 694 Expect(hdr).To(HaveLen(2)) 695 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 696 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) 697 Expect(ev).To(HaveKeyWithValue("trigger", "reordering_threshold")) 698 }) 699 700 It("records congestion state updates", func() { 701 tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance) 702 entry := exportAndParseSingle() 703 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 704 Expect(entry.Name).To(Equal("recovery:congestion_state_updated")) 705 ev := entry.Event 706 Expect(ev).To(HaveKeyWithValue("new", "congestion_avoidance")) 707 }) 708 709 It("records PTO changes", func() { 710 tracer.UpdatedPTOCount(42) 711 entry := exportAndParseSingle() 712 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 713 Expect(entry.Name).To(Equal("recovery:metrics_updated")) 714 Expect(entry.Event).To(HaveKeyWithValue("pto_count", float64(42))) 715 }) 716 717 It("records TLS key updates", func() { 718 tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient) 719 entry := exportAndParseSingle() 720 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 721 Expect(entry.Name).To(Equal("security:key_updated")) 722 ev := entry.Event 723 Expect(ev).To(HaveKeyWithValue("key_type", "client_handshake_secret")) 724 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 725 Expect(ev).ToNot(HaveKey("key_phase")) 726 Expect(ev).ToNot(HaveKey("old")) 727 Expect(ev).ToNot(HaveKey("new")) 728 }) 729 730 It("records TLS key updates, for 1-RTT keys", func() { 731 tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer) 732 entry := exportAndParseSingle() 733 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 734 Expect(entry.Name).To(Equal("security:key_updated")) 735 ev := entry.Event 736 Expect(ev).To(HaveKeyWithValue("key_type", "server_1rtt_secret")) 737 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 738 Expect(ev).To(HaveKeyWithValue("key_phase", float64(0))) 739 Expect(ev).ToNot(HaveKey("old")) 740 Expect(ev).ToNot(HaveKey("new")) 741 }) 742 743 It("records QUIC key updates", func() { 744 tracer.UpdatedKey(1337, true) 745 entries := exportAndParse() 746 Expect(entries).To(HaveLen(2)) 747 var keyTypes []string 748 for _, entry := range entries { 749 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 750 Expect(entry.Name).To(Equal("security:key_updated")) 751 ev := entry.Event 752 Expect(ev).To(HaveKeyWithValue("key_phase", float64(1337))) 753 Expect(ev).To(HaveKeyWithValue("trigger", "remote_update")) 754 Expect(ev).To(HaveKey("key_type")) 755 keyTypes = append(keyTypes, ev["key_type"].(string)) 756 } 757 Expect(keyTypes).To(ContainElement("server_1rtt_secret")) 758 Expect(keyTypes).To(ContainElement("client_1rtt_secret")) 759 }) 760 761 It("records dropped encryption levels", func() { 762 tracer.DroppedEncryptionLevel(protocol.EncryptionInitial) 763 entries := exportAndParse() 764 Expect(entries).To(HaveLen(2)) 765 var keyTypes []string 766 for _, entry := range entries { 767 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 768 Expect(entry.Name).To(Equal("security:key_discarded")) 769 ev := entry.Event 770 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 771 Expect(ev).To(HaveKey("key_type")) 772 keyTypes = append(keyTypes, ev["key_type"].(string)) 773 } 774 Expect(keyTypes).To(ContainElement("server_initial_secret")) 775 Expect(keyTypes).To(ContainElement("client_initial_secret")) 776 }) 777 778 It("records dropped 0-RTT keys", func() { 779 tracer.DroppedEncryptionLevel(protocol.Encryption0RTT) 780 entries := exportAndParse() 781 Expect(entries).To(HaveLen(1)) 782 entry := entries[0] 783 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 784 Expect(entry.Name).To(Equal("security:key_discarded")) 785 ev := entry.Event 786 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 787 Expect(ev).To(HaveKeyWithValue("key_type", "server_0rtt_secret")) 788 }) 789 790 It("records dropped keys", func() { 791 tracer.DroppedKey(42) 792 entries := exportAndParse() 793 Expect(entries).To(HaveLen(2)) 794 var keyTypes []string 795 for _, entry := range entries { 796 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 797 Expect(entry.Name).To(Equal("security:key_discarded")) 798 ev := entry.Event 799 Expect(ev).To(HaveKeyWithValue("key_phase", float64(42))) 800 Expect(ev).ToNot(HaveKey("trigger")) 801 Expect(ev).To(HaveKey("key_type")) 802 keyTypes = append(keyTypes, ev["key_type"].(string)) 803 } 804 Expect(keyTypes).To(ContainElement("server_1rtt_secret")) 805 Expect(keyTypes).To(ContainElement("client_1rtt_secret")) 806 }) 807 808 It("records when the timer is set", func() { 809 timeout := time.Now().Add(137 * time.Millisecond) 810 tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout) 811 entry := exportAndParseSingle() 812 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 813 Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) 814 ev := entry.Event 815 Expect(ev).To(HaveLen(4)) 816 Expect(ev).To(HaveKeyWithValue("event_type", "set")) 817 Expect(ev).To(HaveKeyWithValue("timer_type", "pto")) 818 Expect(ev).To(HaveKeyWithValue("packet_number_space", "handshake")) 819 Expect(ev).To(HaveKey("delta")) 820 delta := time.Duration(ev["delta"].(float64)*1e6) * time.Nanosecond 821 Expect(entry.Time.Add(delta)).To(BeTemporally("~", timeout, scaleDuration(10*time.Microsecond))) 822 }) 823 824 It("records when the loss timer expires", func() { 825 tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT) 826 entry := exportAndParseSingle() 827 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 828 Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) 829 ev := entry.Event 830 Expect(ev).To(HaveLen(3)) 831 Expect(ev).To(HaveKeyWithValue("event_type", "expired")) 832 Expect(ev).To(HaveKeyWithValue("timer_type", "ack")) 833 Expect(ev).To(HaveKeyWithValue("packet_number_space", "application_data")) 834 }) 835 836 It("records when the timer is canceled", func() { 837 tracer.LossTimerCanceled() 838 entry := exportAndParseSingle() 839 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 840 Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) 841 ev := entry.Event 842 Expect(ev).To(HaveLen(1)) 843 Expect(ev).To(HaveKeyWithValue("event_type", "cancelled")) 844 }) 845 846 It("records an ECN state transition, without a trigger", func() { 847 tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger) 848 entry := exportAndParseSingle() 849 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 850 Expect(entry.Name).To(Equal("recovery:ecn_state_updated")) 851 ev := entry.Event 852 Expect(ev).To(HaveLen(1)) 853 Expect(ev).To(HaveKeyWithValue("new", "unknown")) 854 }) 855 856 It("records an ECN state transition, with a trigger", func() { 857 tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts) 858 entry := exportAndParseSingle() 859 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 860 Expect(entry.Name).To(Equal("recovery:ecn_state_updated")) 861 ev := entry.Event 862 Expect(ev).To(HaveLen(2)) 863 Expect(ev).To(HaveKeyWithValue("new", "failed")) 864 Expect(ev).To(HaveKeyWithValue("trigger", "ACK doesn't contain ECN marks")) 865 }) 866 867 It("records a generic event", func() { 868 tracer.Debug("foo", "bar") 869 entry := exportAndParseSingle() 870 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 871 Expect(entry.Name).To(Equal("transport:foo")) 872 ev := entry.Event 873 Expect(ev).To(HaveLen(1)) 874 Expect(ev).To(HaveKeyWithValue("details", "bar")) 875 }) 876 }) 877 })