From b031615db53fd044c1ff237c912b0507aaa83428 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Mon, 27 Jan 2020 11:29:53 +0700 Subject: [PATCH] export a qlog when the session's run loop stops --- client.go | 30 ++++++++++++++---------------- client_test.go | 13 +++++++++++++ config_test.go | 14 ++++++++++---- interface.go | 4 ++++ packet_packer.go | 4 ++-- packet_packer_test.go | 9 +++++---- qlog/qlog.go | 2 ++ server.go | 11 ++++++++++- server_test.go | 10 ++++++++++ session.go | 34 +++++++++++++++++++++++++++------- session_test.go | 2 ++ 11 files changed, 99 insertions(+), 34 deletions(-) diff --git a/client.go b/client.go index e115acac..f5b668fd 100644 --- a/client.go +++ b/client.go @@ -12,6 +12,7 @@ import ( "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/utils" "github.com/lucas-clemente/quic-go/internal/wire" + "github.com/lucas-clemente/quic-go/qlog" ) type client struct { @@ -176,7 +177,14 @@ func dialContext( return nil, err } c.packetHandlers = packetHandlers - if err := c.dial(ctx); err != nil { + + var qlogger qlog.Tracer + if c.config.GetLogWriter != nil { + if w := c.config.GetLogWriter(c.destConnID); w != nil { + qlogger = qlog.NewTracer(w, protocol.PerspectiveClient, c.destConnID) + } + } + if err := c.dial(ctx, qlogger); err != nil { return nil, err } return c.session, nil @@ -249,7 +257,7 @@ func populateClientConfig(config *Config, createdPacketConn bool) *Config { return config } -func (c *client) dial(ctx context.Context) error { +func (c *client) dial(ctx context.Context, qlogger qlog.Tracer) error { c.logger.Infof("Starting new connection to %s (%s -> %s), source connection ID %s, destination connection ID %s, version %s", c.tlsConf.ServerName, c.conn.LocalAddr(), c.conn.RemoteAddr(), c.srcConnID, c.destConnID, c.version) c.mutex.Lock() @@ -263,6 +271,7 @@ func (c *client) dial(ctx context.Context) error { c.initialPacketNumber, c.initialVersion, c.use0RTT, + qlogger, c.logger, c.version, ) @@ -271,21 +280,7 @@ func (c *client) dial(ctx context.Context) error { // since there's no way to securely communicate it to the server. c.packetHandlers.Add(c.srcConnID, c) - err := c.establishSecureConnection(ctx) - if err == errCloseForRecreating { - return c.dial(ctx) - } - return err -} - -// establishSecureConnection runs the session, and tries to establish a secure connection -// It returns: -// - errCloseForRecreating when the server sends a version negotiation packet -// - any other error that might occur -// - when the connection is forward-secure -func (c *client) establishSecureConnection(ctx context.Context) error { errorChan := make(chan error, 1) - go func() { err := c.session.run() // returns as soon as the session is closed if err != errCloseForRecreating && c.createdPacketConn { @@ -306,6 +301,9 @@ func (c *client) establishSecureConnection(ctx context.Context) error { c.session.shutdown() return ctx.Err() case err := <-errorChan: + if err == errCloseForRecreating { + return c.dial(ctx, qlogger) + } return err case <-earlySessionChan: // ready to send 0-RTT data diff --git a/client_test.go b/client_test.go index eb4866f2..3db99092 100644 --- a/client_test.go +++ b/client_test.go @@ -9,6 +9,8 @@ import ( "os" "time" + "github.com/lucas-clemente/quic-go/qlog" + "github.com/golang/mock/gomock" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/utils" @@ -39,6 +41,7 @@ var _ = Describe("Client", func() { initialPacketNumber protocol.PacketNumber, initialVersion protocol.VersionNumber, enable0RTT bool, + qlogger qlog.Tracer, logger utils.Logger, v protocol.VersionNumber, ) quicSession @@ -142,6 +145,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -173,6 +177,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -204,6 +209,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -240,6 +246,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, enable0RTT bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -280,6 +287,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, enable0RTT bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -325,6 +333,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -366,6 +375,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -415,6 +425,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -535,6 +546,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, /* initial version */ _ bool, + _ qlog.Tracer, _ utils.Logger, versionP protocol.VersionNumber, ) quicSession { @@ -584,6 +596,7 @@ var _ = Describe("Client", func() { _ protocol.PacketNumber, _ protocol.VersionNumber, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { diff --git a/config_test.go b/config_test.go index 239c1cb8..e1c86dbf 100644 --- a/config_test.go +++ b/config_test.go @@ -2,6 +2,7 @@ package quic import ( "fmt" + "io" "net" "reflect" "time" @@ -14,11 +15,16 @@ import ( var _ = Describe("Config", func() { It("clones function fields", func() { - var called bool - c1 := &Config{AcceptToken: func(_ net.Addr, _ *Token) bool { called = true; return true }} + var calledAcceptToken, calledGetLogWriter bool + c1 := &Config{ + AcceptToken: func(_ net.Addr, _ *Token) bool { calledAcceptToken = true; return true }, + GetLogWriter: func(connectionID []byte) io.WriteCloser { calledGetLogWriter = true; return nil }, + } c2 := c1.Clone() c2.AcceptToken(&net.UDPAddr{}, &Token{}) - Expect(called).To(BeTrue()) + c2.GetLogWriter([]byte{1, 2, 3}) + Expect(calledAcceptToken).To(BeTrue()) + Expect(calledGetLogWriter).To(BeTrue()) }) It("clones non-function fields", func() { @@ -34,7 +40,7 @@ var _ = Describe("Config", func() { } switch fn := typ.Field(i).Name; fn { - case "AcceptToken": + case "AcceptToken", "GetLogWriter": // Can't compare functions. case "Versions": f.Set(reflect.ValueOf([]VersionNumber{1, 2, 3})) diff --git a/interface.go b/interface.go index 660034f8..d4118dbc 100644 --- a/interface.go +++ b/interface.go @@ -260,6 +260,10 @@ type Config struct { // QUIC Event Tracer. // Warning: Experimental. This API should not be considered stable and will change soon. QuicTracer quictrace.Tracer + // GetLogWriter is used to pass in a writer for the qlog. + // If it is nil, no qlog will be collected and exported. + // If it returns nil, no qlog will be collected and exported for the respective connection. + GetLogWriter func(connectionID []byte) io.WriteCloser } // A Listener for incoming QUIC connections diff --git a/packet_packer.go b/packet_packer.go index b3cb82a0..cf010b88 100644 --- a/packet_packer.go +++ b/packet_packer.go @@ -63,7 +63,7 @@ func (p *packedPacket) IsAckEliciting() bool { return ackhandler.HasAckElicitingFrames(p.frames) } -func (p *packedPacket) ToAckHandlerPacket(q *retransmissionQueue) *ackhandler.Packet { +func (p *packedPacket) ToAckHandlerPacket(now time.Time, q *retransmissionQueue) *ackhandler.Packet { largestAcked := protocol.InvalidPacketNumber if p.ack != nil { largestAcked = p.ack.LargestAcked() @@ -88,7 +88,7 @@ func (p *packedPacket) ToAckHandlerPacket(q *retransmissionQueue) *ackhandler.Pa Frames: p.frames, Length: protocol.ByteCount(len(p.raw)), EncryptionLevel: encLevel, - SendTime: time.Now(), + SendTime: now, } } diff --git a/packet_packer_test.go b/packet_packer_test.go index c4bb50c4..547c0640 100644 --- a/packet_packer_test.go +++ b/packet_packer_test.go @@ -830,11 +830,12 @@ var _ = Describe("Converting to AckHandler packets", func() { ack: &wire.AckFrame{AckRanges: []wire.AckRange{{Largest: 100, Smallest: 80}}}, raw: []byte("foobar"), } - p := packet.ToAckHandlerPacket(nil) + t := time.Now() + p := packet.ToAckHandlerPacket(t, nil) Expect(p.Length).To(Equal(protocol.ByteCount(6))) Expect(p.Frames).To(Equal(packet.frames)) Expect(p.LargestAcked).To(Equal(protocol.PacketNumber(100))) - Expect(p.SendTime).To(BeTemporally("~", time.Now(), 50*time.Millisecond)) + Expect(p.SendTime).To(Equal(t)) }) It("sets the LargestAcked to invalid, if the packet doesn't have an ACK frame", func() { @@ -843,7 +844,7 @@ var _ = Describe("Converting to AckHandler packets", func() { frames: []ackhandler.Frame{{Frame: &wire.MaxDataFrame{}}, {Frame: &wire.PingFrame{}}}, raw: []byte("foobar"), } - p := packet.ToAckHandlerPacket(nil) + p := packet.ToAckHandlerPacket(time.Now(), nil) Expect(p.LargestAcked).To(Equal(protocol.InvalidPacketNumber)) }) @@ -857,7 +858,7 @@ var _ = Describe("Converting to AckHandler packets", func() { }, raw: []byte("foobar"), } - p := packet.ToAckHandlerPacket(newRetransmissionQueue(protocol.VersionTLS)) + p := packet.ToAckHandlerPacket(time.Now(), newRetransmissionQueue(protocol.VersionTLS)) Expect(p.Frames).To(HaveLen(2)) Expect(p.Frames[0].OnLost).ToNot(BeNil()) p.Frames[1].OnLost(nil) diff --git a/qlog/qlog.go b/qlog/qlog.go index 97ea5dcf..5723e698 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -35,6 +35,8 @@ func NewTracer(w io.WriteCloser, p protocol.Perspective, odcid protocol.Connecti } } +func (t *tracer) Active() bool { return true } + // Export writes a qlog. func (t *tracer) Export() error { enc := gojay.NewEncoder(t.w) diff --git a/server.go b/server.go index 08dd035d..93129721 100644 --- a/server.go +++ b/server.go @@ -11,6 +11,8 @@ import ( "sync/atomic" "time" + "github.com/lucas-clemente/quic-go/qlog" + "github.com/lucas-clemente/quic-go/internal/handshake" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/qerr" @@ -71,7 +73,7 @@ type baseServer struct { receivedPackets chan *receivedPacket // set as a member, so they can be set in the tests - newSession func(connection, sessionRunner, protocol.ConnectionID /* original connection ID */, protocol.ConnectionID /* client dest connection ID */, protocol.ConnectionID /* destination connection ID */, protocol.ConnectionID /* source connection ID */, [16]byte, *Config, *tls.Config, *handshake.TokenGenerator, bool /* enable 0-RTT */, utils.Logger, protocol.VersionNumber) quicSession + newSession func(connection, sessionRunner, protocol.ConnectionID /* original connection ID */, protocol.ConnectionID /* client dest connection ID */, protocol.ConnectionID /* destination connection ID */, protocol.ConnectionID /* source connection ID */, [16]byte, *Config, *tls.Config, *handshake.TokenGenerator, bool /* enable 0-RTT */, qlog.Tracer, utils.Logger, protocol.VersionNumber) quicSession serverError error errorChan chan struct{} @@ -394,6 +396,12 @@ func (s *baseServer) createNewSession( srcConnID protocol.ConnectionID, version protocol.VersionNumber, ) quicSession { + var qlogger qlog.Tracer + if s.config.GetLogWriter != nil { + if w := s.config.GetLogWriter(origDestConnID); w != nil { + qlogger = qlog.NewTracer(w, protocol.PerspectiveServer, origDestConnID) + } + } sess := s.newSession( &conn{pconn: s.conn, currentAddr: remoteAddr}, s.sessionHandler, @@ -406,6 +414,7 @@ func (s *baseServer) createNewSession( s.tlsConf, s.tokenGenerator, s.acceptEarlySessions, + qlogger, s.logger, version, ) diff --git a/server_test.go b/server_test.go index 96161637..b3ac89db 100644 --- a/server_test.go +++ b/server_test.go @@ -13,6 +13,8 @@ import ( "sync" "time" + "github.com/lucas-clemente/quic-go/qlog" + "github.com/golang/mock/gomock" "github.com/lucas-clemente/quic-go/internal/handshake" "github.com/lucas-clemente/quic-go/internal/protocol" @@ -349,6 +351,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, enable0RTT bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -402,6 +405,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -431,6 +435,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -491,6 +496,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -594,6 +600,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -656,6 +663,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, enable0RTT bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -689,6 +697,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { @@ -748,6 +757,7 @@ var _ = Describe("Server", func() { _ *tls.Config, _ *handshake.TokenGenerator, _ bool, + _ qlog.Tracer, _ utils.Logger, _ protocol.VersionNumber, ) quicSession { diff --git a/session.go b/session.go index 4d8ec6f6..be4c3703 100644 --- a/session.go +++ b/session.go @@ -20,6 +20,7 @@ import ( "github.com/lucas-clemente/quic-go/internal/qerr" "github.com/lucas-clemente/quic-go/internal/utils" "github.com/lucas-clemente/quic-go/internal/wire" + "github.com/lucas-clemente/quic-go/qlog" "github.com/lucas-clemente/quic-go/quictrace" ) @@ -186,8 +187,9 @@ type session struct { traceCallback func(quictrace.Event) - logID string - logger utils.Logger + logID string + qlogger qlog.Tracer + logger utils.Logger } var _ Session = &session{} @@ -206,6 +208,7 @@ var newSession = func( tlsConf *tls.Config, tokenGenerator *handshake.TokenGenerator, enable0RTT bool, + qlogger qlog.Tracer, logger utils.Logger, v protocol.VersionNumber, ) quicSession { @@ -218,6 +221,7 @@ var newSession = func( oneRTTStream: newCryptoStream(), perspective: protocol.PerspectiveServer, handshakeCompleteChan: make(chan struct{}), + qlogger: qlogger, logger: logger, version: v, } @@ -313,6 +317,7 @@ var newClientSession = func( initialPacketNumber protocol.PacketNumber, initialVersion protocol.VersionNumber, enable0RTT bool, + qlogger qlog.Tracer, logger utils.Logger, v protocol.VersionNumber, ) quicSession { @@ -325,6 +330,7 @@ var newClientSession = func( handshakeCompleteChan: make(chan struct{}), logID: destConnID.String(), logger: logger, + qlogger: qlogger, initialVersion: initialVersion, version: v, } @@ -565,6 +571,11 @@ runLoop: s.logger.Infof("Connection %s closed.", s.logID) s.cryptoStreamHandler.Close() s.sendQueue.Close() + if s.qlogger != nil { + if err := s.qlogger.Export(); err != nil { + return err + } + } return closeErr.err } @@ -831,7 +842,7 @@ func (s *session) handleUnpackedPacket(packet *unpackedPacket, rcvTime time.Time if ackhandler.IsFrameAckEliciting(frame) { isAckEliciting = true } - if s.traceCallback != nil { + if s.traceCallback != nil || s.qlogger != nil { frames = append(frames, frame) } if err := s.handleFrame(frame, packet.packetNumber, packet.encryptionLevel); err != nil { @@ -851,6 +862,9 @@ func (s *session) handleUnpackedPacket(packet *unpackedPacket, rcvTime time.Time Frames: frames, }) } + if s.qlogger != nil { + s.qlogger.ReceivedPacket(rcvTime, packet.hdr, frames) + } return s.receivedPacketHandler.ReceivedPacket(packet.packetNumber, packet.encryptionLevel, rcvTime, isAckEliciting) } @@ -1235,7 +1249,6 @@ func (s *session) maybeSendAckOnlyPacket() error { if packet == nil { return nil } - s.sentPacketHandler.SentPacket(packet.ToAckHandlerPacket(s.retransmissionQueue)) s.sendPackedPacket(packet) return nil } @@ -1277,7 +1290,6 @@ func (s *session) sendProbePacket(encLevel protocol.EncryptionLevel) error { if packet == nil { return fmt.Errorf("session BUG: couldn't pack %s probe packet", encLevel) } - s.sentPacketHandler.SentPacket(packet.ToAckHandlerPacket(s.retransmissionQueue)) s.sendPackedPacket(packet) return nil } @@ -1292,7 +1304,6 @@ func (s *session) sendPacket() (bool, error) { if err != nil || packet == nil { return false, err } - s.sentPacketHandler.SentPacket(packet.ToAckHandlerPacket(s.retransmissionQueue)) s.sendPackedPacket(packet) return true, nil } @@ -1301,13 +1312,15 @@ func (s *session) sendPackedPacket(packet *packedPacket) { if s.firstAckElicitingPacketAfterIdleSentTime.IsZero() && packet.IsAckEliciting() { s.firstAckElicitingPacketAfterIdleSentTime = time.Now() } + now := time.Now() + s.sentPacketHandler.SentPacket(packet.ToAckHandlerPacket(now, s.retransmissionQueue)) if s.traceCallback != nil { frames := make([]wire.Frame, 0, len(packet.frames)) for _, f := range packet.frames { frames = append(frames, f.Frame) } s.traceCallback(quictrace.Event{ - Time: time.Now(), + Time: now, EventType: quictrace.PacketSent, TransportState: s.sentPacketHandler.GetStats(), EncryptionLevel: packet.EncryptionLevel(), @@ -1316,6 +1329,13 @@ func (s *session) sendPackedPacket(packet *packedPacket) { Frames: frames, }) } + if s.qlogger != nil { + frames := make([]wire.Frame, 0, len(packet.frames)) + for _, f := range packet.frames { + frames = append(frames, f.Frame) + } + s.qlogger.SentPacket(now, packet.header, packet.ack, frames) + } s.logPacket(packet) s.connIDManager.SentPacket() s.sendQueue.Send(packet) diff --git a/session_test.go b/session_test.go index 6163648f..dd759e5a 100644 --- a/session_test.go +++ b/session_test.go @@ -92,6 +92,7 @@ var _ = Describe("Session", func() { nil, // tls.Config tokenGenerator, false, + nil, utils.DefaultLogger, protocol.VersionTLS, ).(*session) @@ -1698,6 +1699,7 @@ var _ = Describe("Client Session", func() { 42, // initial packet number protocol.VersionTLS, false, + nil, utils.DefaultLogger, protocol.VersionTLS, ).(*session)