diff --git a/internal/mocks/qlog.go b/internal/mocks/qlog.go index ba4a7474b..a12feadff 100644 --- a/internal/mocks/qlog.go +++ b/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() diff --git a/qlog/event.go b/qlog/event.go index b77076789..969d0243e 100644 --- a/qlog/event.go +++ b/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 diff --git a/qlog/qlog.go b/qlog/qlog.go index 9276b070c..b609c19b0 100644 --- a/qlog/qlog.go +++ b/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) } diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index 6ab985e64..2b9130710 100644 --- a/qlog/qlog_test.go +++ b/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, diff --git a/qlog/types.go b/qlog/types.go index 041e416de..07b4a1187 100644 --- a/qlog/types.go +++ b/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") + } +} diff --git a/qlog/types_test.go b/qlog/types_test.go index ad8a6b5a5..4d1eb9fbf 100644 --- a/qlog/types_test.go +++ b/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")) + }) }) diff --git a/session.go b/session.go index 3ff5d9b43..58b389acc 100644 --- a/session.go +++ b/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) { diff --git a/session_test.go b/session_test.go index b04a02fd1..f8ed2918d 100644 --- a/session_test.go +++ b/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() {