From 140b90449b65b16b7a2183d433a00b8db6824a04 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Wed, 15 Apr 2020 15:15:45 +0700 Subject: [PATCH] use decimal numbers when logging packet numbers --- internal/ackhandler/received_packet_tracker.go | 4 ++-- internal/ackhandler/sent_packet_handler.go | 10 +++++----- internal/wire/extended_header.go | 4 ++-- internal/wire/extended_header_test.go | 16 ++++++++-------- internal/wire/log.go | 6 +++--- internal/wire/log_test.go | 10 +++++----- session.go | 6 +++--- 7 files changed, 28 insertions(+), 28 deletions(-) diff --git a/internal/ackhandler/received_packet_tracker.go b/internal/ackhandler/received_packet_tracker.go index b7f0a03d..1b5337ae 100644 --- a/internal/ackhandler/received_packet_tracker.go +++ b/internal/ackhandler/received_packet_tracker.go @@ -68,7 +68,7 @@ func (h *receivedPacketTracker) IgnoreBelow(p protocol.PacketNumber) { h.ignoreBelow = p h.packetHistory.DeleteBelow(p) if h.logger.Debug() { - h.logger.Debugf("\tIgnoring all packets below %#x.", p) + h.logger.Debugf("\tIgnoring all packets below %d.", p) } } @@ -106,7 +106,7 @@ func (h *receivedPacketTracker) maybeQueueAck(packetNumber protocol.PacketNumber // 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.logger.Debugf("\tQueueing ACK because packet %d was missing before.", packetNumber) } h.ackQueued = true } diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index 690915a5..9fbc3cb0 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -213,7 +213,7 @@ func (h *sentPacketHandler) sentPacketImpl(packet *Packet) bool /* is ack-elicit if h.logger.Debug() && pnSpace.history.HasOutstandingPackets() { for p := utils.MaxPacketNumber(0, pnSpace.largestSent+1); p < packet.PacketNumber; p++ { - h.logger.Debugf("Skipping packet number %#x", p) + h.logger.Debugf("Skipping packet number %d", p) } } @@ -332,7 +332,7 @@ func (h *sentPacketHandler) detectAndRemoveAckedPackets(ack *wire.AckFrame, encL if p.PacketNumber >= ackRange.Smallest { // packet i contained in ACK range if p.PacketNumber > ackRange.Largest { - return false, fmt.Errorf("BUG: ackhandler would have acked wrong packet 0x%x, while evaluating range 0x%x -> 0x%x", p.PacketNumber, ackRange.Smallest, ackRange.Largest) + return false, fmt.Errorf("BUG: ackhandler would have acked wrong packet %d, while evaluating range %d -> %d", p.PacketNumber, ackRange.Smallest, ackRange.Largest) } ackedPackets = append(ackedPackets, p) } @@ -346,7 +346,7 @@ func (h *sentPacketHandler) detectAndRemoveAckedPackets(ack *wire.AckFrame, encL for i, p := range ackedPackets { pns[i] = p.PacketNumber } - h.logger.Debugf("\tnewly acked packets (%d): %#x", len(pns), pns) + h.logger.Debugf("\tnewly acked packets (%d): %d", len(pns), pns) } for _, p := range ackedPackets { @@ -500,7 +500,7 @@ func (h *sentPacketHandler) detectAndRemoveLostPackets(now time.Time, encLevel p // Note: This conditional is only entered once per call lossTime := packet.SendTime.Add(lossDelay) if h.logger.Debug() { - h.logger.Debugf("\tsetting loss timer for packet %#x (%s) to %s (in %s)", packet.PacketNumber, encLevel, lossDelay, lossTime) + h.logger.Debugf("\tsetting loss timer for packet %d (%s) to %s (in %s)", packet.PacketNumber, encLevel, lossDelay, lossTime) } pnSpace.lossTime = lossTime } @@ -514,7 +514,7 @@ func (h *sentPacketHandler) detectAndRemoveLostPackets(now time.Time, encLevel p for i, p := range lostPackets { pns[i] = p.PacketNumber } - h.logger.Debugf("\tlost packets (%d): %#x", len(pns), pns) + h.logger.Debugf("\tlost packets (%d): %d", len(pns), pns) } for _, p := range lostPackets { diff --git a/internal/wire/extended_header.go b/internal/wire/extended_header.go index 26aa453a..48c627b7 100644 --- a/internal/wire/extended_header.go +++ b/internal/wire/extended_header.go @@ -226,8 +226,8 @@ func (h *ExtendedHeader) Log(logger utils.Logger) { return } } - logger.Debugf("\tLong Header{Type: %s, DestConnectionID: %s, SrcConnectionID: %s, %sPacketNumber: %#x, PacketNumberLen: %d, Length: %d, Version: %s}", h.Type, h.DestConnectionID, h.SrcConnectionID, token, h.PacketNumber, h.PacketNumberLen, h.Length, h.Version) + logger.Debugf("\tLong Header{Type: %s, DestConnectionID: %s, SrcConnectionID: %s, %sPacketNumber: %d, PacketNumberLen: %d, Length: %d, Version: %s}", h.Type, h.DestConnectionID, h.SrcConnectionID, token, h.PacketNumber, h.PacketNumberLen, h.Length, h.Version) } else { - logger.Debugf("\tShort Header{DestConnectionID: %s, PacketNumber: %#x, PacketNumberLen: %d, KeyPhase: %s}", h.DestConnectionID, h.PacketNumber, h.PacketNumberLen, h.KeyPhase) + logger.Debugf("\tShort Header{DestConnectionID: %s, PacketNumber: %d, PacketNumberLen: %d, KeyPhase: %s}", h.DestConnectionID, h.PacketNumber, h.PacketNumberLen, h.KeyPhase) } } diff --git a/internal/wire/extended_header_test.go b/internal/wire/extended_header_test.go index 442452e9..bb49030d 100644 --- a/internal/wire/extended_header_test.go +++ b/internal/wire/extended_header_test.go @@ -322,10 +322,10 @@ var _ = Describe("Header", func() { Length: 54321, Version: 0xfeed, }, - PacketNumber: 0x1337, + PacketNumber: 1337, PacketNumberLen: protocol.PacketNumberLen2, }).Log(logger) - Expect(buf.String()).To(ContainSubstring("Long Header{Type: Handshake, DestConnectionID: 0xdeadbeefcafe1337, SrcConnectionID: 0xdecafbad13371337, PacketNumber: 0x1337, PacketNumberLen: 2, Length: 54321, Version: 0xfeed}")) + Expect(buf.String()).To(ContainSubstring("Long Header{Type: Handshake, DestConnectionID: 0xdeadbeefcafe1337, SrcConnectionID: 0xdecafbad13371337, PacketNumber: 1337, PacketNumberLen: 2, Length: 54321, Version: 0xfeed}")) }) It("logs Initial Packets with a Token", func() { @@ -339,10 +339,10 @@ var _ = Describe("Header", func() { Length: 100, Version: 0xfeed, }, - PacketNumber: 0x42, + PacketNumber: 42, PacketNumberLen: protocol.PacketNumberLen2, }).Log(logger) - Expect(buf.String()).To(ContainSubstring("Long Header{Type: Initial, DestConnectionID: 0xcafe1337, SrcConnectionID: 0xdecafbad, Token: 0xdeadbeef, PacketNumber: 0x42, PacketNumberLen: 2, Length: 100, Version: 0xfeed}")) + Expect(buf.String()).To(ContainSubstring("Long Header{Type: Initial, DestConnectionID: 0xcafe1337, SrcConnectionID: 0xdecafbad, Token: 0xdeadbeef, PacketNumber: 42, PacketNumberLen: 2, Length: 100, Version: 0xfeed}")) }) It("logs Initial packets without a Token", func() { @@ -355,10 +355,10 @@ var _ = Describe("Header", func() { Length: 100, Version: 0xfeed, }, - PacketNumber: 0x42, + PacketNumber: 42, PacketNumberLen: protocol.PacketNumberLen2, }).Log(logger) - Expect(buf.String()).To(ContainSubstring("Long Header{Type: Initial, DestConnectionID: 0xcafe1337, SrcConnectionID: 0xdecafbad, Token: (empty), PacketNumber: 0x42, PacketNumberLen: 2, Length: 100, Version: 0xfeed}")) + Expect(buf.String()).To(ContainSubstring("Long Header{Type: Initial, DestConnectionID: 0xcafe1337, SrcConnectionID: 0xdecafbad, Token: (empty), PacketNumber: 42, PacketNumberLen: 2, Length: 100, Version: 0xfeed}")) }) It("logs Retry packets with a Token", func() { @@ -381,10 +381,10 @@ var _ = Describe("Header", func() { DestConnectionID: protocol.ConnectionID{0xde, 0xad, 0xbe, 0xef, 0xca, 0xfe, 0x13, 0x37}, }, KeyPhase: protocol.KeyPhaseOne, - PacketNumber: 0x1337, + PacketNumber: 1337, PacketNumberLen: 4, }).Log(logger) - Expect(buf.String()).To(ContainSubstring("Short Header{DestConnectionID: 0xdeadbeefcafe1337, PacketNumber: 0x1337, PacketNumberLen: 4, KeyPhase: 1}")) + Expect(buf.String()).To(ContainSubstring("Short Header{DestConnectionID: 0xdeadbeefcafe1337, PacketNumber: 1337, PacketNumberLen: 4, KeyPhase: 1}")) }) }) }) diff --git a/internal/wire/log.go b/internal/wire/log.go index 6013c8be..c2792161 100644 --- a/internal/wire/log.go +++ b/internal/wire/log.go @@ -27,11 +27,11 @@ func LogFrame(logger utils.Logger, frame Frame, sent bool) { if len(f.AckRanges) > 1 { ackRanges := make([]string, len(f.AckRanges)) for i, r := range f.AckRanges { - ackRanges[i] = fmt.Sprintf("{Largest: %#x, Smallest: %#x}", r.Largest, r.Smallest) + ackRanges[i] = fmt.Sprintf("{Largest: %d, Smallest: %d}", r.Largest, r.Smallest) } - logger.Debugf("\t%s &wire.AckFrame{LargestAcked: %#x, LowestAcked: %#x, AckRanges: {%s}, DelayTime: %s}", dir, f.LargestAcked(), f.LowestAcked(), strings.Join(ackRanges, ", "), f.DelayTime.String()) + logger.Debugf("\t%s &wire.AckFrame{LargestAcked: %d, LowestAcked: %d, AckRanges: {%s}, DelayTime: %s}", dir, f.LargestAcked(), f.LowestAcked(), strings.Join(ackRanges, ", "), f.DelayTime.String()) } else { - logger.Debugf("\t%s &wire.AckFrame{LargestAcked: %#x, LowestAcked: %#x, DelayTime: %s}", dir, f.LargestAcked(), f.LowestAcked(), f.DelayTime.String()) + logger.Debugf("\t%s &wire.AckFrame{LargestAcked: %d, LowestAcked: %d, DelayTime: %s}", dir, f.LargestAcked(), f.LowestAcked(), f.DelayTime.String()) } case *MaxStreamsFrame: switch f.Type { diff --git a/internal/wire/log_test.go b/internal/wire/log_test.go index 51bc92dd..9cfdeb27 100644 --- a/internal/wire/log_test.go +++ b/internal/wire/log_test.go @@ -68,23 +68,23 @@ var _ = Describe("Frame logging", func() { It("logs ACK frames without missing packets", func() { frame := &AckFrame{ - AckRanges: []AckRange{{Smallest: 0x42, Largest: 0x1337}}, + AckRanges: []AckRange{{Smallest: 42, Largest: 1337}}, DelayTime: 1 * time.Millisecond, } LogFrame(logger, frame, false) - Expect(buf.String()).To(ContainSubstring("\t<- &wire.AckFrame{LargestAcked: 0x1337, LowestAcked: 0x42, DelayTime: 1ms}\n")) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.AckFrame{LargestAcked: 1337, LowestAcked: 42, DelayTime: 1ms}\n")) }) It("logs ACK frames with missing packets", func() { frame := &AckFrame{ AckRanges: []AckRange{ - {Smallest: 0x5, Largest: 0x8}, - {Smallest: 0x2, Largest: 0x3}, + {Smallest: 5, Largest: 8}, + {Smallest: 2, Largest: 3}, }, DelayTime: 12 * time.Millisecond, } LogFrame(logger, frame, false) - Expect(buf.String()).To(ContainSubstring("\t<- &wire.AckFrame{LargestAcked: 0x8, LowestAcked: 0x2, AckRanges: {{Largest: 0x8, Smallest: 0x5}, {Largest: 0x3, Smallest: 0x2}}, DelayTime: 12ms}\n")) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.AckFrame{LargestAcked: 8, LowestAcked: 2, AckRanges: {{Largest: 8, Smallest: 5}, {Largest: 3, Smallest: 2}}, DelayTime: 12ms}\n")) }) It("logs MAX_STREAMS frames", func() { diff --git a/session.go b/session.go index b95cee30..89160777 100644 --- a/session.go +++ b/session.go @@ -795,7 +795,7 @@ func (s *session) handleSinglePacket(p *receivedPacket, hdr *wire.Header) bool / } if s.logger.Debug() { - s.logger.Debugf("<- Reading packet %#x (%d bytes) for connection %s, %s", packet.packetNumber, len(p.data), hdr.DestConnectionID, packet.encryptionLevel) + s.logger.Debugf("<- Reading packet %d (%d bytes) for connection %s, %s", packet.packetNumber, len(p.data), hdr.DestConnectionID, packet.encryptionLevel) packet.hdr.Log(s.logger) } @@ -1499,7 +1499,7 @@ func (s *session) logCoalescedPacket(now time.Time, packet *coalescedPacket) { if len(packet.packets) > 1 { s.logger.Debugf("-> Sending coalesced packet (%d parts, %d bytes) for connection %s", len(packet.packets), packet.buffer.Len(), s.logID) } else { - s.logger.Debugf("-> Sending packet %#x (%d bytes) for connection %s, %s", packet.packets[0].header.PacketNumber, packet.buffer.Len(), s.logID, packet.packets[0].EncryptionLevel()) + s.logger.Debugf("-> Sending packet %d (%d bytes) for connection %s, %s", packet.packets[0].header.PacketNumber, packet.buffer.Len(), s.logID, packet.packets[0].EncryptionLevel()) } } for _, p := range packet.packets { @@ -1509,7 +1509,7 @@ func (s *session) logCoalescedPacket(now time.Time, packet *coalescedPacket) { func (s *session) logPacket(now time.Time, packet *packedPacket) { if s.logger.Debug() { - s.logger.Debugf("-> Sending packet %#x (%d bytes) for connection %s, %s", packet.header.PacketNumber, packet.buffer.Len(), s.logID, packet.EncryptionLevel()) + s.logger.Debugf("-> Sending packet %d (%d bytes) for connection %s, %s", packet.header.PacketNumber, packet.buffer.Len(), s.logID, packet.EncryptionLevel()) } s.logPacketContents(now, packet.packetContents) }