mirrors/uquic
1
0
Fork 0
mirror of https://github.com/refraction-networking/uquic.git synced 2025-04-03 20:27:35 +03:00
Code Issues Projects Releases Packages Wiki Activity

add logging for the packet header

Browse source
This commit is contained in:
Marten Seemann 2017-10-27 08:40:02 +07:00
parent 3e39991e1e
commit a65929f6cf
9 changed files with 217 additions and 15 deletions
Download patch file Download diff file Expand all files Collapse all files

20
internal/wire/header.go
View file

@ -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()
}
}

62
internal/wire/header_test.go
View file

@ -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"))
})
})
})

12
internal/wire/ietf_header.go
View file

@ -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)
}
}

48
internal/wire/ietf_header_test.go
View file

@ -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}"))
})
})
})

13
internal/wire/public_header.go
View file

@ -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)
}

55
internal/wire/public_header_test.go
View file

@ -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}"))
})
})
})

12
packet_packer.go
View file

@ -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,

4
packet_packer_test.go
View file

@ -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)))
})

6
session.go
View file

@ -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)
}