From d1dd2a4a60fbaa36d30c772f2b05c83ea4fac150 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Mon, 7 May 2018 09:31:37 +0900 Subject: [PATCH] add logging to the ackhandler --- .../ackhandler/received_packet_handler.go | 41 +++++++++++++-- .../received_packet_handler_test.go | 3 +- internal/ackhandler/sent_packet_handler.go | 50 ++++++++++++++++--- session.go | 6 +-- 4 files changed, 87 insertions(+), 13 deletions(-) diff --git a/internal/ackhandler/received_packet_handler.go b/internal/ackhandler/received_packet_handler.go index 57b68e6a..8af21324 100644 --- a/internal/ackhandler/received_packet_handler.go +++ b/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) - ackTime := rcvTime.Add(time.Duration(ackDelay)) + ackDelay := time.Duration(float64(h.rttStats.MinRTT()) * float64(shortAckDecimationDelay)) + 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(), diff --git a/internal/ackhandler/received_packet_handler_test.go b/internal/ackhandler/received_packet_handler_test.go index 4ebd6cf5..d845efe8 100644 --- a/internal/ackhandler/received_packet_handler_test.go +++ b/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() { diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index a5f9011d..274607be 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/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 } diff --git a/session.go b/session.go index a34f2eda..ad53499d 100644 --- a/session.go +++ b/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() {