add support for the connection_closed qlog event

quic-go · Dec 6, 2020 · 2bf6c6a · 2bf6c6a
1 parent 2a52a9f
commit 2bf6c6a
Show file tree

Hide file tree

Showing 3 changed files with 75 additions and 33 deletions.
diff --git a/qlog/event.go b/qlog/event.go
@@ -77,16 +77,42 @@ func (e eventConnectionStarted) MarshalJSONObject(enc *gojay.Encoder) {
 }
 
 type eventConnectionClosed struct {
-	Reason timeoutReason
+	Reason logging.CloseReason
 }
 
 func (e eventConnectionClosed) Category() category { return categoryTransport }
-func (e eventConnectionClosed) Name() string       { return "connection_state_updated" }
+func (e eventConnectionClosed) Name() string       { return "connection_closed" }
 func (e eventConnectionClosed) IsNil() bool        { return false }
 
 func (e eventConnectionClosed) MarshalJSONObject(enc *gojay.Encoder) {
-	enc.StringKey("new", "closed")
-	enc.StringKey("trigger", e.Reason.String())
+	// TODO: add version mismatch
+	if token, ok := e.Reason.StatelessReset(); ok {
+		enc.StringKey("owner", ownerRemote.String())
+		enc.StringKey("trigger", "stateless_reset")
+		enc.StringKey("stateless_reset_token", fmt.Sprintf("%x", token))
+		return
+	}
+	if timeout, ok := e.Reason.Timeout(); ok {
+		enc.StringKey("owner", ownerLocal.String())
+		enc.StringKey("trigger", timeoutReason(timeout).String())
+		return
+	}
+	if code, remote, ok := e.Reason.ApplicationError(); ok {
+		owner := ownerLocal
+		if remote {
+			owner = ownerRemote
+		}
+		enc.StringKey("owner", owner.String())
+		enc.Uint64Key("application_code", uint64(code))
+	}
+	if code, remote, ok := e.Reason.TransportError(); ok {
+		owner := ownerLocal
+		if remote {
+			owner = ownerRemote
+		}
+		enc.StringKey("owner", owner.String())
+		enc.StringKey("connection_code", transportError(code).String())
+	}
 }
 
 type eventPacketSent struct {
@@ -155,19 +181,6 @@ func (e eventVersionNegotiationReceived) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.ArrayKey("supported_versions", versions(e.SupportedVersions))
 }
 
-type eventStatelessResetReceived struct {
-	Token protocol.StatelessResetToken
-}
-
-func (e eventStatelessResetReceived) Category() category { return categoryTransport }
-func (e eventStatelessResetReceived) Name() string       { return "packet_received" }
-func (e eventStatelessResetReceived) IsNil() bool        { return false }
-
-func (e eventStatelessResetReceived) MarshalJSONObject(enc *gojay.Encoder) {
-	enc.StringKey("packet_type", packetType(logging.PacketTypeStatelessReset).String())
-	enc.StringKey("stateless_reset_token", fmt.Sprintf("%x", e.Token))
-}
-
 type eventPacketBuffered struct {
 	PacketType packetType
 }

