Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Extend qlog support #4201

Closed
wants to merge 2 commits into from
Closed

Extend qlog support #4201

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
7e146ab
Extend qlog support
birneee Dec 13, 2023
2aebc11
gofumpt-ed
birneee Dec 13, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
17 changes: 14 additions & 3 deletions client.go
View file
Open in desktop
Expand Up @@ -6,6 +6,8 @@ import (
"errors"
"net"

"github.com/quic-go/quic-go/qlog"

"github.com/quic-go/quic-go/internal/protocol"
"github.com/quic-go/quic-go/internal/utils"
"github.com/quic-go/quic-go/logging"
Expand Down Expand Up @@ -149,10 +151,19 @@ func dial(
}
c.packetHandlers = packetHandlers

c.tracingID = nextConnTracingID()
if c.config.Tracer != nil {
c.tracer = c.config.Tracer(context.WithValue(ctx, ConnectionTracingKey, c.tracingID), protocol.PerspectiveClient, c.destConnID)
var tracers []*logging.ConnectionTracer
{
ctx := context.WithValue(ctx, ConnectionTracingKey, c.tracingID)
c.tracingID = nextConnTracingID()
if c.config.Tracer != nil {
tracers = append(tracers, c.config.Tracer(ctx, protocol.PerspectiveClient, c.destConnID))
}
if qlog.QlogDir != "" {
tracers = append(tracers, qlog.NewQlogDirConnectionTracer(ctx, protocol.PerspectiveClient, c.destConnID, "client"))
}
}
c.tracer = logging.NewMultiplexedConnectionTracer(tracers...)

if c.tracer != nil && c.tracer.StartedConnection != nil {
c.tracer.StartedConnection(c.sendConn.LocalAddr(), c.sendConn.RemoteAddr(), c.srcConnID, c.destConnID)
}
Expand Down
18 changes: 18 additions & 0 deletions connection.go
View file
Open in desktop
Expand Up @@ -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
}

Expand Down Expand Up @@ -2386,3 +2392,15 @@ func (s *connection) NextConnection() Connection {
s.streamsMap.UseResetMaps()
return s
}

func (s *connection) onStreamDataReadByApplication(id protocol.StreamID, offset protocol.ByteCount, n protocol.ByteCount) {
if s.tracer != nil && s.tracer.StreamDataMoved != nil {
s.tracer.StreamDataMoved(id, offset, n, "transport", "application")
}
}

func (s *connection) onStreamDataWrittenByApplication(id protocol.StreamID, offset protocol.ByteCount, n protocol.ByteCount) {
if s.tracer != nil && s.tracer.StreamDataMoved != nil {
s.tracer.StreamDataMoved(id, offset, n, "application", "transport")
}
}
12 changes: 12 additions & 0 deletions connection_test.go
View file
Open in desktop
Expand Up @@ -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()
Expand All @@ -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())
Expand All @@ -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())
Expand Down Expand Up @@ -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)
Expand All @@ -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()
Expand Down Expand Up @@ -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{}))
}),
Expand All @@ -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)
Expand Down Expand Up @@ -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())
})

Expand All @@ -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())
})

Expand Down
6 changes: 6 additions & 0 deletions internal/mocks/logging/connection_tracer.go
View file
Open in desktop
Expand Up @@ -98,6 +98,12 @@ 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)
},
StreamDataMoved: func(id logging.StreamID, offset logging.ByteCount, n logging.ByteCount, from string, to string) {
t.StreamDataMoved(id, offset, n, from, to)
},
Close: func() {
t.Close()
},
Expand Down
72 changes: 72 additions & 0 deletions internal/mocks/logging/internal/connection_tracer.go
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 2 additions & 0 deletions internal/mocks/logging/mockgen.go
View file
Open in desktop
Expand Up @@ -45,6 +45,8 @@ type ConnectionTracer interface {
LossTimerExpired(logging.TimerType, logging.EncryptionLevel)
LossTimerCanceled()
ECNStateUpdated(state logging.ECNState, trigger logging.ECNStateTrigger)
ChoseAlpn(protocol string)
StreamDataMoved(id logging.StreamID, offset logging.ByteCount, n logging.ByteCount, from string, to string)
// Close is called when the connection is closed.
Close()
Debug(name, msg string)
Expand Down
18 changes: 18 additions & 0 deletions logging/connection_tracer.go
View file
Open in desktop
Expand Up @@ -3,6 +3,8 @@ package logging
import (
"net"
"time"

"github.com/quic-go/quic-go/internal/protocol"
)

// A ConnectionTracer records events.
Expand Down Expand Up @@ -34,6 +36,8 @@ type ConnectionTracer struct {
LossTimerExpired func(TimerType, EncryptionLevel)
LossTimerCanceled func()
ECNStateUpdated func(state ECNState, trigger ECNStateTrigger)
ChoseAlpn func(protocol string)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be nice if we could also log server_alpns and client_alpns, but it doesn't seem possible without wrapping various callback on the tls.Config, which we should avoid doing.

Suggested change
ChoseAlpn func(protocol string)
ChoseALPN func(protocol string)

StreamDataMoved func(id StreamID, offset protocol.ByteCount, n protocol.ByteCount, from string, to string)
// Close is called when the connection is closed.
Close func()
Debug func(name, msg string)
Expand Down Expand Up @@ -237,6 +241,20 @@ func NewMultiplexedConnectionTracer(tracers ...*ConnectionTracer) *ConnectionTra
}
}
},
ChoseAlpn: func(protocol string) {
for _, t := range tracers {
if t.ChoseAlpn != nil {
t.ChoseAlpn(protocol)
}
}
},
StreamDataMoved: func(id StreamID, offset ByteCount, n ByteCount, from string, to string) {
for _, t := range tracers {
if t.StreamDataMoved != nil {
t.StreamDataMoved(id, offset, n, from, to)
}
}
},
Close: func() {
for _, t := range tracers {
if t.Close != nil {
Expand Down
72 changes: 72 additions & 0 deletions mock_stream_sender_test.go
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.