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