diff --git a/qlog/qlog.go b/qlog/qlog.go
@@ -9,9 +9,8 @@ import (
 	"sync"
 	"time"
 
-	"github.com/lucas-clemente/quic-go/internal/utils"
-
 	"github.com/lucas-clemente/quic-go/internal/protocol"
+	"github.com/lucas-clemente/quic-go/internal/utils"
 	"github.com/lucas-clemente/quic-go/internal/wire"
 	"github.com/lucas-clemente/quic-go/logging"
 
@@ -157,15 +156,8 @@ func (t *connectionTracer) StartedConnection(local, remote net.Addr, version pro
 
 func (t *connectionTracer) ClosedConnection(r logging.CloseReason) {
 	t.mutex.Lock()
-	defer t.mutex.Unlock()
-
-	if reason, ok := r.Timeout(); ok {
-		t.recordEvent(time.Now(), &eventConnectionClosed{Reason: timeoutReason(reason)})
-	} else if token, ok := r.StatelessReset(); ok {
-		t.recordEvent(time.Now(), &eventStatelessResetReceived{
-			Token: token,
-		})
-	}
+	t.recordEvent(time.Now(), &eventConnectionClosed{Reason: r})
+	t.mutex.Unlock()
 }
 
 func (t *connectionTracer) SentTransportParameters(tp *wire.TransportParameters) {

diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go
@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"github.com/lucas-clemente/quic-go/internal/protocol"
+	"github.com/lucas-clemente/quic-go/internal/qerr"
 	"github.com/lucas-clemente/quic-go/internal/utils"
 	"github.com/lucas-clemente/quic-go/logging"
 
@@ -169,26 +170,62 @@ var _ = Describe("Tracing", func() {
 				Expect(ev).To(HaveKeyWithValue("dst_cid", "05060708"))
 			})
 
-			It("records connection closes", func() {
+			It("records idle timeouts", func() {
 				tracer.ClosedConnection(logging.NewTimeoutCloseReason(logging.TimeoutReasonIdle))
 				entry := exportAndParseSingle()
 				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
-				Expect(entry.Name).To(Equal("transport:connection_state_updated"))
+				Expect(entry.Name).To(Equal("transport:connection_closed"))
 				ev := entry.Event
-				Expect(ev).To(HaveKeyWithValue("new", "closed"))
+				Expect(ev).To(HaveLen(2))
+				Expect(ev).To(HaveKeyWithValue("owner", "local"))
 				Expect(ev).To(HaveKeyWithValue("trigger", "idle_timeout"))
 			})
 
+			It("records handshake timeouts", func() {
+				tracer.ClosedConnection(logging.NewTimeoutCloseReason(logging.TimeoutReasonHandshake))
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("transport:connection_closed"))
+				ev := entry.Event
+				Expect(ev).To(HaveLen(2))
+				Expect(ev).To(HaveKeyWithValue("owner", "local"))
+				Expect(ev).To(HaveKeyWithValue("trigger", "handshake_timeout"))
+			})
+
 			It("records a received stateless reset packet", func() {
 				tracer.ClosedConnection(logging.NewStatelessResetCloseReason(logging.StatelessResetToken{0x00, 0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff}))
 				entry := exportAndParseSingle()
 				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
-				Expect(entry.Name).To(Equal("transport:packet_received"))
+				Expect(entry.Name).To(Equal("transport:connection_closed"))
 				ev := entry.Event
-				Expect(ev).To(HaveKeyWithValue("packet_type", "stateless_reset"))
+				Expect(ev).To(HaveLen(3))
+				Expect(ev).To(HaveKeyWithValue("owner", "remote"))
+				Expect(ev).To(HaveKeyWithValue("trigger", "stateless_reset"))
 				Expect(ev).To(HaveKeyWithValue("stateless_reset_token", "00112233445566778899aabbccddeeff"))
 			})
 
+			It("records application errors", func() {
+				tracer.ClosedConnection(logging.NewApplicationCloseReason(1337, true))
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("transport:connection_closed"))
+				ev := entry.Event
+				Expect(ev).To(HaveLen(2))
+				Expect(ev).To(HaveKeyWithValue("owner", "remote"))
+				Expect(ev).To(HaveKeyWithValue("application_code", float64(1337)))
+			})
+
+			It("records transport errors", func() {
+				tracer.ClosedConnection(logging.NewTransportCloseReason(qerr.AEADLimitReached, false))
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("transport:connection_closed"))
+				ev := entry.Event
+				Expect(ev).To(HaveLen(2))
+				Expect(ev).To(HaveKeyWithValue("owner", "local"))
+				Expect(ev).To(HaveKeyWithValue("connection_code", "aead_limit_reached"))
+			})
+
 			It("records sent transport parameters", func() {
 				tracer.SentTransportParameters(&logging.TransportParameters{
 					InitialMaxStreamDataBidiLocal:   1000,