github.com/tumi8/quic-go@v0.37.4-tum/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/tumi8/quic-go" 14 "github.com/tumi8/quic-go/noninternal/protocol" 15 "github.com/tumi8/quic-go/noninternal/qerr" 16 "github.com/tumi8/quic-go/noninternal/utils" 17 "github.com/tumi8/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 nil, 423 []logging.Frame{ 424 &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, 425 &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, 426 }, 427 ) 428 entry := exportAndParseSingle() 429 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 430 Expect(entry.Name).To(Equal("transport:packet_sent")) 431 ev := entry.Event 432 Expect(ev).To(HaveKey("raw")) 433 raw := ev["raw"].(map[string]interface{}) 434 Expect(raw).To(HaveKeyWithValue("length", float64(987))) 435 Expect(raw).To(HaveKeyWithValue("payload_length", float64(1337))) 436 Expect(ev).To(HaveKey("header")) 437 hdr := ev["header"].(map[string]interface{}) 438 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 439 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 440 Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) 441 Expect(ev).To(HaveKey("frames")) 442 frames := ev["frames"].([]interface{}) 443 Expect(frames).To(HaveLen(2)) 444 Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_stream_data")) 445 Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream")) 446 }) 447 448 It("records a sent short header packet, without an ACK", func() { 449 tracer.SentShortHeaderPacket( 450 &logging.ShortHeader{ 451 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4}), 452 PacketNumber: 1337, 453 }, 454 123, 455 &logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}}, 456 []logging.Frame{&logging.MaxDataFrame{MaximumData: 987}}, 457 ) 458 entry := exportAndParseSingle() 459 ev := entry.Event 460 raw := ev["raw"].(map[string]interface{}) 461 Expect(raw).To(HaveKeyWithValue("length", float64(123))) 462 Expect(raw).ToNot(HaveKey("payload_length")) 463 Expect(ev).To(HaveKey("header")) 464 hdr := ev["header"].(map[string]interface{}) 465 Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) 466 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 467 Expect(ev).To(HaveKey("frames")) 468 frames := ev["frames"].([]interface{}) 469 Expect(frames).To(HaveLen(2)) 470 Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "ack")) 471 Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_data")) 472 }) 473 474 It("records a received Long Header packet", func() { 475 tracer.ReceivedLongHeaderPacket( 476 &logging.ExtendedHeader{ 477 Header: logging.Header{ 478 Type: protocol.PacketTypeInitial, 479 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 480 SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), 481 Token: []byte{0xde, 0xad, 0xbe, 0xef}, 482 Length: 1234, 483 Version: protocol.Version1, 484 }, 485 PacketNumber: 1337, 486 }, 487 789, 488 []logging.Frame{ 489 &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, 490 &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, 491 }, 492 ) 493 entry := exportAndParseSingle() 494 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 495 Expect(entry.Name).To(Equal("transport:packet_received")) 496 ev := entry.Event 497 Expect(ev).To(HaveKey("raw")) 498 raw := ev["raw"].(map[string]interface{}) 499 Expect(raw).To(HaveKeyWithValue("length", float64(789))) 500 Expect(raw).To(HaveKeyWithValue("payload_length", float64(1234))) 501 Expect(ev).To(HaveKey("header")) 502 hdr := ev["header"].(map[string]interface{}) 503 Expect(hdr).To(HaveKeyWithValue("packet_type", "initial")) 504 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 505 Expect(hdr).To(HaveKeyWithValue("scid", "04030201")) 506 Expect(hdr).To(HaveKey("token")) 507 token := hdr["token"].(map[string]interface{}) 508 Expect(token).To(HaveKeyWithValue("data", "deadbeef")) 509 Expect(ev).To(HaveKey("frames")) 510 Expect(ev["frames"].([]interface{})).To(HaveLen(2)) 511 }) 512 513 It("records a received Short Header packet", func() { 514 shdr := &logging.ShortHeader{ 515 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 516 PacketNumber: 1337, 517 PacketNumberLen: protocol.PacketNumberLen3, 518 KeyPhase: protocol.KeyPhaseZero, 519 } 520 tracer.ReceivedShortHeaderPacket( 521 shdr, 522 789, 523 []logging.Frame{ 524 &logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987}, 525 &logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true}, 526 }, 527 ) 528 entry := exportAndParseSingle() 529 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 530 Expect(entry.Name).To(Equal("transport:packet_received")) 531 ev := entry.Event 532 Expect(ev).To(HaveKey("raw")) 533 raw := ev["raw"].(map[string]interface{}) 534 Expect(raw).To(HaveKeyWithValue("length", float64(789))) 535 Expect(raw).To(HaveKeyWithValue("payload_length", float64(789-(1+8+3)))) 536 Expect(ev).To(HaveKey("header")) 537 hdr := ev["header"].(map[string]interface{}) 538 Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT")) 539 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337))) 540 Expect(hdr).To(HaveKeyWithValue("key_phase_bit", "0")) 541 Expect(ev).To(HaveKey("frames")) 542 Expect(ev["frames"].([]interface{})).To(HaveLen(2)) 543 }) 544 545 It("records a received Retry packet", func() { 546 tracer.ReceivedRetry( 547 &logging.Header{ 548 Type: protocol.PacketTypeRetry, 549 DestConnectionID: protocol.ParseConnectionID([]byte{1, 2, 3, 4, 5, 6, 7, 8}), 550 SrcConnectionID: protocol.ParseConnectionID([]byte{4, 3, 2, 1}), 551 Token: []byte{0xde, 0xad, 0xbe, 0xef}, 552 Version: protocol.Version1, 553 }, 554 ) 555 entry := exportAndParseSingle() 556 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 557 Expect(entry.Name).To(Equal("transport:packet_received")) 558 ev := entry.Event 559 Expect(ev).ToNot(HaveKey("raw")) 560 Expect(ev).To(HaveKey("header")) 561 header := ev["header"].(map[string]interface{}) 562 Expect(header).To(HaveKeyWithValue("packet_type", "retry")) 563 Expect(header).ToNot(HaveKey("packet_number")) 564 Expect(header).To(HaveKey("version")) 565 Expect(header).To(HaveKey("dcid")) 566 Expect(header).To(HaveKey("scid")) 567 Expect(header).To(HaveKey("token")) 568 token := header["token"].(map[string]interface{}) 569 Expect(token).To(HaveKeyWithValue("data", "deadbeef")) 570 Expect(ev).ToNot(HaveKey("frames")) 571 }) 572 573 It("records a received Version Negotiation packet", func() { 574 tracer.ReceivedVersionNegotiationPacket( 575 protocol.ArbitraryLenConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, 576 protocol.ArbitraryLenConnectionID{4, 3, 2, 1}, 577 []protocol.VersionNumber{0xdeadbeef, 0xdecafbad}, 578 ) 579 entry := exportAndParseSingle() 580 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 581 Expect(entry.Name).To(Equal("transport:packet_received")) 582 ev := entry.Event 583 Expect(ev).To(HaveKey("header")) 584 Expect(ev).ToNot(HaveKey("frames")) 585 Expect(ev).To(HaveKey("supported_versions")) 586 Expect(ev["supported_versions"].([]interface{})).To(Equal([]interface{}{"deadbeef", "decafbad"})) 587 header := ev["header"] 588 Expect(header).To(HaveKeyWithValue("packet_type", "version_negotiation")) 589 Expect(header).ToNot(HaveKey("packet_number")) 590 Expect(header).ToNot(HaveKey("version")) 591 Expect(header).To(HaveKeyWithValue("dcid", "0102030405060708")) 592 Expect(header).To(HaveKeyWithValue("scid", "04030201")) 593 }) 594 595 It("records buffered packets", func() { 596 tracer.BufferedPacket(logging.PacketTypeHandshake, 1337) 597 entry := exportAndParseSingle() 598 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 599 Expect(entry.Name).To(Equal("transport:packet_buffered")) 600 ev := entry.Event 601 Expect(ev).To(HaveKey("header")) 602 hdr := ev["header"].(map[string]interface{}) 603 Expect(hdr).To(HaveLen(1)) 604 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 605 Expect(ev).To(HaveKey("raw")) 606 Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) 607 Expect(ev).To(HaveKeyWithValue("trigger", "keys_unavailable")) 608 }) 609 610 It("records dropped packets", func() { 611 tracer.DroppedPacket(logging.PacketTypeHandshake, 1337, logging.PacketDropPayloadDecryptError) 612 entry := exportAndParseSingle() 613 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 614 Expect(entry.Name).To(Equal("transport:packet_dropped")) 615 ev := entry.Event 616 Expect(ev).To(HaveKey("raw")) 617 Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337))) 618 Expect(ev).To(HaveKey("header")) 619 hdr := ev["header"].(map[string]interface{}) 620 Expect(hdr).To(HaveLen(1)) 621 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 622 Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error")) 623 }) 624 625 It("records metrics updates", func() { 626 now := time.Now() 627 rttStats := utils.NewRTTStats() 628 rttStats.UpdateRTT(15*time.Millisecond, 0, now) 629 rttStats.UpdateRTT(20*time.Millisecond, 0, now) 630 rttStats.UpdateRTT(25*time.Millisecond, 0, now) 631 Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) 632 Expect(rttStats.SmoothedRTT()).To(And( 633 BeNumerically(">", 15*time.Millisecond), 634 BeNumerically("<", 25*time.Millisecond), 635 )) 636 Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) 637 tracer.UpdatedMetrics( 638 rttStats, 639 4321, 640 1234, 641 42, 642 ) 643 entry := exportAndParseSingle() 644 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 645 Expect(entry.Name).To(Equal("recovery:metrics_updated")) 646 ev := entry.Event 647 Expect(ev).To(HaveKeyWithValue("min_rtt", float64(15))) 648 Expect(ev).To(HaveKeyWithValue("latest_rtt", float64(25))) 649 Expect(ev).To(HaveKey("smoothed_rtt")) 650 Expect(time.Duration(ev["smoothed_rtt"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.SmoothedRTT(), time.Millisecond)) 651 Expect(ev).To(HaveKey("rtt_variance")) 652 Expect(time.Duration(ev["rtt_variance"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.MeanDeviation(), time.Millisecond)) 653 Expect(ev).To(HaveKeyWithValue("congestion_window", float64(4321))) 654 Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(1234))) 655 Expect(ev).To(HaveKeyWithValue("packets_in_flight", float64(42))) 656 }) 657 658 It("only logs the diff between two metrics updates", func() { 659 now := time.Now() 660 rttStats := utils.NewRTTStats() 661 rttStats.UpdateRTT(15*time.Millisecond, 0, now) 662 rttStats.UpdateRTT(20*time.Millisecond, 0, now) 663 rttStats.UpdateRTT(25*time.Millisecond, 0, now) 664 Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) 665 666 rttStats2 := utils.NewRTTStats() 667 rttStats2.UpdateRTT(15*time.Millisecond, 0, now) 668 rttStats2.UpdateRTT(15*time.Millisecond, 0, now) 669 rttStats2.UpdateRTT(15*time.Millisecond, 0, now) 670 Expect(rttStats2.MinRTT()).To(Equal(15 * time.Millisecond)) 671 672 Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) 673 tracer.UpdatedMetrics( 674 rttStats, 675 4321, 676 1234, 677 42, 678 ) 679 tracer.UpdatedMetrics( 680 rttStats2, 681 4321, 682 12345, // changed 683 42, 684 ) 685 entries := exportAndParse() 686 Expect(entries).To(HaveLen(2)) 687 Expect(entries[0].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 688 Expect(entries[0].Name).To(Equal("recovery:metrics_updated")) 689 Expect(entries[0].Event).To(HaveLen(7)) 690 Expect(entries[1].Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 691 Expect(entries[1].Name).To(Equal("recovery:metrics_updated")) 692 ev := entries[1].Event 693 Expect(ev).ToNot(HaveKey("min_rtt")) 694 Expect(ev).ToNot(HaveKey("congestion_window")) 695 Expect(ev).ToNot(HaveKey("packets_in_flight")) 696 Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(12345))) 697 Expect(ev).To(HaveKeyWithValue("smoothed_rtt", float64(15))) 698 }) 699 700 It("records lost packets", func() { 701 tracer.LostPacket(protocol.EncryptionHandshake, 42, logging.PacketLossReorderingThreshold) 702 entry := exportAndParseSingle() 703 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 704 Expect(entry.Name).To(Equal("recovery:packet_lost")) 705 ev := entry.Event 706 Expect(ev).To(HaveKey("header")) 707 hdr := ev["header"].(map[string]interface{}) 708 Expect(hdr).To(HaveLen(2)) 709 Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake")) 710 Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42))) 711 Expect(ev).To(HaveKeyWithValue("trigger", "reordering_threshold")) 712 }) 713 714 It("records congestion state updates", func() { 715 tracer.UpdatedCongestionState(logging.CongestionStateCongestionAvoidance) 716 entry := exportAndParseSingle() 717 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 718 Expect(entry.Name).To(Equal("recovery:congestion_state_updated")) 719 ev := entry.Event 720 Expect(ev).To(HaveKeyWithValue("new", "congestion_avoidance")) 721 }) 722 723 It("records PTO changes", func() { 724 tracer.UpdatedPTOCount(42) 725 entry := exportAndParseSingle() 726 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 727 Expect(entry.Name).To(Equal("recovery:metrics_updated")) 728 Expect(entry.Event).To(HaveKeyWithValue("pto_count", float64(42))) 729 }) 730 731 It("records TLS key updates", func() { 732 tracer.UpdatedKeyFromTLS(protocol.EncryptionHandshake, protocol.PerspectiveClient) 733 entry := exportAndParseSingle() 734 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 735 Expect(entry.Name).To(Equal("security:key_updated")) 736 ev := entry.Event 737 Expect(ev).To(HaveKeyWithValue("key_type", "client_handshake_secret")) 738 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 739 Expect(ev).ToNot(HaveKey("generation")) 740 Expect(ev).ToNot(HaveKey("old")) 741 Expect(ev).ToNot(HaveKey("new")) 742 }) 743 744 It("records TLS key updates, for 1-RTT keys", func() { 745 tracer.UpdatedKeyFromTLS(protocol.Encryption1RTT, protocol.PerspectiveServer) 746 entry := exportAndParseSingle() 747 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 748 Expect(entry.Name).To(Equal("security:key_updated")) 749 ev := entry.Event 750 Expect(ev).To(HaveKeyWithValue("key_type", "server_1rtt_secret")) 751 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 752 Expect(ev).To(HaveKeyWithValue("generation", float64(0))) 753 Expect(ev).ToNot(HaveKey("old")) 754 Expect(ev).ToNot(HaveKey("new")) 755 }) 756 757 It("records QUIC key updates", func() { 758 tracer.UpdatedKey(1337, true) 759 entries := exportAndParse() 760 Expect(entries).To(HaveLen(2)) 761 var keyTypes []string 762 for _, entry := range entries { 763 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 764 Expect(entry.Name).To(Equal("security:key_updated")) 765 ev := entry.Event 766 Expect(ev).To(HaveKeyWithValue("generation", float64(1337))) 767 Expect(ev).To(HaveKeyWithValue("trigger", "remote_update")) 768 Expect(ev).To(HaveKey("key_type")) 769 keyTypes = append(keyTypes, ev["key_type"].(string)) 770 } 771 Expect(keyTypes).To(ContainElement("server_1rtt_secret")) 772 Expect(keyTypes).To(ContainElement("client_1rtt_secret")) 773 }) 774 775 It("records dropped encryption levels", func() { 776 tracer.DroppedEncryptionLevel(protocol.EncryptionInitial) 777 entries := exportAndParse() 778 Expect(entries).To(HaveLen(2)) 779 var keyTypes []string 780 for _, entry := range entries { 781 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 782 Expect(entry.Name).To(Equal("security:key_discarded")) 783 ev := entry.Event 784 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 785 Expect(ev).To(HaveKey("key_type")) 786 keyTypes = append(keyTypes, ev["key_type"].(string)) 787 } 788 Expect(keyTypes).To(ContainElement("server_initial_secret")) 789 Expect(keyTypes).To(ContainElement("client_initial_secret")) 790 }) 791 792 It("records dropped 0-RTT keys", func() { 793 tracer.DroppedEncryptionLevel(protocol.Encryption0RTT) 794 entries := exportAndParse() 795 Expect(entries).To(HaveLen(1)) 796 entry := entries[0] 797 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 798 Expect(entry.Name).To(Equal("security:key_discarded")) 799 ev := entry.Event 800 Expect(ev).To(HaveKeyWithValue("trigger", "tls")) 801 Expect(ev).To(HaveKeyWithValue("key_type", "server_0rtt_secret")) 802 }) 803 804 It("records dropped keys", func() { 805 tracer.DroppedKey(42) 806 entries := exportAndParse() 807 Expect(entries).To(HaveLen(2)) 808 var keyTypes []string 809 for _, entry := range entries { 810 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 811 Expect(entry.Name).To(Equal("security:key_discarded")) 812 ev := entry.Event 813 Expect(ev).To(HaveKeyWithValue("generation", float64(42))) 814 Expect(ev).ToNot(HaveKey("trigger")) 815 Expect(ev).To(HaveKey("key_type")) 816 keyTypes = append(keyTypes, ev["key_type"].(string)) 817 } 818 Expect(keyTypes).To(ContainElement("server_1rtt_secret")) 819 Expect(keyTypes).To(ContainElement("client_1rtt_secret")) 820 }) 821 822 It("records when the timer is set", func() { 823 timeout := time.Now().Add(137 * time.Millisecond) 824 tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout) 825 entry := exportAndParseSingle() 826 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 827 Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) 828 ev := entry.Event 829 Expect(ev).To(HaveLen(4)) 830 Expect(ev).To(HaveKeyWithValue("event_type", "set")) 831 Expect(ev).To(HaveKeyWithValue("timer_type", "pto")) 832 Expect(ev).To(HaveKeyWithValue("packet_number_space", "handshake")) 833 Expect(ev).To(HaveKey("delta")) 834 delta := time.Duration(ev["delta"].(float64)*1e6) * time.Nanosecond 835 Expect(entry.Time.Add(delta)).To(BeTemporally("~", timeout, scaleDuration(10*time.Microsecond))) 836 }) 837 838 It("records when the loss timer expires", func() { 839 tracer.LossTimerExpired(logging.TimerTypeACK, protocol.Encryption1RTT) 840 entry := exportAndParseSingle() 841 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 842 Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) 843 ev := entry.Event 844 Expect(ev).To(HaveLen(3)) 845 Expect(ev).To(HaveKeyWithValue("event_type", "expired")) 846 Expect(ev).To(HaveKeyWithValue("timer_type", "ack")) 847 Expect(ev).To(HaveKeyWithValue("packet_number_space", "application_data")) 848 }) 849 850 It("records when the timer is canceled", func() { 851 tracer.LossTimerCanceled() 852 entry := exportAndParseSingle() 853 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 854 Expect(entry.Name).To(Equal("recovery:loss_timer_updated")) 855 ev := entry.Event 856 Expect(ev).To(HaveLen(1)) 857 Expect(ev).To(HaveKeyWithValue("event_type", "cancelled")) 858 }) 859 860 It("records a generic event", func() { 861 tracer.Debug("foo", "bar") 862 entry := exportAndParseSingle() 863 Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond))) 864 Expect(entry.Name).To(Equal("transport:foo")) 865 ev := entry.Event 866 Expect(ev).To(HaveLen(1)) 867 Expect(ev).To(HaveKeyWithValue("details", "bar")) 868 }) 869 }) 870 }) 871 })