derp: add counters to track the type of dropped packets.

Signed-off-by: David Anderson <danderson@tailscale.com>

derp/derp_server.go

@@ -106,12 +106,10 @@ type Server struct {
 	_                            [pad32bit]byte
 	packetsDropped               expvar.Int
 	packetsDroppedReason         metrics.LabelMap
-	packetsDroppedUnknown    *expvar.Int // unknown dst pubkey
+	packetsDroppedReasonCounters []*expvar.Int // indexed by dropReason
-	packetsDroppedFwdUnknown *expvar.Int // unknown dst pubkey on forward
+	packetsDroppedType           metrics.LabelMap
-	packetsDroppedGone       *expvar.Int // dst conn shutting down
+	packetsDroppedTypeDisco      *expvar.Int
-	packetsDroppedQueueHead  *expvar.Int // queue full, drop head packet
+	packetsDroppedTypeOther      *expvar.Int
-	packetsDroppedQueueTail  *expvar.Int // queue full, drop tail packet
-	packetsDroppedWrite      *expvar.Int // error writing to dst conn
 	_                            [pad32bit]byte
 	packetsForwardedOut          expvar.Int
 	packetsForwardedIn           expvar.Int
@@ -189,6 +187,7 @@ func NewServer(privateKey key.Private, logf logger.Logf) *Server {
 		limitedLogf:          logger.RateLimitedFn(logf, 30*time.Second, 5, 100),
 		packetsRecvByKind:    metrics.LabelMap{Label: "kind"},
 		packetsDroppedReason: metrics.LabelMap{Label: "reason"},
+		packetsDroppedType:   metrics.LabelMap{Label: "type"},
 		clients:              map[key.Public]*sclient{},
 		clientsEver:          map[key.Public]bool{},
 		clientsMesh:          map[key.Public]PacketForwarder{},
@@ -202,12 +201,16 @@ func NewServer(privateKey key.Private, logf logger.Logf) *Server {
 	s.initMetacert()
 	s.packetsRecvDisco = s.packetsRecvByKind.Get("disco")
 	s.packetsRecvOther = s.packetsRecvByKind.Get("other")
-	s.packetsDroppedUnknown = s.packetsDroppedReason.Get("unknown_dest")
+	s.packetsDroppedReasonCounters = []*expvar.Int{
-	s.packetsDroppedFwdUnknown = s.packetsDroppedReason.Get("unknown_dest_on_fwd")
+		s.packetsDroppedReason.Get("unknown_dest"),
-	s.packetsDroppedGone = s.packetsDroppedReason.Get("gone")
+		s.packetsDroppedReason.Get("unknown_dest_on_fwd"),
-	s.packetsDroppedQueueHead = s.packetsDroppedReason.Get("queue_head")
+		s.packetsDroppedReason.Get("gone"),
-	s.packetsDroppedQueueTail = s.packetsDroppedReason.Get("queue_tail")
+		s.packetsDroppedReason.Get("queue_head"),
-	s.packetsDroppedWrite = s.packetsDroppedReason.Get("write_error")
+		s.packetsDroppedReason.Get("queue_tail"),
+		s.packetsDroppedReason.Get("write_error"),
+	}
+	s.packetsDroppedTypeDisco = s.packetsDroppedType.Get("disco")
+	s.packetsDroppedTypeOther = s.packetsDroppedType.Get("other")
 	return s
 }
 
@@ -631,11 +634,7 @@ func (c *sclient) handleFrameForwardPacket(ft frameType, fl uint32) error {
 	s.mu.Unlock()
 
 	if dst == nil {
-		s.packetsDropped.Add(1)
+		s.recordDrop(contents, srcKey, dstKey, dropReasonUnknownDestOnFwd)
-		s.packetsDroppedFwdUnknown.Add(1)
-		if debug {
-			c.logf("dropping forwarded packet for unknown %x", dstKey)
-		}
 		return nil
 	}
 
@@ -686,11 +685,7 @@ func (c *sclient) handleFrameSendPacket(ft frameType, fl uint32) error {
 			}
 			return nil
 		}
-		s.packetsDropped.Add(1)
+		s.recordDrop(contents, c.key, dstKey, dropReasonUnknownDest)
-		s.packetsDroppedUnknown.Add(1)
-		if debug {
-			c.logf("dropping packet for unknown %x", dstKey)
-		}
 		return nil
 	}
 
@@ -702,6 +697,41 @@ func (c *sclient) handleFrameSendPacket(ft frameType, fl uint32) error {
 	return c.sendPkt(dst, p)
 }
 
+// dropReason is why we dropped a DERP frame.
+type dropReason int
+
+//go:generate stringer -type=dropReason -trimprefix=dropReason
+
+const (
+	dropReasonUnknownDest      dropReason = iota // unknown destination pubkey
+	dropReasonUnknownDestOnFwd                   // unknown destination pubkey on a derp-forwarded packet
+	dropReasonGone                               // destination tailscaled disconnected before we could send
+	dropReasonQueueHead                          // destination queue is full, dropped packet at queue head
+	dropReasonQueueTail                          // destination queue is full, dropped packet at queue tail
+	dropReasonWriteError                         // OS write() failed
+)
+
+func (s *Server) recordDrop(packetBytes []byte, srcKey, dstKey key.Public, reason dropReason) {
+	s.packetsDropped.Add(1)
+	s.packetsDroppedReasonCounters[reason].Add(1)
+	if disco.LooksLikeDiscoWrapper(packetBytes) {
+		s.packetsDroppedTypeDisco.Add(1)
+	} else {
+		s.packetsDroppedTypeOther.Add(1)
+	}
+	if verboseDropKeys[dstKey] {
+		// Preformat the log string prior to calling limitedLogf. The
+		// limiter acts based on the format string, and we want to
+		// rate-limit per src/dst keys, not on the generic "dropped
+		// stuff" message.
+		msg := fmt.Sprintf("drop (%s) %s -> %s", srcKey.ShortString(), reason, dstKey.ShortString())
+		s.limitedLogf(msg)
+	}
+	if debug {
+		s.logf("dropping packet reason=%s dst=%s disco=%v", reason, dstKey, disco.LooksLikeDiscoWrapper(packetBytes))
+	}
+}
+
 func (c *sclient) sendPkt(dst *sclient, p pkt) error {
 	s := c.s
 	dstKey := dst.key
@@ -712,11 +742,7 @@ func (c *sclient) sendPkt(dst *sclient, p pkt) error {
 	for attempt := 0; attempt < 3; attempt++ {
 		select {
 		case <-dst.done:
-			s.packetsDropped.Add(1)
+			s.recordDrop(p.bs, c.key, dstKey, dropReasonGone)
-			s.packetsDroppedGone.Add(1)
-			if debug {
-				c.logf("dropping packet for shutdown client %x", dstKey)
-			}
 			return nil
 		default:
 		}
@@ -728,35 +754,15 @@ func (c *sclient) sendPkt(dst *sclient, p pkt) error {
 
 		select {
 		case pkt := <-dst.sendQueue:
-			s.packetsDropped.Add(1)
+			s.recordDrop(pkt.bs, c.key, dstKey, dropReasonQueueHead)
-			s.packetsDroppedQueueHead.Add(1)
-			if verboseDropKeys[dstKey] {
-				// Generate a full string including src and dst, so
-				// the limiter kicks in once per src.
-				msg := fmt.Sprintf("tail drop %s -> %s", p.src.ShortString(), dstKey.ShortString())
-				c.s.limitedLogf(msg)
-			}
 			c.recordQueueTime(pkt.enqueuedAt)
-			if debug {
-				c.logf("dropping packet from client %x queue head", dstKey)
-			}
 		default:
 		}
 	}
 	// Failed to make room for packet. This can happen in a heavily
 	// contended queue with racing writers. Give up and tail-drop in
 	// this case to keep reader unblocked.
-	s.packetsDropped.Add(1)
+	s.recordDrop(p.bs, c.key, dstKey, dropReasonQueueTail)
-	s.packetsDroppedQueueTail.Add(1)
-	if verboseDropKeys[dstKey] {
-		// Generate a full string including src and dst, so
-		// the limiter kicks in once per src.
-		msg := fmt.Sprintf("head drop %s -> %s", p.src.ShortString(), dstKey.ShortString())
-		c.s.limitedLogf(msg)
-	}
-	if debug {
-		c.logf("dropping packet from client %x queue tail", dstKey)
-	}
 
 	return nil
 }
@@ -1031,12 +1037,8 @@ func (c *sclient) sendLoop(ctx context.Context) error {
 		// Drain the send queue to count dropped packets
 		for {
 			select {
-			case <-c.sendQueue:
+			case pkt := <-c.sendQueue:
-				c.s.packetsDropped.Add(1)
+				c.s.recordDrop(pkt.bs, pkt.src, c.key, dropReasonGone)
-				c.s.packetsDroppedGone.Add(1)
-				if debug {
-					c.logf("dropping packet for shutdown %x", c.key)
-				}
 			default:
 				return
 			}
@@ -1179,11 +1181,7 @@ func (c *sclient) sendPacket(srcKey key.Public, contents []byte) (err error) {
 	defer func() {
 		// Stats update.
 		if err != nil {
-			c.s.packetsDropped.Add(1)
+			c.s.recordDrop(contents, srcKey, c.key, dropReasonWriteError)
-			c.s.packetsDroppedWrite.Add(1)
-			if debug {
-				c.logf("dropping packet to %x: %v", c.key, err)
-			}
 		} else {
 			c.s.packetsSent.Add(1)
 			c.s.bytesSent.Add(int64(len(contents)))

derp/dropreason_string.go

@@ -0,0 +1,28 @@
+// Code generated by "stringer -type=dropReason -trimprefix=dropReason"; DO NOT EDIT.
+
+package derp
+
+import "strconv"
+
+func _() {
+	// An "invalid array index" compiler error signifies that the constant values have changed.
+	// Re-run the stringer command to generate them again.
+	var x [1]struct{}
+	_ = x[dropReasonUnknownDest-0]
+	_ = x[dropReasonUnknownDestOnFwd-1]
+	_ = x[dropReasonGone-2]
+	_ = x[dropReasonQueueHead-3]
+	_ = x[dropReasonQueueTail-4]
+	_ = x[dropReasonWriteError-5]
+}
+
+const _dropReason_name = "UnknownDestUnknownDestOnFwdGoneQueueHeadQueueTailWriteError"
+
+var _dropReason_index = [...]uint8{0, 11, 27, 31, 40, 49, 59}
+
+func (i dropReason) String() string {
+	if i < 0 || i >= dropReason(len(_dropReason_index)-1) {
+		return "dropReason(" + strconv.FormatInt(int64(i), 10) + ")"
+	}
+	return _dropReason_name[_dropReason_index[i]:_dropReason_index[i+1]]
+}

scripts/check_license_headers.sh

@@ -38,6 +38,9 @@ for file in $(find $1 -name '*.go' -not -path '*/.git/*'); do
         $1/wgengine/router/ifconfig_windows.go)
             # WireGuard copyright.
         ;;
+		*_string.go)
+			# Generated file from go:generate stringer
+		;;
         *)
             header="$(head -3 $file)"
             if ! check_file "$header"; then