qlog session timeouts

internal/mocks/qlog.go

@@ -51,6 +51,18 @@ func (mr *MockTracerMockRecorder) BufferedPacket(arg0 interface{}) *gomock.Call
 	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "BufferedPacket", reflect.TypeOf((*MockTracer)(nil).BufferedPacket), arg0)
 }
 
+// ClosedConnection mocks base method
+func (m *MockTracer) ClosedConnection(arg0 qlog.CloseReason) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "ClosedConnection", arg0)
+}
+
+// ClosedConnection indicates an expected call of ClosedConnection
+func (mr *MockTracerMockRecorder) ClosedConnection(arg0 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "ClosedConnection", reflect.TypeOf((*MockTracer)(nil).ClosedConnection), arg0)
+}
+
 // DroppedEncryptionLevel mocks base method
 func (m *MockTracer) DroppedEncryptionLevel(arg0 protocol.EncryptionLevel) {
 	m.ctrl.T.Helper()

qlog/event.go

@@ -92,6 +92,19 @@ func (e eventConnectionStarted) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("dst_cid", connectionID(e.DestConnectionID).String())
 }
 
+type eventConnectionClosed struct {
+	Reason CloseReason
+}
+
+func (e eventConnectionClosed) Category() category { return categoryTransport }
+func (e eventConnectionClosed) Name() string       { return "connection_state_updated" }
+func (e eventConnectionClosed) IsNil() bool        { return false }
+
+func (e eventConnectionClosed) MarshalJSONObject(enc *gojay.Encoder) {
+	enc.StringKey("new", "closed")
+	enc.StringKey("trigger", e.Reason.String())
+}
+
 type eventPacketSent struct {
 	PacketType  PacketType
 	Header      packetHeader

qlog/qlog.go

@@ -21,6 +21,7 @@ const eventChanSize = 50
 type Tracer interface {
 	Export() error
 	StartedConnection(local, remote net.Addr, version protocol.VersionNumber, srcConnID, destConnID protocol.ConnectionID)
+	ClosedConnection(CloseReason)
 	SentTransportParameters(*wire.TransportParameters)
 	ReceivedTransportParameters(*wire.TransportParameters)
 	SentPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *wire.AckFrame, frames []wire.Frame)
@@ -154,6 +155,12 @@ func (t *tracer) StartedConnection(local, remote net.Addr, version protocol.Vers
 	t.mutex.Unlock()
 }
 
+func (t *tracer) ClosedConnection(r CloseReason) {
+	t.mutex.Lock()
+	t.recordEvent(time.Now(), &eventConnectionClosed{Reason: r})
+	t.mutex.Unlock()
+}
+
 func (t *tracer) SentTransportParameters(tp *wire.TransportParameters) {
 	t.recordTransportParameters(ownerLocal, tp)
 }

qlog/qlog_test.go

@@ -158,6 +158,17 @@ var _ = Describe("Tracer", func() {
 			Expect(ev).To(HaveKeyWithValue("dst_cid", "05060708"))
 		})
 
+		It("records connection closes", func() {
+			tracer.ClosedConnection(CloseReasonIdleTimeout)
+			entry := exportAndParseSingle()
+			Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond))
+			Expect(entry.Category).To(Equal("transport"))
+			Expect(entry.Name).To(Equal("connection_state_updated"))
+			ev := entry.Event
+			Expect(ev).To(HaveKeyWithValue("new", "closed"))
+			Expect(ev).To(HaveKeyWithValue("trigger", "idle_timeout"))
+		})
+
 		It("records sent transport parameters", func() {
 			tracer.SentTransportParameters(&wire.TransportParameters{
 				InitialMaxStreamDataBidiLocal:  1000,

qlog/types.go

@@ -348,3 +348,26 @@ func (t TimerType) String() string {
 		panic("unknown timer type")
 	}
 }
+
+// CloseReason is the reason why a session is closed
+type CloseReason uint8
+
+const (
+	// CloseReasonHandshakeTimeout is used when the session is closed due to a handshake timeout
+	// This reason is not defined in the qlog draft, but very useful for debugging.
+	CloseReasonHandshakeTimeout CloseReason = iota
+	// CloseReasonIdleTimeout is used when the session is closed due to an idle timeout
+	// This reason is not defined in the qlog draft, but very useful for debugging.
+	CloseReasonIdleTimeout
+)
+
+func (r CloseReason) String() string {
+	switch r {
+	case CloseReasonHandshakeTimeout:
+		return "handshake_timeout"
+	case CloseReasonIdleTimeout:
+		return "idle_timeout"
+	default:
+		panic("unknown close reason")
+	}
+}

qlog/types_test.go

@@ -118,4 +118,9 @@ var _ = Describe("Types", func() {
 		Expect(TimerTypeACK.String()).To(Equal("ack"))
 		Expect(TimerTypePTO.String()).To(Equal("pto"))
 	})
+
+	It("has a string representation for the close reason", func() {
+		Expect(CloseReasonHandshakeTimeout.String()).To(Equal("handshake_timeout"))
+		Expect(CloseReasonIdleTimeout.String()).To(Equal("idle_timeout"))
+	})
 })

session.go

@@ -572,9 +572,15 @@ runLoop:
 			s.framer.QueueControlFrame(&wire.PingFrame{})
 			s.keepAlivePingSent = true
 		} else if !s.handshakeComplete && now.Sub(s.sessionCreationTime) >= s.config.HandshakeTimeout {
+			if s.qlogger != nil {
+				s.qlogger.ClosedConnection(qlog.CloseReasonHandshakeTimeout)
+			}
 			s.destroyImpl(qerr.NewTimeoutError("Handshake did not complete in time"))
 			continue
 		} else if s.handshakeComplete && now.Sub(s.idleTimeoutStartTime()) >= s.idleTimeout {
+			if s.qlogger != nil {
+				s.qlogger.ClosedConnection(qlog.CloseReasonIdleTimeout)
+			}
 			s.destroyImpl(qerr.NewTimeoutError("No recent network activity"))
 			continue
 		} else if !pacingDeadline.IsZero() && now.Before(pacingDeadline) {

session_test.go

@@ -1708,7 +1708,10 @@ var _ = Describe("Session", func() {
 			sess.lastPacketReceivedTime = time.Now().Add(-time.Hour)
 			done := make(chan struct{})
 			cryptoSetup.EXPECT().Close()
-			qlogger.EXPECT().Export()
+			gomock.InOrder(
+				qlogger.EXPECT().ClosedConnection(qlog.CloseReasonIdleTimeout),
+				qlogger.EXPECT().Export(),
+			)
 			go func() {
 				defer GinkgoRecover()
 				cryptoSetup.EXPECT().RunHandshake().MaxTimes(1)
@@ -1727,7 +1730,10 @@ var _ = Describe("Session", func() {
 			sess.sessionCreationTime = time.Now().Add(-protocol.DefaultHandshakeTimeout).Add(-time.Second)
 			sessionRunner.EXPECT().Remove(gomock.Any()).Times(2)
 			cryptoSetup.EXPECT().Close()
-			qlogger.EXPECT().Export()
+			gomock.InOrder(
+				qlogger.EXPECT().ClosedConnection(qlog.CloseReasonHandshakeTimeout),
+				qlogger.EXPECT().Export(),
+			)
 			done := make(chan struct{})
 			go func() {
 				defer GinkgoRecover()
@@ -1775,7 +1781,10 @@ var _ = Describe("Session", func() {
 				sessionRunner.EXPECT().Remove(gomock.Any()),
 			)
 			cryptoSetup.EXPECT().Close()
-			qlogger.EXPECT().Export()
+			gomock.InOrder(
+				qlogger.EXPECT().ClosedConnection(qlog.CloseReasonIdleTimeout),
+				qlogger.EXPECT().Export(),
+			)
 			sess.idleTimeout = 0
 			done := make(chan struct{})
 			go func() {