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