add tracing and qlogging of state transitions for ECN validation

internal/mocks/logging/connection_tracer.go

@@ -135,6 +135,18 @@ func (mr *MockConnectionTracerMockRecorder) DroppedPacket(arg0, arg1, arg2 inter
 	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedPacket", reflect.TypeOf((*MockConnectionTracer)(nil).DroppedPacket), arg0, arg1, arg2)
 }
 
+// ECNStateUpdated mocks base method.
+func (m *MockConnectionTracer) ECNStateUpdated(arg0 logging.ECNState, arg1 logging.ECNStateTrigger) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "ECNStateUpdated", arg0, arg1)
+}
+
+// ECNStateUpdated indicates an expected call of ECNStateUpdated.
+func (mr *MockConnectionTracerMockRecorder) ECNStateUpdated(arg0, arg1 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "ECNStateUpdated", reflect.TypeOf((*MockConnectionTracer)(nil).ECNStateUpdated), arg0, arg1)
+}
+
 // LossTimerCanceled mocks base method.
 func (m *MockConnectionTracer) LossTimerCanceled() {
 	m.ctrl.T.Helper()

logging/interface.go

@@ -148,6 +148,7 @@ type ConnectionTracer interface {
 	SetLossTimer(TimerType, EncryptionLevel, time.Time)
 	LossTimerExpired(TimerType, EncryptionLevel)
 	LossTimerCanceled()
+	ECNStateUpdated(state ECNState, trigger ECNStateTrigger)
 	// Close is called when the connection is closed.
 	Close()
 	Debug(name, msg string)

logging/mock_connection_tracer_test.go

@@ -134,6 +134,18 @@ func (mr *MockConnectionTracerMockRecorder) DroppedPacket(arg0, arg1, arg2 inter
 	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedPacket", reflect.TypeOf((*MockConnectionTracer)(nil).DroppedPacket), arg0, arg1, arg2)
 }
 
+// ECNStateUpdated mocks base method.
+func (m *MockConnectionTracer) ECNStateUpdated(arg0 ECNState, arg1 ECNStateTrigger) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "ECNStateUpdated", arg0, arg1)
+}
+
+// ECNStateUpdated indicates an expected call of ECNStateUpdated.
+func (mr *MockConnectionTracerMockRecorder) ECNStateUpdated(arg0, arg1 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "ECNStateUpdated", reflect.TypeOf((*MockConnectionTracer)(nil).ECNStateUpdated), arg0, arg1)
+}
+
 // LossTimerCanceled mocks base method.
 func (m *MockConnectionTracer) LossTimerCanceled() {
 	m.ctrl.T.Helper()

logging/multiplex.go

@@ -213,6 +213,12 @@ func (m *connTracerMultiplexer) LossTimerCanceled() {
 	}
 }
 
