From dc245ca6a32110e35275df73871f7d91987eb072 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Thu, 9 Jul 2020 20:18:33 +0700 Subject: [PATCH] trace dropped packets in the server --- internal/mocks/tracer.go | 13 ++++++++ logging/interface.go | 2 ++ logging/mock_tracer_test.go | 13 ++++++++ logging/multiplex.go | 6 ++++ logging/multiplex_test.go | 7 ++++ metrics/metrics.go | 3 ++ qlog/qlog.go | 3 ++ server.go | 23 ++++++++++++- server_test.go | 66 +++++++++++++++++++++---------------- 9 files changed, 106 insertions(+), 30 deletions(-) diff --git a/internal/mocks/tracer.go b/internal/mocks/tracer.go index 1392d914f..a798d6950 100644 --- a/internal/mocks/tracer.go +++ b/internal/mocks/tracer.go @@ -5,6 +5,7 @@ package mocks import ( + net "net" reflect "reflect" gomock "github.com/golang/mock/gomock" @@ -35,6 +36,18 @@ func (m *MockTracer) EXPECT() *MockTracerMockRecorder { return m.recorder } +// DroppedPacket mocks base method +func (m *MockTracer) DroppedPacket(arg0 net.Addr, arg1 protocol.PacketType, arg2 protocol.ByteCount, arg3 logging.PacketDropReason) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "DroppedPacket", arg0, arg1, arg2, arg3) +} + +// DroppedPacket indicates an expected call of DroppedPacket +func (mr *MockTracerMockRecorder) DroppedPacket(arg0, arg1, arg2, arg3 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedPacket", reflect.TypeOf((*MockTracer)(nil).DroppedPacket), arg0, arg1, arg2, arg3) +} + // TracerForConnection mocks base method func (m *MockTracer) TracerForConnection(arg0 protocol.Perspective, arg1 protocol.ConnectionID) logging.ConnectionTracer { m.ctrl.T.Helper() diff --git a/logging/interface.go b/logging/interface.go index 05bebada8..11adb0733 100644 --- a/logging/interface.go +++ b/logging/interface.go @@ -84,6 +84,8 @@ type Tracer interface { // The destination connection ID that the client used on the first Initial packet it sent on this connection. // If nil is returned, tracing will be disabled for this connection. TracerForConnection(p Perspective, odcid ConnectionID) ConnectionTracer + + DroppedPacket(net.Addr, PacketType, ByteCount, PacketDropReason) } // A ConnectionTracer records events. diff --git a/logging/mock_tracer_test.go b/logging/mock_tracer_test.go index cebf2d0f0..4d07bc24a 100644 --- a/logging/mock_tracer_test.go +++ b/logging/mock_tracer_test.go @@ -7,6 +7,7 @@ package logging import ( gomock "github.com/golang/mock/gomock" protocol "github.com/lucas-clemente/quic-go/internal/protocol" + net "net" reflect "reflect" ) @@ -33,6 +34,18 @@ func (m *MockTracer) EXPECT() *MockTracerMockRecorder { return m.recorder } +// DroppedPacket mocks base method +func (m *MockTracer) DroppedPacket(arg0 net.Addr, arg1 protocol.PacketType, arg2 protocol.ByteCount, arg3 PacketDropReason) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "DroppedPacket", arg0, arg1, arg2, arg3) +} + +// DroppedPacket indicates an expected call of DroppedPacket +func (mr *MockTracerMockRecorder) DroppedPacket(arg0, arg1, arg2, arg3 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedPacket", reflect.TypeOf((*MockTracer)(nil).DroppedPacket), arg0, arg1, arg2, arg3) +} + // TracerForConnection mocks base method func (m *MockTracer) TracerForConnection(arg0 protocol.Perspective, arg1 protocol.ConnectionID) ConnectionTracer { m.ctrl.T.Helper() diff --git a/logging/multiplex.go b/logging/multiplex.go index fc7bf01fd..bf9d9665e 100644 --- a/logging/multiplex.go +++ b/logging/multiplex.go @@ -32,6 +32,12 @@ func (m *tracerMultiplexer) TracerForConnection(p Perspective, odcid ConnectionI return newConnectionMultiplexer(connTracers...) } +func (m *tracerMultiplexer) DroppedPacket(remote net.Addr, typ PacketType, size ByteCount, reason PacketDropReason) { + for _, t := range m.tracers { + t.DroppedPacket(remote, typ, size, reason) + } +} + type connTracerMultiplexer struct { tracers []ConnectionTracer } diff --git a/logging/multiplex_test.go b/logging/multiplex_test.go index a821fac3e..7702640a3 100644 --- a/logging/multiplex_test.go +++ b/logging/multiplex_test.go @@ -54,6 +54,13 @@ var _ = Describe("Tracing", func() { tr2.EXPECT().TracerForConnection(PerspectiveClient, ConnectionID{1, 2, 3}) Expect(tracer.TracerForConnection(PerspectiveClient, ConnectionID{1, 2, 3})).To(BeNil()) }) + + It("traces the PacketSent event", func() { + remote := &net.UDPAddr{IP: net.IPv4(4, 3, 2, 1)} + tr1.EXPECT().DroppedPacket(remote, PacketTypeRetry, ByteCount(1024), PacketDropDuplicate) + tr2.EXPECT().DroppedPacket(remote, PacketTypeRetry, ByteCount(1024), PacketDropDuplicate) + tracer.DroppedPacket(remote, PacketTypeRetry, 1024, PacketDropDuplicate) + }) }) Context("Connection Tracer", func() { diff --git a/metrics/metrics.go b/metrics/metrics.go index 351503a1f..93c022737 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -65,6 +65,9 @@ func (t *tracer) TracerForConnection(p logging.Perspective, _ logging.Connection return newConnTracer(t, p) } +func (t *tracer) DroppedPacket(net.Addr, logging.PacketType, logging.ByteCount, logging.PacketDropReason) { +} + type connTracer struct { perspective logging.Perspective tracer logging.Tracer diff --git a/qlog/qlog.go b/qlog/qlog.go index 1ecd2c26f..dfed26808 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -37,6 +37,9 @@ func (t *tracer) TracerForConnection(p logging.Perspective, odcid protocol.Conne return nil } +func (t *tracer) DroppedPacket(net.Addr, logging.PacketType, protocol.ByteCount, logging.PacketDropReason) { +} + type connectionTracer struct { mutex sync.Mutex diff --git a/server.go b/server.go index aa788686a..512b82590 100644 --- a/server.go +++ b/server.go @@ -308,6 +308,9 @@ func (s *baseServer) handlePacket(p *receivedPacket) { case s.receivedPackets <- p: default: s.logger.Debugf("Dropping packet from %s (%d bytes). Server receive queue full.", p.remoteAddr, p.Size()) + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeNotDetermined, p.Size(), logging.PacketDropDOSPrevention) + } } } @@ -316,6 +319,9 @@ func (s *baseServer) handlePacketImpl(p *receivedPacket) bool /* should the buff // The header will then be parsed again. hdr, _, _, err := wire.ParsePacket(p.data, s.config.ConnectionIDLength) if err != nil && err != wire.ErrUnsupportedVersion { + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeNotDetermined, p.Size(), logging.PacketDropHeaderParseError) + } s.logger.Debugf("Error parsing packet: %s", err) return false } @@ -325,6 +331,9 @@ func (s *baseServer) handlePacketImpl(p *receivedPacket) bool /* should the buff } if hdr.Type == protocol.PacketTypeInitial && p.Size() < protocol.MinInitialPacketSize { s.logger.Debugf("Dropping a packet that is too small to be a valid Initial (%d bytes)", p.Size()) + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeInitial, p.Size(), logging.PacketDropUnexpectedPacket) + } return false } // send a Version Negotiation Packet if the client is speaking a different protocol version @@ -338,9 +347,12 @@ func (s *baseServer) handlePacketImpl(p *receivedPacket) bool /* should the buff return true } else if hdr.Type != protocol.PacketTypeInitial { // Drop long header packets. - // There's litte point in sending a Stateless Reset, since the client + // There's little point in sending a Stateless Reset, since the client // might not have received the token yet. s.logger.Debugf("Dropping long header packet of type %s (%d bytes)", hdr.Type, len(p.data)) + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeFromHeader(hdr), p.Size(), logging.PacketDropUnexpectedPacket) + } return false } } @@ -358,6 +370,9 @@ func (s *baseServer) handlePacketImpl(p *receivedPacket) bool /* should the buff func (s *baseServer) handleInitialImpl(p *receivedPacket, hdr *wire.Header) error { if len(hdr.Token) == 0 && hdr.DestConnectionID.Len() < protocol.MinConnectionIDLenInitial { p.buffer.Release() + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeInitial, p.Size(), logging.PacketDropUnexpectedPacket) + } return errors.New("too short connection ID") } @@ -549,12 +564,18 @@ func (s *baseServer) maybeSendInvalidToken(p *receivedPacket, hdr *wire.Header) data := p.data[:hdr.ParsedLen()+hdr.Length] extHdr, err := unpackHeader(opener, hdr, data, hdr.Version) if err != nil { + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeInitial, p.Size(), logging.PacketDropHeaderParseError) + } // don't return the error here. Just drop the packet. return nil } hdrLen := extHdr.ParsedLen() if _, err := opener.Open(data[hdrLen:hdrLen], data[hdrLen:], extHdr.PacketNumber, data[:hdrLen]); err != nil { // don't return the error here. Just drop the packet. + if s.config.Tracer != nil { + s.config.Tracer.DroppedPacket(p.remoteAddr, logging.PacketTypeInitial, p.Size(), logging.PacketDropPayloadDecryptError) + } return nil } if s.logger.Debug() { diff --git a/server_test.go b/server_test.go index c7a695a7a..5b1492c52 100644 --- a/server_test.go +++ b/server_test.go @@ -14,6 +14,8 @@ import ( "sync/atomic" "time" + "github.com/lucas-clemente/quic-go/internal/mocks" + "github.com/lucas-clemente/quic-go/internal/handshake" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/qerr" @@ -60,8 +62,9 @@ var _ = Describe("Server", func() { data = data[:len(data)+16] sealer.EncryptHeader(data[n:n+16], &data[0], data[n-4:n]) return &receivedPacket{ - data: data, - buffer: buffer, + remoteAddr: &net.UDPAddr{IP: net.IPv4(4, 5, 6, 7), Port: 456}, + data: data, + buffer: buffer, } } @@ -181,12 +184,14 @@ var _ = Describe("Server", func() { Context("server accepting sessions that completed the handshake", func() { var ( - serv *baseServer - phm *MockPacketHandlerManager + serv *baseServer + phm *MockPacketHandlerManager + tracer *mocks.MockTracer ) BeforeEach(func() { - ln, err := Listen(conn, tlsConf, nil) + tracer = mocks.NewMockTracer(mockCtrl) + ln, err := Listen(conn, tlsConf, &Config{Tracer: tracer}) Expect(err).ToNot(HaveOccurred()) serv = ln.(*baseServer) phm = NewMockPacketHandlerManager(mockCtrl) @@ -200,46 +205,39 @@ var _ = Describe("Server", func() { Context("handling packets", func() { It("drops Initial packets with a too short connection ID", func() { - serv.handlePacket(getPacket(&wire.Header{ + p := getPacket(&wire.Header{ IsLongHeader: true, Type: protocol.PacketTypeInitial, DestConnectionID: protocol.ConnectionID{1, 2, 3, 4}, Version: serv.config.Versions[0], - }, nil)) + }, nil) + tracer.EXPECT().DroppedPacket(p.remoteAddr, logging.PacketTypeInitial, p.Size(), logging.PacketDropUnexpectedPacket) + serv.handlePacket(p) Consistently(conn.dataWritten).ShouldNot(Receive()) }) It("drops too small Initial", func() { - serv.handlePacket(getPacket(&wire.Header{ + p := getPacket(&wire.Header{ IsLongHeader: true, Type: protocol.PacketTypeInitial, DestConnectionID: protocol.ConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, Version: serv.config.Versions[0], }, make([]byte, protocol.MinInitialPacketSize-100), - )) - Consistently(conn.dataWritten).ShouldNot(Receive()) - }) - - It("drops packets with a too short connection ID", func() { - serv.handlePacket(getPacket(&wire.Header{ - IsLongHeader: true, - Type: protocol.PacketTypeInitial, - SrcConnectionID: protocol.ConnectionID{1, 2, 3, 4, 5, 6, 7, 8}, - DestConnectionID: protocol.ConnectionID{1, 2, 3, 4}, - Version: serv.config.Versions[0], - }, make([]byte, protocol.MinInitialPacketSize))) + ) + tracer.EXPECT().DroppedPacket(p.remoteAddr, logging.PacketTypeInitial, p.Size(), logging.PacketDropUnexpectedPacket) + serv.handlePacket(p) Consistently(conn.dataWritten).ShouldNot(Receive()) }) It("drops non-Initial packets", func() { - serv.handlePacket(getPacket( - &wire.Header{ - IsLongHeader: true, - Type: protocol.PacketTypeHandshake, - Version: serv.config.Versions[0], - }, - []byte("invalid"), - )) + p := getPacket(&wire.Header{ + IsLongHeader: true, + Type: protocol.PacketTypeHandshake, + Version: serv.config.Versions[0], + }, []byte("invalid")) + tracer.EXPECT().DroppedPacket(p.remoteAddr, logging.PacketTypeHandshake, p.Size(), logging.PacketDropUnexpectedPacket) + serv.handlePacket(p) + Consistently(conn.dataWritten).ShouldNot(Receive()) }) It("decodes the token from the Token field", func() { @@ -321,6 +319,7 @@ var _ = Describe("Server", func() { fn() return true }) + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, protocol.ConnectionID{0xde, 0xad, 0xc0, 0xde}) sess := NewMockQuicSession(mockCtrl) serv.newSession = func( _ connection, @@ -466,6 +465,7 @@ var _ = Describe("Server", func() { packet := getPacket(hdr, make([]byte, protocol.MinInitialPacketSize)) packet.data[len(packet.data)-10] ^= 0xff // corrupt the packet packet.remoteAddr = &net.UDPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 1337} + tracer.EXPECT().DroppedPacket(packet.remoteAddr, logging.PacketTypeInitial, packet.Size(), logging.PacketDropPayloadDecryptError) serv.handlePacket(packet) Consistently(conn.dataWritten).ShouldNot(Receive()) }) @@ -494,6 +494,7 @@ var _ = Describe("Server", func() { fn() return true }) + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, protocol.ConnectionID{1, 2, 3, 4, 5, 6, 7, 8, 9, 10}) sess := NewMockQuicSession(mockCtrl) serv.newSession = func( @@ -592,6 +593,7 @@ var _ = Describe("Server", func() { fn() return true }) + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, gomock.Any()) Expect(serv.handlePacketImpl(initialPacket)).To(BeTrue()) Expect(createdSession).To(BeTrue()) }) @@ -602,6 +604,7 @@ var _ = Describe("Server", func() { fn() return true }).AnyTimes() + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, gomock.Any()).AnyTimes() serv.config.AcceptToken = func(net.Addr, *Token) bool { return true } acceptSession := make(chan struct{}) @@ -633,7 +636,9 @@ var _ = Describe("Server", func() { return sess } - serv.handlePacket(getInitial(protocol.ConnectionID{1, 2, 3, 4, 5, 6, 7, 8})) + p := getInitial(protocol.ConnectionID{1, 2, 3, 4, 5, 6, 7, 8}) + serv.handlePacket(p) + tracer.EXPECT().DroppedPacket(p.remoteAddr, logging.PacketTypeNotDetermined, p.Size(), logging.PacketDropDOSPrevention).MinTimes(1) var wg sync.WaitGroup for i := 0; i < 3*protocol.MaxServerUnprocessedPackets; i++ { wg.Add(1) @@ -719,6 +724,7 @@ var _ = Describe("Server", func() { fn() return true }).Times(protocol.MaxAcceptQueueSize) + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, gomock.Any()).Times(protocol.MaxAcceptQueueSize) var wg sync.WaitGroup wg.Add(protocol.MaxAcceptQueueSize) @@ -784,6 +790,7 @@ var _ = Describe("Server", func() { fn() return true }) + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, gomock.Any()) serv.handlePacket(p) Consistently(conn.dataWritten).ShouldNot(Receive()) @@ -887,6 +894,7 @@ var _ = Describe("Server", func() { fn() return true }) + tracer.EXPECT().TracerForConnection(protocol.PerspectiveServer, gomock.Any()) serv.createNewSession(&net.UDPAddr{}, nil, nil, nil, nil, nil, protocol.VersionWhatever) Consistently(done).ShouldNot(BeClosed()) cancel() // complete the handshake