From 72092fbc29e6f81e546a31e68a85ae9d25357eba Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Sun, 21 Jul 2024 12:31:32 -0600 Subject: [PATCH] move connection logging to a separate file, absorb logutils package (#4586) No functional change expected. --- connection.go | 125 +------------ connection_logging.go | 173 ++++++++++++++++++ ...rame_test.go => connection_logging_test.go | 10 +- internal/logutils/frame.go | 50 ----- internal/logutils/logutils_suite_test.go | 13 -- 5 files changed, 179 insertions(+), 192 deletions(-) create mode 100644 connection_logging.go rename internal/logutils/frame_test.go => connection_logging_test.go (86%) delete mode 100644 internal/logutils/frame.go delete mode 100644 internal/logutils/logutils_suite_test.go diff --git a/connection.go b/connection.go index d65f7c2ef..e603ce386 100644 --- a/connection.go +++ b/connection.go @@ -16,7 +16,6 @@ import ( "github.com/quic-go/quic-go/internal/ackhandler" "github.com/quic-go/quic-go/internal/flowcontrol" "github.com/quic-go/quic-go/internal/handshake" - "github.com/quic-go/quic-go/internal/logutils" "github.com/quic-go/quic-go/internal/protocol" "github.com/quic-go/quic-go/internal/qerr" "github.com/quic-go/quic-go/internal/utils" @@ -1261,7 +1260,7 @@ func (s *connection) handleFrames( isAckEliciting = true } if log != nil { - frames = append(frames, logutils.ConvertFrame(frame)) + frames = append(frames, toLoggingFrame(frame)) } // An error occurred handling a previous frame. // Don't handle the current frame. @@ -2157,128 +2156,6 @@ func (s *connection) maxPacketSize() protocol.ByteCount { return s.mtuDiscoverer.CurrentSize() } -func (s *connection) logLongHeaderPacket(p *longHeaderPacket, ecn protocol.ECN) { - // quic-go logging - if s.logger.Debug() { - p.header.Log(s.logger) - if p.ack != nil { - wire.LogFrame(s.logger, p.ack, true) - } - for _, frame := range p.frames { - wire.LogFrame(s.logger, frame.Frame, true) - } - for _, frame := range p.streamFrames { - wire.LogFrame(s.logger, frame.Frame, true) - } - } - - // tracing - if s.tracer != nil && s.tracer.SentLongHeaderPacket != nil { - frames := make([]logging.Frame, 0, len(p.frames)) - for _, f := range p.frames { - frames = append(frames, logutils.ConvertFrame(f.Frame)) - } - for _, f := range p.streamFrames { - frames = append(frames, logutils.ConvertFrame(f.Frame)) - } - var ack *logging.AckFrame - if p.ack != nil { - ack = logutils.ConvertAckFrame(p.ack) - } - s.tracer.SentLongHeaderPacket(p.header, p.length, ecn, ack, frames) - } -} - -func (s *connection) logShortHeaderPacket( - destConnID protocol.ConnectionID, - ackFrame *wire.AckFrame, - frames []ackhandler.Frame, - streamFrames []ackhandler.StreamFrame, - pn protocol.PacketNumber, - pnLen protocol.PacketNumberLen, - kp protocol.KeyPhaseBit, - ecn protocol.ECN, - size protocol.ByteCount, - isCoalesced bool, -) { - if s.logger.Debug() && !isCoalesced { - s.logger.Debugf("-> Sending packet %d (%d bytes) for connection %s, 1-RTT (ECN: %s)", pn, size, s.logID, ecn) - } - // quic-go logging - if s.logger.Debug() { - wire.LogShortHeader(s.logger, destConnID, pn, pnLen, kp) - if ackFrame != nil { - wire.LogFrame(s.logger, ackFrame, true) - } - for _, f := range frames { - wire.LogFrame(s.logger, f.Frame, true) - } - for _, f := range streamFrames { - wire.LogFrame(s.logger, f.Frame, true) - } - } - - // tracing - if s.tracer != nil && s.tracer.SentShortHeaderPacket != nil { - fs := make([]logging.Frame, 0, len(frames)+len(streamFrames)) - for _, f := range frames { - fs = append(fs, logutils.ConvertFrame(f.Frame)) - } - for _, f := range streamFrames { - fs = append(fs, logutils.ConvertFrame(f.Frame)) - } - var ack *logging.AckFrame - if ackFrame != nil { - ack = logutils.ConvertAckFrame(ackFrame) - } - s.tracer.SentShortHeaderPacket( - &logging.ShortHeader{ - DestConnectionID: destConnID, - PacketNumber: pn, - PacketNumberLen: pnLen, - KeyPhase: kp, - }, - size, - ecn, - ack, - fs, - ) - } -} - -func (s *connection) logCoalescedPacket(packet *coalescedPacket, ecn protocol.ECN) { - if s.logger.Debug() { - // There's a short period between dropping both Initial and Handshake keys and completion of the handshake, - // during which we might call PackCoalescedPacket but just pack a short header packet. - if len(packet.longHdrPackets) == 0 && packet.shortHdrPacket != nil { - s.logShortHeaderPacket( - packet.shortHdrPacket.DestConnID, - packet.shortHdrPacket.Ack, - packet.shortHdrPacket.Frames, - packet.shortHdrPacket.StreamFrames, - packet.shortHdrPacket.PacketNumber, - packet.shortHdrPacket.PacketNumberLen, - packet.shortHdrPacket.KeyPhase, - ecn, - packet.shortHdrPacket.Length, - false, - ) - return - } - if len(packet.longHdrPackets) > 1 { - s.logger.Debugf("-> Sending coalesced packet (%d parts, %d bytes) for connection %s", len(packet.longHdrPackets), packet.buffer.Len(), s.logID) - } else { - s.logger.Debugf("-> Sending packet %d (%d bytes) for connection %s, %s", packet.longHdrPackets[0].header.PacketNumber, packet.buffer.Len(), s.logID, packet.longHdrPackets[0].EncryptionLevel()) - } - } - for _, p := range packet.longHdrPackets { - s.logLongHeaderPacket(p, ecn) - } - if p := packet.shortHdrPacket; p != nil { - s.logShortHeaderPacket(p.DestConnID, p.Ack, p.Frames, p.StreamFrames, p.PacketNumber, p.PacketNumberLen, p.KeyPhase, ecn, p.Length, true) - } -} - // AcceptStream returns the next stream openend by the peer func (s *connection) AcceptStream(ctx context.Context) (Stream, error) { return s.streamsMap.AcceptStream(ctx) diff --git a/connection_logging.go b/connection_logging.go new file mode 100644 index 000000000..f75b39f6f --- /dev/null +++ b/connection_logging.go @@ -0,0 +1,173 @@ +package quic + +import ( + "slices" + + "github.com/quic-go/quic-go/internal/ackhandler" + "github.com/quic-go/quic-go/internal/protocol" + "github.com/quic-go/quic-go/internal/wire" + "github.com/quic-go/quic-go/logging" +) + +// ConvertFrame converts a wire.Frame into a logging.Frame. +// This makes it possible for external packages to access the frames. +// Furthermore, it removes the data slices from CRYPTO and STREAM frames. +func toLoggingFrame(frame wire.Frame) logging.Frame { + switch f := frame.(type) { + case *wire.AckFrame: + // We use a pool for ACK frames. + // Implementations of the tracer interface may hold on to frames, so we need to make a copy here. + return toLoggingAckFrame(f) + case *wire.CryptoFrame: + return &logging.CryptoFrame{ + Offset: f.Offset, + Length: protocol.ByteCount(len(f.Data)), + } + case *wire.StreamFrame: + return &logging.StreamFrame{ + StreamID: f.StreamID, + Offset: f.Offset, + Length: f.DataLen(), + Fin: f.Fin, + } + case *wire.DatagramFrame: + return &logging.DatagramFrame{ + Length: logging.ByteCount(len(f.Data)), + } + default: + return logging.Frame(frame) + } +} + +func toLoggingAckFrame(f *wire.AckFrame) *logging.AckFrame { + ack := &logging.AckFrame{ + AckRanges: slices.Clone(f.AckRanges), + DelayTime: f.DelayTime, + ECNCE: f.ECNCE, + ECT0: f.ECT0, + ECT1: f.ECT1, + } + return ack +} + +func (s *connection) logLongHeaderPacket(p *longHeaderPacket, ecn protocol.ECN) { + // quic-go logging + if s.logger.Debug() { + p.header.Log(s.logger) + if p.ack != nil { + wire.LogFrame(s.logger, p.ack, true) + } + for _, frame := range p.frames { + wire.LogFrame(s.logger, frame.Frame, true) + } + for _, frame := range p.streamFrames { + wire.LogFrame(s.logger, frame.Frame, true) + } + } + + // tracing + if s.tracer != nil && s.tracer.SentLongHeaderPacket != nil { + frames := make([]logging.Frame, 0, len(p.frames)) + for _, f := range p.frames { + frames = append(frames, toLoggingFrame(f.Frame)) + } + for _, f := range p.streamFrames { + frames = append(frames, toLoggingFrame(f.Frame)) + } + var ack *logging.AckFrame + if p.ack != nil { + ack = toLoggingAckFrame(p.ack) + } + s.tracer.SentLongHeaderPacket(p.header, p.length, ecn, ack, frames) + } +} + +func (s *connection) logShortHeaderPacket( + destConnID protocol.ConnectionID, + ackFrame *wire.AckFrame, + frames []ackhandler.Frame, + streamFrames []ackhandler.StreamFrame, + pn protocol.PacketNumber, + pnLen protocol.PacketNumberLen, + kp protocol.KeyPhaseBit, + ecn protocol.ECN, + size protocol.ByteCount, + isCoalesced bool, +) { + if s.logger.Debug() && !isCoalesced { + s.logger.Debugf("-> Sending packet %d (%d bytes) for connection %s, 1-RTT (ECN: %s)", pn, size, s.logID, ecn) + } + // quic-go logging + if s.logger.Debug() { + wire.LogShortHeader(s.logger, destConnID, pn, pnLen, kp) + if ackFrame != nil { + wire.LogFrame(s.logger, ackFrame, true) + } + for _, f := range frames { + wire.LogFrame(s.logger, f.Frame, true) + } + for _, f := range streamFrames { + wire.LogFrame(s.logger, f.Frame, true) + } + } + + // tracing + if s.tracer != nil && s.tracer.SentShortHeaderPacket != nil { + fs := make([]logging.Frame, 0, len(frames)+len(streamFrames)) + for _, f := range frames { + fs = append(fs, toLoggingFrame(f.Frame)) + } + for _, f := range streamFrames { + fs = append(fs, toLoggingFrame(f.Frame)) + } + var ack *logging.AckFrame + if ackFrame != nil { + ack = toLoggingAckFrame(ackFrame) + } + s.tracer.SentShortHeaderPacket( + &logging.ShortHeader{ + DestConnectionID: destConnID, + PacketNumber: pn, + PacketNumberLen: pnLen, + KeyPhase: kp, + }, + size, + ecn, + ack, + fs, + ) + } +} + +func (s *connection) logCoalescedPacket(packet *coalescedPacket, ecn protocol.ECN) { + if s.logger.Debug() { + // There's a short period between dropping both Initial and Handshake keys and completion of the handshake, + // during which we might call PackCoalescedPacket but just pack a short header packet. + if len(packet.longHdrPackets) == 0 && packet.shortHdrPacket != nil { + s.logShortHeaderPacket( + packet.shortHdrPacket.DestConnID, + packet.shortHdrPacket.Ack, + packet.shortHdrPacket.Frames, + packet.shortHdrPacket.StreamFrames, + packet.shortHdrPacket.PacketNumber, + packet.shortHdrPacket.PacketNumberLen, + packet.shortHdrPacket.KeyPhase, + ecn, + packet.shortHdrPacket.Length, + false, + ) + return + } + if len(packet.longHdrPackets) > 1 { + s.logger.Debugf("-> Sending coalesced packet (%d parts, %d bytes) for connection %s", len(packet.longHdrPackets), packet.buffer.Len(), s.logID) + } else { + s.logger.Debugf("-> Sending packet %d (%d bytes) for connection %s, %s", packet.longHdrPackets[0].header.PacketNumber, packet.buffer.Len(), s.logID, packet.longHdrPackets[0].EncryptionLevel()) + } + } + for _, p := range packet.longHdrPackets { + s.logLongHeaderPacket(p, ecn) + } + if p := packet.shortHdrPacket; p != nil { + s.logShortHeaderPacket(p.DestConnID, p.Ack, p.Frames, p.StreamFrames, p.PacketNumber, p.PacketNumberLen, p.KeyPhase, ecn, p.Length, true) + } +} diff --git a/internal/logutils/frame_test.go b/connection_logging_test.go similarity index 86% rename from internal/logutils/frame_test.go rename to connection_logging_test.go index 6db71561d..f64437f45 100644 --- a/internal/logutils/frame_test.go +++ b/connection_logging_test.go @@ -1,4 +1,4 @@ -package logutils +package quic import ( "github.com/quic-go/quic-go/internal/wire" @@ -10,7 +10,7 @@ import ( var _ = Describe("CRYPTO frame", func() { It("converts CRYPTO frames", func() { - f := ConvertFrame(&wire.CryptoFrame{ + f := toLoggingFrame(&wire.CryptoFrame{ Offset: 1234, Data: []byte("foobar"), }) @@ -21,7 +21,7 @@ var _ = Describe("CRYPTO frame", func() { }) It("converts STREAM frames", func() { - f := ConvertFrame(&wire.StreamFrame{ + f := toLoggingFrame(&wire.StreamFrame{ StreamID: 42, Offset: 1234, Data: []byte("foo"), @@ -36,14 +36,14 @@ var _ = Describe("CRYPTO frame", func() { }) It("converts DATAGRAM frames", func() { - f := ConvertFrame(&wire.DatagramFrame{Data: []byte("foobar")}) + f := toLoggingFrame(&wire.DatagramFrame{Data: []byte("foobar")}) Expect(f).To(BeAssignableToTypeOf(&logging.DatagramFrame{})) df := f.(*logging.DatagramFrame) Expect(df.Length).To(Equal(logging.ByteCount(6))) }) It("converts other frames", func() { - f := ConvertFrame(&wire.MaxDataFrame{MaximumData: 1234}) + f := toLoggingFrame(&wire.MaxDataFrame{MaximumData: 1234}) Expect(f).To(BeAssignableToTypeOf(&logging.MaxDataFrame{})) Expect(f).ToNot(BeAssignableToTypeOf(&logging.MaxStreamDataFrame{})) mdf := f.(*logging.MaxDataFrame) diff --git a/internal/logutils/frame.go b/internal/logutils/frame.go deleted file mode 100644 index a6032fc20..000000000 --- a/internal/logutils/frame.go +++ /dev/null @@ -1,50 +0,0 @@ -package logutils - -import ( - "github.com/quic-go/quic-go/internal/protocol" - "github.com/quic-go/quic-go/internal/wire" - "github.com/quic-go/quic-go/logging" -) - -// ConvertFrame converts a wire.Frame into a logging.Frame. -// This makes it possible for external packages to access the frames. -// Furthermore, it removes the data slices from CRYPTO and STREAM frames. -func ConvertFrame(frame wire.Frame) logging.Frame { - switch f := frame.(type) { - case *wire.AckFrame: - // We use a pool for ACK frames. - // Implementations of the tracer interface may hold on to frames, so we need to make a copy here. - return ConvertAckFrame(f) - case *wire.CryptoFrame: - return &logging.CryptoFrame{ - Offset: f.Offset, - Length: protocol.ByteCount(len(f.Data)), - } - case *wire.StreamFrame: - return &logging.StreamFrame{ - StreamID: f.StreamID, - Offset: f.Offset, - Length: f.DataLen(), - Fin: f.Fin, - } - case *wire.DatagramFrame: - return &logging.DatagramFrame{ - Length: logging.ByteCount(len(f.Data)), - } - default: - return logging.Frame(frame) - } -} - -func ConvertAckFrame(f *wire.AckFrame) *logging.AckFrame { - ranges := make([]wire.AckRange, 0, len(f.AckRanges)) - ranges = append(ranges, f.AckRanges...) - ack := &logging.AckFrame{ - AckRanges: ranges, - DelayTime: f.DelayTime, - ECNCE: f.ECNCE, - ECT0: f.ECT0, - ECT1: f.ECT1, - } - return ack -} diff --git a/internal/logutils/logutils_suite_test.go b/internal/logutils/logutils_suite_test.go deleted file mode 100644 index 8eaa613a1..000000000 --- a/internal/logutils/logutils_suite_test.go +++ /dev/null @@ -1,13 +0,0 @@ -package logutils - -import ( - "testing" - - . "github.com/onsi/ginkgo/v2" - . "github.com/onsi/gomega" -) - -func TestLogutils(t *testing.T) { - RegisterFailHandler(Fail) - RunSpecs(t, "Logutils Suite") -}