+func (m *connTracerMultiplexer) ECNStateUpdated(state ECNState, trigger ECNStateTrigger) {
+	for _, t := range m.tracers {
+		t.ECNStateUpdated(state, trigger)
+	}
+}
+
 func (m *connTracerMultiplexer) Debug(name, msg string) {
 	for _, t := range m.tracers {
 		t.Debug(name, msg)

logging/null_tracer.go

@@ -47,16 +47,17 @@ func (n NullConnectionTracer) DroppedPacket(PacketType, ByteCount, PacketDropRea
 
 func (n NullConnectionTracer) UpdatedMetrics(rttStats *RTTStats, cwnd, bytesInFlight ByteCount, packetsInFlight int) {
 }
-func (n NullConnectionTracer) AcknowledgedPacket(EncryptionLevel, PacketNumber)            {}
-func (n NullConnectionTracer) LostPacket(EncryptionLevel, PacketNumber, PacketLossReason)  {}
-func (n NullConnectionTracer) UpdatedCongestionState(CongestionState)                      {}
-func (n NullConnectionTracer) UpdatedPTOCount(uint32)                                      {}
-func (n NullConnectionTracer) UpdatedKeyFromTLS(EncryptionLevel, Perspective)              {}
-func (n NullConnectionTracer) UpdatedKey(keyPhase KeyPhase, remote bool)                   {}
-func (n NullConnectionTracer) DroppedEncryptionLevel(EncryptionLevel)                      {}
-func (n NullConnectionTracer) DroppedKey(KeyPhase)                                         {}
-func (n NullConnectionTracer) SetLossTimer(TimerType, EncryptionLevel, time.Time)          {}
-func (n NullConnectionTracer) LossTimerExpired(timerType TimerType, level EncryptionLevel) {}
-func (n NullConnectionTracer) LossTimerCanceled()                                          {}
-func (n NullConnectionTracer) Close()                                                      {}
-func (n NullConnectionTracer) Debug(name, msg string)                                      {}
+func (n NullConnectionTracer) AcknowledgedPacket(EncryptionLevel, PacketNumber)           {}
+func (n NullConnectionTracer) LostPacket(EncryptionLevel, PacketNumber, PacketLossReason) {}
+func (n NullConnectionTracer) UpdatedCongestionState(CongestionState)                     {}
+func (n NullConnectionTracer) UpdatedPTOCount(uint32)                                     {}
+func (n NullConnectionTracer) UpdatedKeyFromTLS(EncryptionLevel, Perspective)             {}
+func (n NullConnectionTracer) UpdatedKey(keyPhase KeyPhase, remote bool)                  {}
+func (n NullConnectionTracer) DroppedEncryptionLevel(EncryptionLevel)                     {}
+func (n NullConnectionTracer) DroppedKey(KeyPhase)                                        {}
+func (n NullConnectionTracer) SetLossTimer(TimerType, EncryptionLevel, time.Time)         {}
+func (n NullConnectionTracer) LossTimerExpired(TimerType, EncryptionLevel)                {}
+func (n NullConnectionTracer) LossTimerCanceled()                                         {}
+func (n NullConnectionTracer) ECNStateUpdated(ECNState, ECNStateTrigger)                  {}
+func (n NullConnectionTracer) Close()                                                     {}
+func (n NullConnectionTracer) Debug(name, msg string)                                     {}

logging/types.go

@@ -92,3 +92,35 @@ const (
 	// CongestionStateApplicationLimited means that the congestion controller is application limited
 	CongestionStateApplicationLimited
 )
+
+// ECNState is the state of the ECN state machine (see Appendix A.4 of RFC 9000)
+type ECNState uint8
+
+const (
+	// ECNStateTesting is the testing state
+	ECNStateTesting ECNState = 1 + iota
+	// ECNStateUnknown is the unknown state
+	ECNStateUnknown
+	// ECNStateFailed is the failed state
+	ECNStateFailed
+	// ECNStateCapable is the capable state
+	ECNStateCapable
+)
+
+// ECNStateTrigger is a trigger for an ECN state transition.
+type ECNStateTrigger uint8
+
+const (
+	ECNTriggerNoTrigger ECNStateTrigger = iota
+	// ECNFailedNoECNCounts is emitted when an ACK acknowledges ECN-marked packets,
+	// but doesn't contain any ECN counts
+	ECNFailedNoECNCounts
+	// ECNFailedDecreasedECNCounts is emitted when an ACK frame decreases ECN counts
+	ECNFailedDecreasedECNCounts
+	// ECNFailedLostAllTestingPackets is emitted when all ECN testing packets are declared lost
+	ECNFailedLostAllTestingPackets
+	// ECNFailedMoreECNCountsThanSent is emitted when an ACK contains more ECN counts than ECN-marked packets were sent
+	ECNFailedMoreECNCountsThanSent
+	// ECNFailedTooFewECNCounts is emitted when contains fewer ECT(0) / ECT(1) counts than it acknowledges packets
+	ECNFailedTooFewECNCounts
+)

qlog/event.go

@@ -524,6 +524,20 @@ func (e eventCongestionStateUpdated) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("new", e.state.String())
 }
 
+type eventECNStateUpdated struct {
+	state   logging.ECNState
+	trigger logging.ECNStateTrigger
+}
+
+func (e eventECNStateUpdated) Category() category { return categoryRecovery }
+func (e eventECNStateUpdated) Name() string       { return "ecn_state_updated" }
+func (e eventECNStateUpdated) IsNil() bool        { return false }
+
+func (e eventECNStateUpdated) MarshalJSONObject(enc *gojay.Encoder) {
+	enc.StringKey("new", ecnState(e.state).String())
+	enc.StringKeyOmitEmpty("trigger", ecnStateTrigger(e.trigger).String())
+}
+
 type eventGeneric struct {
 	name string
 	msg  string

qlog/qlog.go

@@ -503,6 +503,12 @@ func (t *connectionTracer) LossTimerCanceled() {
 	t.mutex.Unlock()
 }
 
+func (t *connectionTracer) ECNStateUpdated(state logging.ECNState, trigger logging.ECNStateTrigger) {
+	t.mutex.Lock()
+	t.recordEvent(time.Now(), &eventECNStateUpdated{state: state, trigger: trigger})
+	t.mutex.Unlock()
+}
+
 func (t *connectionTracer) Debug(name, msg string) {
 	t.mutex.Lock()
 	t.recordEvent(time.Now(), &eventGeneric{

qlog/qlog_test.go

@@ -865,6 +865,27 @@ var _ = Describe("Tracing", func() {
 				Expect(ev).To(HaveKeyWithValue("event_type", "cancelled"))
 			})
 
+			It("records an ECN state transition, without a trigger", func() {
+				tracer.ECNStateUpdated(logging.ECNStateUnknown, logging.ECNTriggerNoTrigger)
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("recovery:ecn_state_updated"))
+				ev := entry.Event
+				Expect(ev).To(HaveLen(1))
+				Expect(ev).To(HaveKeyWithValue("new", "unknown"))
+			})
+
+			It("records an ECN state transition, with a trigger", func() {
+				tracer.ECNStateUpdated(logging.ECNStateFailed, logging.ECNFailedNoECNCounts)
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("recovery:ecn_state_updated"))
+				ev := entry.Event
+				Expect(ev).To(HaveLen(2))
+				Expect(ev).To(HaveKeyWithValue("new", "failed"))
+				Expect(ev).To(HaveKeyWithValue("trigger", "ACK doesn't contain ECN marks"))
+			})
+
 			It("records a generic event", func() {
 				tracer.Debug("foo", "bar")
 				entry := exportAndParseSingle()

qlog/types.go

@@ -330,3 +330,41 @@ func (e ecn) String() string {
 		return "unknown ECN"
 	}
 }
+
+type ecnState logging.ECNState
+
+func (e ecnState) String() string {
+	switch logging.ECNState(e) {
+	case logging.ECNStateTesting:
+		return "testing"
+	case logging.ECNStateUnknown:
+		return "unknown"
+	case logging.ECNStateCapable:
+		return "capable"
+	case logging.ECNStateFailed:
+		return "failed"
+	default:
+		return "unknown ECN state"
+	}
+}
+
+type ecnStateTrigger logging.ECNStateTrigger
+
+func (e ecnStateTrigger) String() string {
+	switch logging.ECNStateTrigger(e) {
+	case logging.ECNTriggerNoTrigger:
+		return ""
+	case logging.ECNFailedNoECNCounts:
+		return "ACK doesn't contain ECN marks"
+	case logging.ECNFailedDecreasedECNCounts:
+		return "ACK decreases ECN counts"
+	case logging.ECNFailedLostAllTestingPackets:
+		return "all ECN testing packets declared lost"
+	case logging.ECNFailedMoreECNCountsThanSent:
+		return "ACK contains more ECN counts than ECN-marked packets sent"
+	case logging.ECNFailedTooFewECNCounts:
+		return "ACK contains fewer new ECN counts than acknowledged ECN-marked packets"
+	default:
+		return "unknown ECN state trigger"
+	}
+}

qlog/types_test.go

@@ -135,4 +135,22 @@ var _ = Describe("Types", func() {
 		Expect(ecn(logging.ECTNot).String()).To(Equal("Not-ECT"))
 		Expect(ecn(42).String()).To(Equal("unknown ECN"))
 	})
+
+	It("has a string representation for the ECN state", func() {
+		Expect(ecnState(logging.ECNStateTesting).String()).To(Equal("testing"))
+		Expect(ecnState(logging.ECNStateUnknown).String()).To(Equal("unknown"))
+		Expect(ecnState(logging.ECNStateFailed).String()).To(Equal("failed"))
+		Expect(ecnState(logging.ECNStateCapable).String()).To(Equal("capable"))
+		Expect(ecnState(42).String()).To(Equal("unknown ECN state"))
+	})
+
+	It("has a string representation for the ECN state trigger", func() {
+		Expect(ecnStateTrigger(logging.ECNTriggerNoTrigger).String()).To(Equal(""))
+		Expect(ecnStateTrigger(logging.ECNFailedNoECNCounts).String()).To(Equal("ACK doesn't contain ECN marks"))
+		Expect(ecnStateTrigger(logging.ECNFailedDecreasedECNCounts).String()).To(Equal("ACK decreases ECN counts"))
+		Expect(ecnStateTrigger(logging.ECNFailedLostAllTestingPackets).String()).To(Equal("all ECN testing packets declared lost"))
+		Expect(ecnStateTrigger(logging.ECNFailedMoreECNCountsThanSent).String()).To(Equal("ACK contains more ECN counts than ECN-marked packets sent"))
+		Expect(ecnStateTrigger(logging.ECNFailedTooFewECNCounts).String()).To(Equal("ACK contains fewer new ECN counts than acknowledged ECN-marked packets"))
+		Expect(ecnStateTrigger(42).String()).To(Equal("unknown ECN state trigger"))
+	})
 })