export a qlog when the session's run loop stops

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

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 {

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
+		var calledAcceptToken, calledGetLogWriter bool
-		c1 := &Config{AcceptToken: func(_ net.Addr, _ *Token) bool { called = true; return true }}
+		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}))

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

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,
 	}
 }
 

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)

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)

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,
 	)

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 {

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
+	logID   string
-	logger utils.Logger
+	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)

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)