qlog: add support for alpn_information event (#4216)

* qlog chosen alpn

* qlog chosen alpn

* qlog: fix capitalization of ALPN

---------

Co-authored-by: Marten Seemann <martenseemann@gmail.com>

connection.go

@@ -731,6 +731,10 @@ func (s *connection) handleHandshakeComplete() error {
 	s.connIDManager.SetHandshakeComplete()
 	s.connIDGenerator.SetHandshakeComplete()
 
+	if s.tracer != nil && s.tracer.ChoseALPN != nil {
+		s.tracer.ChoseALPN(s.cryptoStreamHandler.ConnectionState().NegotiatedProtocol)
+	}
+
 	// The server applies transport parameters right away, but the client side has to wait for handshake completion.
 	// During a 0-RTT connection, the client is only allowed to use the new transport parameters for 1-RTT packets.
 	if s.perspective == protocol.PerspectiveClient {

connection_test.go

@@ -1946,6 +1946,7 @@ var _ = Describe("Connection", func() {
 		sph := mockackhandler.NewMockSentPacketHandler(mockCtrl)
 		conn.sentPacketHandler = sph
 		tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake)
+		tracer.EXPECT().ChoseALPN(gomock.Any())
 		sph.EXPECT().GetLossDetectionTimeout().AnyTimes()
 		sph.EXPECT().TimeUntilSend().AnyTimes()
 		sph.EXPECT().SendMode(gomock.Any()).AnyTimes()
@@ -1954,6 +1955,7 @@ var _ = Describe("Connection", func() {
 		connRunner.EXPECT().Retire(clientDestConnID)
 		cryptoSetup.EXPECT().SetHandshakeConfirmed()
 		cryptoSetup.EXPECT().GetSessionTicket()
+		cryptoSetup.EXPECT().ConnectionState()
 		handshakeCtx := conn.HandshakeComplete()
 		Consistently(handshakeCtx).ShouldNot(BeClosed())
 		Expect(conn.handleHandshakeComplete()).To(Succeed())
@@ -1966,8 +1968,10 @@ var _ = Describe("Connection", func() {
 		connRunner.EXPECT().Retire(clientDestConnID)
 		conn.sentPacketHandler.DropPackets(protocol.EncryptionInitial)
 		tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake)
+		tracer.EXPECT().ChoseALPN(gomock.Any())
 		cryptoSetup.EXPECT().SetHandshakeConfirmed()
 		cryptoSetup.EXPECT().GetSessionTicket().Return(make([]byte, size), nil)
+		cryptoSetup.EXPECT().ConnectionState()
 
 		handshakeCtx := conn.HandshakeComplete()
 		Consistently(handshakeCtx).ShouldNot(BeClosed())
@@ -2021,6 +2025,7 @@ var _ = Describe("Connection", func() {
 		sph.EXPECT().SentPacket(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any())
 		mconn.EXPECT().Write(gomock.Any(), gomock.Any(), gomock.Any())
 		tracer.EXPECT().SentShortHeaderPacket(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any())
+		tracer.EXPECT().ChoseALPN(gomock.Any())
 		conn.sentPacketHandler = sph
 		done := make(chan struct{})
 		connRunner.EXPECT().Retire(clientDestConnID)
@@ -2041,6 +2046,7 @@ var _ = Describe("Connection", func() {
 			cryptoSetup.EXPECT().NextEvent().Return(handshake.Event{Kind: handshake.EventNoEvent})
 			cryptoSetup.EXPECT().SetHandshakeConfirmed()
 			cryptoSetup.EXPECT().GetSessionTicket()
+			cryptoSetup.EXPECT().ConnectionState()
 			mconn.EXPECT().Write(gomock.Any(), gomock.Any(), gomock.Any())
 			Expect(conn.handleHandshakeComplete()).To(Succeed())
 			conn.run()
@@ -2351,6 +2357,7 @@ var _ = Describe("Connection", func() {
 			)
 			cryptoSetup.EXPECT().Close()
 			gomock.InOrder(
+				tracer.EXPECT().ChoseALPN(gomock.Any()),
 				tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake),
 				tracer.EXPECT().ClosedConnection(gomock.Any()).Do(func(e error) {
 					Expect(e).To(MatchError(&IdleTimeoutError{}))
@@ -2366,6 +2373,7 @@ var _ = Describe("Connection", func() {
 				cryptoSetup.EXPECT().NextEvent().Return(handshake.Event{Kind: handshake.EventNoEvent})
 				cryptoSetup.EXPECT().GetSessionTicket().MaxTimes(1)
 				cryptoSetup.EXPECT().SetHandshakeConfirmed().MaxTimes(1)
+				cryptoSetup.EXPECT().ConnectionState()
 				Expect(conn.handleHandshakeComplete()).To(Succeed())
 				err := conn.run()
 				nerr, ok := err.(net.Error)
@@ -2896,6 +2904,8 @@ var _ = Describe("Client Connection", func() {
 					defer GinkgoRecover()
 					Expect(conn.handleHandshakeComplete()).To(Succeed())
 				})
+				tracer.EXPECT().ChoseALPN(gomock.Any()).MaxTimes(1)
+				cryptoSetup.EXPECT().ConnectionState().MaxTimes(1)
 				errChan <- conn.run()
 				close(errChan)
 			}()

internal/mocks/logging/connection_tracer.go

@@ -98,6 +98,9 @@ func NewMockConnectionTracer(ctrl *gomock.Controller) (*logging.ConnectionTracer
 		ECNStateUpdated: func(state logging.ECNState, trigger logging.ECNStateTrigger) {
 			t.ECNStateUpdated(state, trigger)
 		},
+		ChoseALPN: func(protocol string) {
+			t.ChoseALPN(protocol)
+		},
 		Close: func() {
 			t.Close()
 		},

internal/mocks/logging/internal/connection_tracer.go

@@ -115,6 +115,42 @@ func (c *ConnectionTracerBufferedPacketCall) DoAndReturn(f func(logging.PacketTy
 	return c
 }
 
+// ChoseALPN mocks base method.
+func (m *MockConnectionTracer) ChoseALPN(arg0 string) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "ChoseALPN", arg0)
+}
+
+// ChoseALPN indicates an expected call of ChoseALPN.
+func (mr *MockConnectionTracerMockRecorder) ChoseALPN(arg0 any) *ConnectionTracerChoseALPNCall {
+	mr.mock.ctrl.T.Helper()
+	call := mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "ChoseALPN", reflect.TypeOf((*MockConnectionTracer)(nil).ChoseALPN), arg0)
+	return &ConnectionTracerChoseALPNCall{Call: call}
+}
+
+// ConnectionTracerChoseALPNCall wrap *gomock.Call
+type ConnectionTracerChoseALPNCall struct {
+	*gomock.Call
+}
+
+// Return rewrite *gomock.Call.Return
+func (c *ConnectionTracerChoseALPNCall) Return() *ConnectionTracerChoseALPNCall {
+	c.Call = c.Call.Return()
+	return c
+}
+
+// Do rewrite *gomock.Call.Do
+func (c *ConnectionTracerChoseALPNCall) Do(f func(string)) *ConnectionTracerChoseALPNCall {
+	c.Call = c.Call.Do(f)
+	return c
+}
+
+// DoAndReturn rewrite *gomock.Call.DoAndReturn
+func (c *ConnectionTracerChoseALPNCall) DoAndReturn(f func(string)) *ConnectionTracerChoseALPNCall {
+	c.Call = c.Call.DoAndReturn(f)
+	return c
+}
+
 // Close mocks base method.
 func (m *MockConnectionTracer) Close() {
 	m.ctrl.T.Helper()

internal/mocks/logging/mockgen.go

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

logging/connection_tracer.go

@@ -34,6 +34,7 @@ type ConnectionTracer struct {
 	LossTimerExpired                 func(TimerType, EncryptionLevel)
 	LossTimerCanceled                func()
 	ECNStateUpdated                  func(state ECNState, trigger ECNStateTrigger)
+	ChoseALPN                        func(protocol string)
 	// Close is called when the connection is closed.
 	Close func()
 	Debug func(name, msg string)
@@ -237,6 +238,13 @@ func NewMultiplexedConnectionTracer(tracers ...*ConnectionTracer) *ConnectionTra
 				}
 			}
 		},
+		ChoseALPN: func(protocol string) {
+			for _, t := range tracers {
+				if t.ChoseALPN != nil {
+					t.ChoseALPN(protocol)
+				}
+			}
+		},
 		Close: func() {
 			for _, t := range tracers {
 				if t.Close != nil {

qlog/event.go

@@ -554,3 +554,15 @@ func (e eventGeneric) IsNil() bool        { return false }
 func (e eventGeneric) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("details", e.msg)
 }
+
+type eventALPNInformation struct {
+	chosenALPN string
+}
+
+func (e eventALPNInformation) Category() category { return categoryTransport }
+func (e eventALPNInformation) Name() string       { return "alpn_information" }
+func (e eventALPNInformation) IsNil() bool        { return false }
+
+func (e eventALPNInformation) MarshalJSONObject(enc *gojay.Encoder) {
+	enc.StringKey("chosen_alpn", e.chosenALPN)
+}

qlog/qlog.go

@@ -145,6 +145,11 @@ func NewConnectionTracer(w io.WriteCloser, p protocol.Perspective, odcid protoco
 		ECNStateUpdated: func(state logging.ECNState, trigger logging.ECNStateTrigger) {
 			t.ECNStateUpdated(state, trigger)
 		},
+		ChoseALPN: func(protocol string) {
+			t.mutex.Lock()
+			t.recordEvent(time.Now(), eventALPNInformation{chosenALPN: protocol})
+			t.mutex.Unlock()
+		},
 		Debug: func(name, msg string) {
 			t.Debug(name, msg)
 		},