uquic/internal/wire/log_test.go

package wire

import (
	"bytes"
	"log"
	"os"
	"time"

	"github.com/refraction-networking/uquic/internal/protocol"
	"github.com/refraction-networking/uquic/internal/utils"

	. "github.com/onsi/ginkgo/v2"
	. "github.com/onsi/gomega"
)

var _ = Describe("Frame logging", func() {
	var (
		buf    *bytes.Buffer
		logger utils.Logger
	)

	BeforeEach(func() {
		buf = &bytes.Buffer{}
		logger = utils.DefaultLogger
		logger.SetLogLevel(utils.LogLevelDebug)
		log.SetOutput(buf)
	})

	AfterEach(func() {
		log.SetOutput(os.Stdout)
	})

	It("doesn't log when debug is disabled", func() {
		logger.SetLogLevel(utils.LogLevelInfo)
		LogFrame(logger, &ResetStreamFrame{}, true)
		Expect(buf.Len()).To(BeZero())
	})

	It("logs sent frames", func() {
		LogFrame(logger, &ResetStreamFrame{}, true)
		Expect(buf.String()).To(ContainSubstring("\t-> &wire.ResetStreamFrame{StreamID: 0, ErrorCode: 0x0, FinalSize: 0}\n"))
	})

	It("logs received frames", func() {
		LogFrame(logger, &ResetStreamFrame{}, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.ResetStreamFrame{StreamID: 0, ErrorCode: 0x0, FinalSize: 0}\n"))
	})

	It("logs CRYPTO frames", func() {
		frame := &CryptoFrame{
			Offset: 42,
			Data:   make([]byte, 123),
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.CryptoFrame{Offset: 42, Data length: 123, Offset + Data length: 165}\n"))
	})

	It("logs STREAM frames", func() {
		frame := &StreamFrame{
			StreamID: 42,
			Offset:   1337,
			Data:     bytes.Repeat([]byte{'f'}, 100),
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.StreamFrame{StreamID: 42, Fin: false, Offset: 1337, Data length: 100, Offset + Data length: 1437}\n"))
	})

	It("logs ACK frames without missing packets", func() {
		frame := &AckFrame{
			AckRanges: []AckRange{{Smallest: 42, Largest: 1337}},
			DelayTime: 1 * time.Millisecond,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.AckFrame{LargestAcked: 1337, LowestAcked: 42, DelayTime: 1ms}\n"))
	})

	It("logs ACK frames with ECN", func() {
		frame := &AckFrame{
			AckRanges: []AckRange{{Smallest: 42, Largest: 1337}},
			DelayTime: 1 * time.Millisecond,
			ECT0:      5,
			ECT1:      66,
			ECNCE:     777,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.AckFrame{LargestAcked: 1337, LowestAcked: 42, DelayTime: 1ms, ECT0: 5, ECT1: 66, CE: 777}\n"))
	})

	It("logs ACK frames with missing packets", func() {
		frame := &AckFrame{
			AckRanges: []AckRange{
				{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: 8, LowestAcked: 2, AckRanges: {{Largest: 8, Smallest: 5}, {Largest: 3, Smallest: 2}}, DelayTime: 12ms}\n"))
	})

	It("logs MAX_STREAMS frames", func() {
		frame := &MaxStreamsFrame{
			Type:         protocol.StreamTypeBidi,
			MaxStreamNum: 42,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.MaxStreamsFrame{Type: bidi, MaxStreamNum: 42}\n"))
	})

	It("logs MAX_DATA frames", func() {
		frame := &MaxDataFrame{
			MaximumData: 42,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.MaxDataFrame{MaximumData: 42}\n"))
	})

	It("logs MAX_STREAM_DATA frames", func() {
		frame := &MaxStreamDataFrame{
			StreamID:          10,
			MaximumStreamData: 42,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.MaxStreamDataFrame{StreamID: 10, MaximumStreamData: 42}\n"))
	})

	It("logs DATA_BLOCKED frames", func() {
		frame := &DataBlockedFrame{
			MaximumData: 1000,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.DataBlockedFrame{MaximumData: 1000}\n"))
	})

	It("logs STREAM_DATA_BLOCKED frames", func() {
		frame := &StreamDataBlockedFrame{
			StreamID:          42,
			MaximumStreamData: 1000,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.StreamDataBlockedFrame{StreamID: 42, MaximumStreamData: 1000}\n"))
	})

	It("logs STREAMS_BLOCKED frames", func() {
		frame := &StreamsBlockedFrame{
			Type:        protocol.StreamTypeBidi,
			StreamLimit: 42,
		}
		LogFrame(logger, frame, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.StreamsBlockedFrame{Type: bidi, MaxStreams: 42}\n"))
	})

	It("logs NEW_CONNECTION_ID frames", func() {
		LogFrame(logger, &NewConnectionIDFrame{
			SequenceNumber:      42,
			RetirePriorTo:       24,
			ConnectionID:        protocol.ParseConnectionID([]byte{0xde, 0xad, 0xbe, 0xef}),
			StatelessResetToken: protocol.StatelessResetToken{0x1, 0x2, 0x3, 0x4, 0x5, 0x6, 0x7, 0x8, 0x9, 0xa, 0xb, 0xc, 0xd, 0xe, 0xf, 0x10},
		}, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.NewConnectionIDFrame{SequenceNumber: 42, RetirePriorTo: 24, ConnectionID: deadbeef, StatelessResetToken: 0x0102030405060708090a0b0c0d0e0f10}"))
	})

	It("logs RETIRE_CONNECTION_ID frames", func() {
		LogFrame(logger, &RetireConnectionIDFrame{SequenceNumber: 42}, false)
		Expect(buf.String()).To(ContainSubstring("\t<- &wire.RetireConnectionIDFrame{SequenceNumber: 42}"))
	})

	It("logs NEW_TOKEN frames", func() {
		LogFrame(logger, &NewTokenFrame{
			Token: []byte{0xde, 0xad, 0xbe, 0xef},
		}, true)
		Expect(buf.String()).To(ContainSubstring("\t-> &wire.NewTokenFrame{Token: 0xdeadbeef"))
	})
})