qlog chosen alpn

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 {
@@ -778,12 +782,6 @@ 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,7 +1946,7 @@ var _ = Describe("Connection", func() {
  sph := mockackhandler.NewMockSentPacketHandler(mockCtrl)
  conn.sentPacketHandler = sph
  tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake)
- tracer.EXPECT().ChoseAlpn(gomock.Any())
+ tracer.EXPECT().ChoseALPN(gomock.Any())
  sph.EXPECT().GetLossDetectionTimeout().AnyTimes()
  sph.EXPECT().TimeUntilSend().AnyTimes()
  sph.EXPECT().SendMode(gomock.Any()).AnyTimes()
@@ -1968,7 +1968,7 @@ var _ = Describe("Connection", func() {
  connRunner.EXPECT().Retire(clientDestConnID)
  conn.sentPacketHandler.DropPackets(protocol.EncryptionInitial)
  tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake)
- tracer.EXPECT().ChoseAlpn(gomock.Any())
+ tracer.EXPECT().ChoseALPN(gomock.Any())
  cryptoSetup.EXPECT().SetHandshakeConfirmed()
  cryptoSetup.EXPECT().GetSessionTicket().Return(make([]byte, size), nil)
  cryptoSetup.EXPECT().ConnectionState()
@@ -2025,7 +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())
+ tracer.EXPECT().ChoseALPN(gomock.Any())
  conn.sentPacketHandler = sph
  done := make(chan struct{})
  connRunner.EXPECT().Retire(clientDestConnID)
@@ -2357,8 +2357,8 @@ var _ = Describe("Connection", func() {
  )
  cryptoSetup.EXPECT().Close()
  gomock.InOrder(
+ tracer.EXPECT().ChoseALPN(gomock.Any()),
  tracer.EXPECT().DroppedEncryptionLevel(protocol.EncryptionHandshake),
- tracer.EXPECT().ChoseAlpn(gomock.Any()),
  tracer.EXPECT().ClosedConnection(gomock.Any()).Do(func(e error) {
  Expect(e).To(MatchError(&IdleTimeoutError{}))
  }),
@@ -2660,11 +2660,9 @@ 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())
  })
 
@@ -2674,13 +2672,11 @@ 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())
  })
 
@@ -2908,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,8 +98,8 @@ 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)
+ ChoseALPN: func(protocol string) {
+ t.ChoseALPN(protocol)
  },
  Close: func() {
  t.Close()

internal/mocks/logging/mockgen.go

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

logging/connection_tracer.go

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

qlog/event.go

@@ -564,5 +564,5 @@ 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)
+ enc.StringKey("chosen_alpn", e.chosenAlpn)
 }

qlog/qlog.go

@@ -145,7 +145,7 @@ 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) {
+ ChoseALPN: func(protocol string) {
  t.mutex.Lock()
  t.recordEvent(time.Now(), eventAlpnInformation{chosenAlpn: protocol})
  t.mutex.Unlock()