diff --git a/internal/wire/header.go b/internal/wire/header.go index b45198c7..c77b4cb6 100644 --- a/internal/wire/header.go +++ b/internal/wire/header.go @@ -27,6 +27,9 @@ type Header struct { Type uint8 IsLongHeader bool KeyPhase int + + // only needed for logging + isPublicHeader bool } // ParseHeader parses the header. @@ -51,7 +54,12 @@ func ParseHeader(b *bytes.Reader, sentBy protocol.Perspective, version protocol. } // This is a gQUIC Public Header. - return parsePublicHeader(b, sentBy, version) + hdr, err := parsePublicHeader(b, sentBy, version) + if err != nil { + return nil, err + } + hdr.isPublicHeader = true // save that this is a Public Header, so we can log it correctly later + return hdr, nil } // PeekConnectionID parses the connection ID from a QUIC packet's public header, sent by the client. @@ -82,6 +90,7 @@ func PeekConnectionID(b *bytes.Reader) (protocol.ConnectionID, error) { // Write writes the Header. func (h *Header) Write(b *bytes.Buffer, pers protocol.Perspective, version protocol.VersionNumber) error { if !version.UsesTLS() { + h.isPublicHeader = true // save that this is a Public Header, so we can log it correctly later return h.writePublicHeader(b, pers, version) } return h.writeHeader(b) @@ -94,3 +103,12 @@ func (h *Header) GetLength(pers protocol.Perspective, version protocol.VersionNu } return h.getHeaderLength() } + +// Log logs the Header +func (h *Header) Log() { + if h.isPublicHeader { + h.logPublicHeader() + } else { + h.logHeader() + } +} diff --git a/internal/wire/header_test.go b/internal/wire/header_test.go index 126ef7a9..b205314b 100644 --- a/internal/wire/header_test.go +++ b/internal/wire/header_test.go @@ -3,8 +3,11 @@ package wire import ( "bytes" "io" + "log" + "os" "github.com/lucas-clemente/quic-go/internal/protocol" + "github.com/lucas-clemente/quic-go/internal/utils" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" ) @@ -53,6 +56,7 @@ var _ = Describe("Header", func() { Expect(err).ToNot(HaveOccurred()) Expect(hdr.KeyPhase).To(BeEquivalentTo(1)) Expect(hdr.PacketNumber).To(Equal(protocol.PacketNumber(0x42))) + Expect(hdr.isPublicHeader).To(BeFalse()) }) It("parses an IETF draft header, when the version is not known, but it has Long Header format", func() { @@ -67,6 +71,7 @@ var _ = Describe("Header", func() { Expect(err).ToNot(HaveOccurred()) Expect(hdr.Type).To(BeEquivalentTo(3)) Expect(hdr.PacketNumber).To(Equal(protocol.PacketNumber(0x42))) + Expect(hdr.isPublicHeader).To(BeFalse()) }) It("parses a gQUIC Public Header, when the version is not known", func() { @@ -83,6 +88,7 @@ var _ = Describe("Header", func() { Expect(err).ToNot(HaveOccurred()) Expect(hdr.PacketNumber).To(Equal(protocol.PacketNumber(0x1337))) Expect(hdr.Version).To(Equal(versionPublicHeader)) + Expect(hdr.isPublicHeader).To(BeTrue()) }) It("parses a gQUIC Public Header, when the version is known", func() { @@ -98,6 +104,21 @@ var _ = Describe("Header", func() { Expect(err).ToNot(HaveOccurred()) Expect(hdr.PacketNumber).To(Equal(protocol.PacketNumber(0x1337))) Expect(hdr.DiversificationNonce).To(HaveLen(32)) + Expect(hdr.isPublicHeader).To(BeTrue()) + }) + + It("errors when parsing the gQUIC header fails", func() { + buf := &bytes.Buffer{} + err := (&Header{ + VersionFlag: true, + Version: versionPublicHeader, + ConnectionID: 0x42, + PacketNumber: 0x1337, + PacketNumberLen: protocol.PacketNumberLen6, + }).writePublicHeader(buf, protocol.PerspectiveClient, versionPublicHeader) + Expect(err).ToNot(HaveOccurred()) + _, err = ParseHeader(bytes.NewReader(buf.Bytes()[0:12]), protocol.PerspectiveClient, protocol.VersionUnknown) + Expect(err).To(MatchError(io.EOF)) }) It("errors when given no data", func() { @@ -109,27 +130,31 @@ var _ = Describe("Header", func() { Context("writing", func() { It("writes a gQUIC Public Header", func() { buf := &bytes.Buffer{} - err := (&Header{ + hdr := &Header{ ConnectionID: 0x1337, PacketNumber: 0x42, PacketNumberLen: protocol.PacketNumberLen2, - }).Write(buf, protocol.PerspectiveServer, versionPublicHeader) + } + err := hdr.Write(buf, protocol.PerspectiveServer, versionPublicHeader) Expect(err).ToNot(HaveOccurred()) _, err = parsePublicHeader(bytes.NewReader(buf.Bytes()), protocol.PerspectiveServer, versionPublicHeader) Expect(err).ToNot(HaveOccurred()) + Expect(hdr.isPublicHeader).To(BeTrue()) }) It("writes a IETF draft header", func() { buf := &bytes.Buffer{} - err := (&Header{ + hdr := &Header{ ConnectionID: 0x1337, PacketNumber: 0x42, PacketNumberLen: protocol.PacketNumberLen2, KeyPhase: 1, - }).Write(buf, protocol.PerspectiveServer, versionIETFHeader) + } + err := hdr.Write(buf, protocol.PerspectiveServer, versionIETFHeader) Expect(err).ToNot(HaveOccurred()) _, err = parseHeader(bytes.NewReader(buf.Bytes()), protocol.PerspectiveServer) Expect(err).ToNot(HaveOccurred()) + Expect(hdr.isPublicHeader).To(BeFalse()) }) }) @@ -175,4 +200,33 @@ var _ = Describe("Header", func() { Expect(len).To(Equal(ietfHeaderLen)) }) }) + + Context("logging", func() { + var buf bytes.Buffer + + BeforeEach(func() { + buf.Reset() + utils.SetLogLevel(utils.LogLevelDebug) + log.SetOutput(&buf) + }) + + AfterEach(func() { + utils.SetLogLevel(utils.LogLevelNothing) + log.SetOutput(os.Stdout) + }) + + It("logs an IETF draft header", func() { + (&Header{ + IsLongHeader: true, + }).Log() + Expect(string(buf.Bytes())).To(ContainSubstring("Long Header")) + }) + + It("logs a Public Header", func() { + (&Header{ + isPublicHeader: true, + }).Log() + Expect(string(buf.Bytes())).To(ContainSubstring("Public Header")) + }) + }) }) diff --git a/internal/wire/ietf_header.go b/internal/wire/ietf_header.go index 5e35dca2..239b58d4 100644 --- a/internal/wire/ietf_header.go +++ b/internal/wire/ietf_header.go @@ -149,3 +149,15 @@ func (h *Header) getHeaderLength() (protocol.ByteCount, error) { length += protocol.ByteCount(h.PacketNumberLen) return length, nil } + +func (h *Header) logHeader() { + if h.IsLongHeader { + utils.Debugf(" Long Header{Type: %#x, ConnectionID: %#x, PacketNumber: %#x, Version: %s}", h.Type, h.ConnectionID, h.PacketNumber, h.Version) + } else { + connID := "(omitted)" + if !h.OmitConnectionID { + connID = fmt.Sprintf("%#x", h.ConnectionID) + } + utils.Debugf(" Short Header{ConnectionID: %s, PacketNumber: %#x, PacketNumberLen: %d, KeyPhase: %d}", connID, h.PacketNumber, h.PacketNumberLen, h.KeyPhase) + } +} diff --git a/internal/wire/ietf_header_test.go b/internal/wire/ietf_header_test.go index 335d96cf..33a09557 100644 --- a/internal/wire/ietf_header_test.go +++ b/internal/wire/ietf_header_test.go @@ -3,8 +3,11 @@ package wire import ( "bytes" "io" + "log" + "os" "github.com/lucas-clemente/quic-go/internal/protocol" + "github.com/lucas-clemente/quic-go/internal/utils" "github.com/lucas-clemente/quic-go/qerr" . "github.com/onsi/ginkgo" @@ -344,4 +347,49 @@ var _ = Describe("IETF draft Header", func() { Expect(err).To(MatchError("invalid packet number length: 5")) }) }) + + Context("logging", func() { + var buf bytes.Buffer + + BeforeEach(func() { + buf.Reset() + utils.SetLogLevel(utils.LogLevelDebug) + log.SetOutput(&buf) + }) + + AfterEach(func() { + utils.SetLogLevel(utils.LogLevelNothing) + log.SetOutput(os.Stdout) + }) + + It("logs Long Headers", func() { + (&Header{ + IsLongHeader: true, + Type: 0x5, + PacketNumber: 0x1337, + ConnectionID: 0xdeadbeef, + Version: 253, + }).logHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("Long Header{Type: 0x5, ConnectionID: 0xdeadbeef, PacketNumber: 0x1337, Version: 253}")) + }) + + It("logs Short Headers containing a connection ID", func() { + (&Header{ + KeyPhase: 1, + PacketNumber: 0x1337, + PacketNumberLen: 4, + ConnectionID: 0xdeadbeef, + }).logHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("Short Header{ConnectionID: 0xdeadbeef, PacketNumber: 0x1337, PacketNumberLen: 4, KeyPhase: 1}")) + }) + + It("logs Short Headers with omitted connection ID", func() { + (&Header{ + PacketNumber: 0x12, + PacketNumberLen: 1, + OmitConnectionID: true, + }).logHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("Short Header{ConnectionID: (omitted), PacketNumber: 0x12, PacketNumberLen: 1, KeyPhase: 0}")) + }) + }) }) diff --git a/internal/wire/public_header.go b/internal/wire/public_header.go index eb73e147..202052a6 100644 --- a/internal/wire/public_header.go +++ b/internal/wire/public_header.go @@ -3,6 +3,7 @@ package wire import ( "bytes" "errors" + "fmt" "io" "github.com/lucas-clemente/quic-go/internal/protocol" @@ -233,3 +234,15 @@ func (h *Header) hasPacketNumber(packetSentBy protocol.Perspective) bool { } return true } + +func (h *Header) logPublicHeader() { + connID := "(omitted)" + if !h.OmitConnectionID { + connID = fmt.Sprintf("%#x", h.ConnectionID) + } + ver := "(unset)" + if h.Version != 0 { + ver = fmt.Sprintf("%s", h.Version) + } + utils.Debugf(" Public Header{ConnectionID: %s, PacketNumber: %#x, PacketNumberLen: %d, Version: %s, DiversificationNonce: %#v}", connID, h.PacketNumber, h.PacketNumberLen, ver, h.DiversificationNonce) +} diff --git a/internal/wire/public_header_test.go b/internal/wire/public_header_test.go index bbae622a..68dd81e4 100644 --- a/internal/wire/public_header_test.go +++ b/internal/wire/public_header_test.go @@ -3,6 +3,8 @@ package wire import ( "bytes" "encoding/binary" + "log" + "os" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/utils" @@ -590,4 +592,57 @@ var _ = Describe("Public Header", func() { }) }) }) + + Context("logging", func() { + var buf bytes.Buffer + + BeforeEach(func() { + buf.Reset() + utils.SetLogLevel(utils.LogLevelDebug) + log.SetOutput(&buf) + }) + + AfterEach(func() { + utils.SetLogLevel(utils.LogLevelNothing) + log.SetOutput(os.Stdout) + }) + + It("logs a Public Header containing a connection ID", func() { + (&Header{ + ConnectionID: 0xdecafbad, + PacketNumber: 0x1337, + PacketNumberLen: 6, + Version: protocol.Version39, + }).logPublicHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("Public Header{ConnectionID: 0xdecafbad, PacketNumber: 0x1337, PacketNumberLen: 6, Version: gQUIC 39")) + }) + + It("logs a Public Header with omitted connection ID", func() { + (&Header{ + OmitConnectionID: true, + PacketNumber: 0x1337, + PacketNumberLen: 6, + Version: protocol.Version39, + }).logPublicHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("Public Header{ConnectionID: (omitted)")) + }) + + It("logs a Public Header without a version", func() { + (&Header{ + OmitConnectionID: true, + PacketNumber: 0x1337, + PacketNumberLen: 6, + }).logPublicHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("Version: (unset)")) + }) + + It("logs diversification nonces", func() { + (&Header{ + ConnectionID: 0xdecafbad, + DiversificationNonce: []byte{0xba, 0xdf, 0x00, 0x0d}, + }).logPublicHeader() + Expect(string(buf.Bytes())).To(ContainSubstring("DiversificationNonce: []byte{0xba, 0xdf, 0x0, 0xd}")) + }) + + }) }) diff --git a/packet_packer.go b/packet_packer.go index 5cc2e08a..98abe16c 100644 --- a/packet_packer.go +++ b/packet_packer.go @@ -12,7 +12,7 @@ import ( ) type packedPacket struct { - number protocol.PacketNumber + header *wire.Header raw []byte frames []wire.Frame encryptionLevel protocol.EncryptionLevel @@ -57,7 +57,7 @@ func (p *packetPacker) PackConnectionClose(ccf *wire.ConnectionCloseFrame) (*pac header := p.getHeader(encLevel) raw, err := p.writeAndSealPacket(header, frames, sealer) return &packedPacket{ - number: header.PacketNumber, + header: header, raw: raw, frames: frames, encryptionLevel: encLevel, @@ -80,7 +80,7 @@ func (p *packetPacker) PackAckPacket() (*packedPacket, error) { p.ackFrame = nil raw, err := p.writeAndSealPacket(header, frames, sealer) return &packedPacket{ - number: header.PacketNumber, + header: header, raw: raw, frames: frames, encryptionLevel: encLevel, @@ -106,7 +106,7 @@ func (p *packetPacker) PackHandshakeRetransmission(packet *ackhandler.Packet) (* p.stopWaiting = nil raw, err := p.writeAndSealPacket(header, frames, sealer) return &packedPacket{ - number: header.PacketNumber, + header: header, raw: raw, frames: frames, encryptionLevel: packet.EncryptionLevel, @@ -154,7 +154,7 @@ func (p *packetPacker) PackPacket() (*packedPacket, error) { return nil, err } return &packedPacket{ - number: header.PacketNumber, + header: header, raw: raw, frames: payloadFrames, encryptionLevel: encLevel, @@ -175,7 +175,7 @@ func (p *packetPacker) packCryptoPacket() (*packedPacket, error) { return nil, err } return &packedPacket{ - number: header.PacketNumber, + header: header, raw: raw, frames: frames, encryptionLevel: encLevel, diff --git a/packet_packer_test.go b/packet_packer_test.go index 694b0fb3..610073dd 100644 --- a/packet_packer_test.go +++ b/packet_packer_test.go @@ -257,7 +257,7 @@ var _ = Describe("Packet packer", func() { p2, err := packer.PackPacket() Expect(err).ToNot(HaveOccurred()) Expect(p2).ToNot(BeNil()) - Expect(p2.number).To(BeNumerically(">", p1.number)) + Expect(p2.header.PacketNumber).To(BeNumerically(">", p1.header.PacketNumber)) }) It("packs a StopWaitingFrame first", func() { @@ -349,7 +349,7 @@ var _ = Describe("Packet packer", func() { p, err = packer.PackPacket() Expect(err).ToNot(HaveOccurred()) Expect(p).ToNot(BeNil()) - Expect(p.number).To(Equal(protocol.PacketNumber(1))) + Expect(p.header.PacketNumber).To(Equal(protocol.PacketNumber(1))) Expect(packer.packetNumberGenerator.Peek()).To(Equal(protocol.PacketNumber(2))) }) diff --git a/session.go b/session.go index 7f413cde..a1691362 100644 --- a/session.go +++ b/session.go @@ -442,6 +442,7 @@ func (s *session) handlePacketImpl(p *receivedPacket) error { } else { utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x, %s", hdr.PacketNumber, len(data)+len(hdr.Raw), hdr.ConnectionID, packet.encryptionLevel) } + hdr.Log() } // if the decryption failed, this might be a packet sent by an attacker // don't update the remote address @@ -739,7 +740,7 @@ func (s *session) sendPacket() error { func (s *session) sendPackedPacket(packet *packedPacket) error { defer putPacketBuffer(packet.raw) err := s.sentPacketHandler.SentPacket(&ackhandler.Packet{ - PacketNumber: packet.number, + PacketNumber: packet.header.PacketNumber, Frames: packet.frames, Length: protocol.ByteCount(len(packet.raw)), EncryptionLevel: packet.encryptionLevel, @@ -769,7 +770,8 @@ func (s *session) logPacket(packet *packedPacket) { // We don't need to allocate the slices for calling the format functions return } - utils.Debugf("-> Sending packet 0x%x (%d bytes) for connection %x, %s", packet.number, len(packet.raw), s.connectionID, packet.encryptionLevel) + utils.Debugf("-> Sending packet 0x%x (%d bytes) for connection %x, %s", packet.header.PacketNumber, len(packet.raw), s.connectionID, packet.encryptionLevel) + packet.header.Log() for _, frame := range packet.frames { wire.LogFrame(frame, true) }