add logging to the ackhandler

internal/ackhandler/received_packet_handler.go

@@ -25,6 +25,8 @@ type receivedPacketHandler struct {
 	ackAlarm                                   time.Time
 	lastAck                                    *wire.AckFrame
 
+	logger utils.Logger
+
 	version protocol.VersionNumber
 }
 
@@ -52,11 +54,16 @@ const (
 )
 
 // NewReceivedPacketHandler creates a new receivedPacketHandler
-func NewReceivedPacketHandler(rttStats *congestion.RTTStats, version protocol.VersionNumber) ReceivedPacketHandler {
+func NewReceivedPacketHandler(
+	rttStats *congestion.RTTStats,
+	logger utils.Logger,
+	version protocol.VersionNumber,
+) ReceivedPacketHandler {
 	return &receivedPacketHandler{
 		packetHistory: newReceivedPacketHistory(),
 		ackSendDelay:  ackSendDelay,
 		rttStats:      rttStats,
+		logger:        logger,
 		version:       version,
 	}
 }
@@ -82,8 +89,14 @@ func (h *receivedPacketHandler) ReceivedPacket(packetNumber protocol.PacketNumbe
 // IgnoreBelow sets a lower limit for acking packets.
 // Packets with packet numbers smaller than p will not be acked.
 func (h *receivedPacketHandler) IgnoreBelow(p protocol.PacketNumber) {
+	if p <= h.ignoreBelow {
+		return
+	}
 	h.ignoreBelow = p
 	h.packetHistory.DeleteBelow(p)
+	if h.logger.Debug() {
+		h.logger.Debugf("\tIgnoring all packets below %#x.", p)
+	}
 }
 
 // isMissing says if a packet was reported missing in the last ACK.
@@ -110,6 +123,7 @@ func (h *receivedPacketHandler) maybeQueueAck(packetNumber protocol.PacketNumber
 
 	// always ack the first packet
 	if h.lastAck == nil {
+		h.logger.Debugf("\tQueueing ACK because the first packet should be acknowledged.")
 		h.ackQueued = true
 		return
 	}
@@ -118,6 +132,9 @@ func (h *receivedPacketHandler) maybeQueueAck(packetNumber protocol.PacketNumber
 	// Ack decimation with reordering relies on the timer to send an ACK, but if
 	// missing packets we reported in the previous ack, send an ACK immediately.
 	if wasMissing {
+		if h.logger.Debug() {
+			h.logger.Debugf("\tQueueing ACK because packet %#x was missing before.", packetNumber)
+		}
 		h.ackQueued = true
 	}
 
@@ -128,26 +145,41 @@ func (h *receivedPacketHandler) maybeQueueAck(packetNumber protocol.PacketNumber
 			// ack up to 10 packets at once
 			if h.retransmittablePacketsReceivedSinceLastAck >= retransmittablePacketsBeforeAck {
 				h.ackQueued = true
+				if h.logger.Debug() {
+					h.logger.Debugf("\tQueueing ACK because packet %d packets were received after the last ACK (using threshold: %d).", h.retransmittablePacketsReceivedSinceLastAck, retransmittablePacketsBeforeAck)
+				}
 			} else if h.ackAlarm.IsZero() {
 				// wait for the minimum of the ack decimation delay or the delayed ack time before sending an ack
 				ackDelay := utils.MinDuration(ackSendDelay, time.Duration(float64(h.rttStats.MinRTT())*float64(ackDecimationDelay)))
 				h.ackAlarm = rcvTime.Add(ackDelay)
+				if h.logger.Debug() {
+					h.logger.Debugf("\tSetting ACK timer to min(1/4 min-RTT, max ack delay): %s (%s from now)", ackDelay, time.Until(h.ackAlarm))
+				}
 			}
 		} else {
 			// send an ACK every 2 retransmittable packets
 			if h.retransmittablePacketsReceivedSinceLastAck >= initialRetransmittablePacketsBeforeAck {
+				if h.logger.Debug() {
+					h.logger.Debugf("\tQueueing ACK because packet %d packets were received after the last ACK (using initial threshold: %d).", h.retransmittablePacketsReceivedSinceLastAck, initialRetransmittablePacketsBeforeAck)
+				}
 				h.ackQueued = true
 			} else if h.ackAlarm.IsZero() {
+				if h.logger.Debug() {
+					h.logger.Debugf("\tSetting ACK timer to max ack delay: %s", ackSendDelay)
+				}
 				h.ackAlarm = rcvTime.Add(ackSendDelay)
 			}
 		}
 		// If there are new missing packets to report, set a short timer to send an ACK.
 		if h.hasNewMissingPackets() {
 			// wait the minimum of 1/8 min RTT and the existing ack time
-			ackDelay := float64(h.rttStats.MinRTT()) * float64(shortAckDecimationDelay)
+			ackDelay := time.Duration(float64(h.rttStats.MinRTT()) * float64(shortAckDecimationDelay))
-			ackTime := rcvTime.Add(time.Duration(ackDelay))
+			ackTime := rcvTime.Add(ackDelay)
 			if h.ackAlarm.IsZero() || h.ackAlarm.After(ackTime) {
 				h.ackAlarm = ackTime
+				if h.logger.Debug() {
+					h.logger.Debugf("\tSetting ACK timer to 1/8 min-RTT: %s (%s from now)", ackDelay, time.Until(h.ackAlarm))
+				}
 			}
 		}
 	}
@@ -163,6 +195,9 @@ func (h *receivedPacketHandler) GetAckFrame() *wire.AckFrame {
 	if !h.ackQueued && (h.ackAlarm.IsZero() || h.ackAlarm.After(now)) {
 		return nil
 	}
+	if h.logger.Debug() && !h.ackQueued && !h.ackAlarm.IsZero() {
+		h.logger.Debugf("Sending ACK because the ACK timer expired.")
+	}
 
 	ack := &wire.AckFrame{
 		AckRanges: h.packetHistory.GetAckRanges(),

internal/ackhandler/received_packet_handler_test.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/lucas-clemente/quic-go/internal/congestion"
 	"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/onsi/ginkgo"
@@ -19,7 +20,7 @@ var _ = Describe("receivedPacketHandler", func() {
 
 	BeforeEach(func() {
 		rttStats = &congestion.RTTStats{}
-		handler = NewReceivedPacketHandler(rttStats, protocol.VersionWhatever).(*receivedPacketHandler)
+		handler = NewReceivedPacketHandler(rttStats, utils.DefaultLogger, protocol.VersionWhatever).(*receivedPacketHandler)
 	})
 
 	Context("accepting packets", func() {

internal/ackhandler/sent_packet_handler.go

@@ -103,6 +103,7 @@ func (h *sentPacketHandler) lowestUnacked() protocol.PacketNumber {
 }
 
 func (h *sentPacketHandler) SetHandshakeComplete() {
+	h.logger.Debugf("Handshake complete. Discarding all outstanding handshake packets.")
 	var queue []*Packet
 	for _, packet := range h.retransmissionQueue {
 		if packet.EncryptionLevel == protocol.EncryptionForwardSecure {
@@ -274,12 +275,22 @@ func (h *sentPacketHandler) determineNewlyAckedPackets(ackFrame *wire.AckFrame)
 		}
 		return true, nil
 	})
+	if h.logger.Debug() && len(ackedPackets) > 0 {
+		pns := make([]protocol.PacketNumber, len(ackedPackets))
+		for i, p := range ackedPackets {
+			pns[i] = p.PacketNumber
+		}
+		h.logger.Debugf("\tnewly acked packets (%d): %#x", len(pns), pns)
+	}
 	return ackedPackets, err
 }
 
 func (h *sentPacketHandler) maybeUpdateRTT(largestAcked protocol.PacketNumber, ackDelay time.Duration, rcvTime time.Time) bool {
 	if p := h.packetHistory.GetPacket(largestAcked); p != nil {
 		h.rttStats.UpdateRTT(rcvTime.Sub(p.SendTime), ackDelay, rcvTime)
+		if h.logger.Debug() {
+			h.logger.Debugf("\tupdated RTT: %s (σ: %s)", h.rttStats.SmoothedRTT(), h.rttStats.MeanDeviation())
+		}
 		return true
 	}
 	return false
@@ -325,11 +336,21 @@ func (h *sentPacketHandler) detectLostPackets(now time.Time, priorInFlight proto
 		if timeSinceSent > delayUntilLost {
 			lostPackets = append(lostPackets, packet)
 		} else if h.lossTime.IsZero() {
+			if h.logger.Debug() {
+				h.logger.Debugf("\tsetting loss timer for packet %#x to %s (in %s)", packet.PacketNumber, delayUntilLost, delayUntilLost-timeSinceSent)
+			}
 			// Note: This conditional is only entered once per call
 			h.lossTime = now.Add(delayUntilLost - timeSinceSent)
 		}
 		return true, nil
 	})
+	if h.logger.Debug() && len(lostPackets) > 0 {
+		pns := make([]protocol.PacketNumber, len(lostPackets))
+		for i, p := range lostPackets {
+			pns[i] = p.PacketNumber
+		}
+		h.logger.Debugf("\tlost packets (%d): %#x", len(pns), pns)
+	}
 
 	for _, p := range lostPackets {
 		// the bytes in flight need to be reduced no matter if this packet will be retransmitted
@@ -339,7 +360,6 @@ func (h *sentPacketHandler) detectLostPackets(now time.Time, priorInFlight proto
 		}
 		if p.canBeRetransmitted {
 			// queue the packet for retransmission, and report the loss to the congestion controller
-			h.logger.Debugf("\tQueueing packet %#x because it was detected lost", p.PacketNumber)
 			if err := h.queuePacketForRetransmission(p); err != nil {
 				return err
 			}
@@ -354,15 +374,27 @@ func (h *sentPacketHandler) OnAlarm() error {
 
 	var err error
 	if !h.handshakeComplete {
+		if h.logger.Debug() {
+			h.logger.Debugf("Loss detection alarm fired in handshake mode")
+		}
 		h.handshakeCount++
 		err = h.queueHandshakePacketsForRetransmission()
 	} else if !h.lossTime.IsZero() {
+		if h.logger.Debug() {
+			h.logger.Debugf("Loss detection alarm fired in loss timer mode")
+		}
 		// Early retransmit or time loss detection
 		err = h.detectLostPackets(now, h.bytesInFlight)
 	} else if h.tlpCount < maxTLPs {
+		if h.logger.Debug() {
+			h.logger.Debugf("Loss detection alarm fired in TLP mode")
+		}
 		h.allowTLP = true
 		h.tlpCount++
 	} else {
+		if h.logger.Debug() {
+			h.logger.Debugf("Loss detection alarm fired in RTO mode")
+		}
 		// RTO
 		h.rtoCount++
 		h.numRTOs += 2
@@ -477,7 +509,9 @@ func (h *sentPacketHandler) SendMode() SendMode {
 	// we will stop sending out new data when reaching MaxOutstandingSentPackets,
 	// but still allow sending of retransmissions and ACKs.
 	if numTrackedPackets >= protocol.MaxTrackedSentPackets {
-		h.logger.Debugf("Limited by the number of tracked packets: tracking %d packets, maximum %d", numTrackedPackets, protocol.MaxTrackedSentPackets)
+		if h.logger.Debug() {
+			h.logger.Debugf("Limited by the number of tracked packets: tracking %d packets, maximum %d", numTrackedPackets, protocol.MaxTrackedSentPackets)
+		}
 		return SendNone
 	}
 	if h.allowTLP {
@@ -488,7 +522,9 @@ func (h *sentPacketHandler) SendMode() SendMode {
 	}
 	// Only send ACKs if we're congestion limited.
 	if cwnd := h.congestion.GetCongestionWindow(); h.bytesInFlight > cwnd {
-		h.logger.Debugf("Congestion limited: bytes in flight %d, window %d", h.bytesInFlight, cwnd)
+		if h.logger.Debug() {
+			h.logger.Debugf("Congestion limited: bytes in flight %d, window %d", h.bytesInFlight, cwnd)
+		}
 		return SendAck
 	}
 	// Send retransmissions first, if there are any.
@@ -496,7 +532,9 @@ func (h *sentPacketHandler) SendMode() SendMode {
 		return SendRetransmission
 	}
 	if numTrackedPackets >= protocol.MaxOutstandingSentPackets {
-		h.logger.Debugf("Max outstanding limited: tracking %d packets, maximum: %d", numTrackedPackets, protocol.MaxOutstandingSentPackets)
+		if h.logger.Debug() {
+			h.logger.Debugf("Max outstanding limited: tracking %d packets, maximum: %d", numTrackedPackets, protocol.MaxOutstandingSentPackets)
+		}
 		return SendAck
 	}
 	return SendAny
@@ -526,7 +564,7 @@ func (h *sentPacketHandler) queueRTOs() error {
 	// They are still tracked in the packet history and count towards the bytes in flight.
 	for i := 0; i < 2; i++ {
 		if p := h.packetHistory.FirstOutstanding(); p != nil {
-			h.logger.Debugf("\tQueueing packet %#x for retransmission (RTO)", p.PacketNumber)
+			h.logger.Debugf("Queueing packet %#x for retransmission (RTO)", p.PacketNumber)
 			if err := h.queuePacketForRetransmission(p); err != nil {
 				return err
 			}
@@ -544,7 +582,7 @@ func (h *sentPacketHandler) queueHandshakePacketsForRetransmission() error {
 		return true, nil
 	})
 	for _, p := range handshakePackets {
-		h.logger.Debugf("\tQueueing packet %#x as a handshake retransmission", p.PacketNumber)
+		h.logger.Debugf("Queueing packet %#x as a handshake retransmission", p.PacketNumber)
 		if err := h.queuePacketForRetransmission(p); err != nil {
 			return err
 		}

session.go

@@ -425,7 +425,7 @@ func (s *session) postSetup() error {
 	s.lastNetworkActivityTime = now
 	s.sessionCreationTime = now
 
-	s.receivedPacketHandler = ackhandler.NewReceivedPacketHandler(s.rttStats, s.version)
+	s.receivedPacketHandler = ackhandler.NewReceivedPacketHandler(s.rttStats, s.logger, s.version)
 	s.windowUpdateQueue = newWindowUpdateQueue(s.streamsMap, s.cryptoStream, s.connFlowController, s.packer.QueueControlFrame)
 	return nil
 }
@@ -996,9 +996,9 @@ func (s *session) maybeSendRetransmission() (bool, error) {
 	}
 
 	if retransmitPacket.EncryptionLevel != protocol.EncryptionForwardSecure {
-		s.logger.Debugf("\tDequeueing handshake retransmission for packet 0x%x", retransmitPacket.PacketNumber)
+		s.logger.Debugf("Dequeueing handshake retransmission for packet 0x%x", retransmitPacket.PacketNumber)
 	} else {
-		s.logger.Debugf("\tDequeueing retransmission for packet 0x%x", retransmitPacket.PacketNumber)
+		s.logger.Debugf("Dequeueing retransmission for packet 0x%x", retransmitPacket.PacketNumber)
 	}
 
 	if s.version.UsesStopWaitingFrames() {