qlog: add support for alpn_information event

connection.go

@@ -778,6 +778,12 @@ func (s *connection) handleHandshakeConfirmed() error {
  }
  s.mtuDiscoverer.Start(utils.Min(maxPacketSize, protocol.MaxPacketBufferSize))
  }
+
+ // do not log earlier to not apply additional pressure on the handshake mutex
+ if s.tracer != nil && s.tracer.ChoseAlpn != nil {
+ s.tracer.ChoseAlpn(s.cryptoStreamHandler.ConnectionState().NegotiatedProtocol)
+ }
+
  return nil
 }
 

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()
@@ -2352,6 +2358,7 @@ var _ = Describe("Connection", func() {
  cryptoSetup.EXPECT().Close()
  gomock.InOrder(
  tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake),
+ tracer.EXPECT().ChoseAlpn(gomock.Any()),
  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)
@@ -2652,9 +2660,11 @@ var _ = Describe("Client Connection", func() {
  sph := mockackhandler.NewMockSentPacketHandler(mockCtrl)
  conn.sentPacketHandler = sph
  tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake)
+ tracer.EXPECT().ChoseAlpn(gomock.Any())
  sph.EXPECT().DropPackets(protocol.EncryptionHandshake)
  sph.EXPECT().SetHandshakeConfirmed()
  cryptoSetup.EXPECT().SetHandshakeConfirmed()
+ cryptoSetup.EXPECT().ConnectionState()
  Expect(conn.handleHandshakeDoneFrame()).To(Succeed())
  })
 
@@ -2664,11 +2674,13 @@ var _ = Describe("Client Connection", func() {
  conn.sentPacketHandler = sph
  ack := &wire.AckFrame{AckRanges: []wire.AckRange{{Smallest: 1, Largest: 3}}}
  tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake)
+ tracer.EXPECT().ChoseAlpn(gomock.Any())
  sph.EXPECT().ReceivedAck(ack, protocol.Encryption1RTT, gomock.Any()).Return(true, nil)
  sph.EXPECT().DropPackets(protocol.EncryptionHandshake)
  sph.EXPECT().SetHandshakeConfirmed()
  cryptoSetup.EXPECT().SetLargest1RTTAcked(protocol.PacketNumber(3))
  cryptoSetup.EXPECT().SetHandshakeConfirmed()
+ cryptoSetup.EXPECT().ConnectionState()
  Expect(conn.handleAckFrame(ack, protocol.Encryption1RTT)).To(Succeed())
  })
 

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/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.StringKeyOmitEmpty("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)
  },