derp: add a debug option to verbosely log drops to a destination.

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

derp/derp_server.go

@@ -16,6 +16,7 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
+	"log"
 	"math/big"
 	"os"
 	"runtime"
@@ -24,6 +25,7 @@ import (
 	"sync"
 	"time"
 
+	"go4.org/mem"
 	"golang.org/x/crypto/nacl/box"
 	"golang.org/x/sync/errgroup"
 	"tailscale.com/disco"
@@ -35,6 +37,25 @@ import (
 
 var debug, _ = strconv.ParseBool(os.Getenv("DERP_DEBUG_LOGS"))
 
+// verboseDropKeys is the set of destination public keys that should
+// verbosely log whenever DERP drops a packet.
+var verboseDropKeys = map[key.Public]bool{}
+
+func init() {
+	keys := os.Getenv("TS_DEBUG_VERBOSE_DROPS")
+	if keys == "" {
+		return
+	}
+	for _, keyStr := range strings.Split(keys, ",") {
+		k, err := key.NewPublicFromHexMem(mem.S(keyStr))
+		if err != nil {
+			log.Printf("ignoring invalid debug key %q: %v", keyStr, err)
+		} else {
+			verboseDropKeys[k] = true
+		}
+	}
+}
+
 const (
 	perClientSendQueueDepth = 32 // packets buffered for sending
 	writeTimeout            = 2 * time.Second
@@ -53,14 +74,14 @@ type Server struct {
 	// before failing when writing to a client.
 	WriteTimeout time.Duration
 
-	privateKey key.Private
-	publicKey  key.Public
-	logf       logger.Logf
-	memSys0    uint64 // runtime.MemStats.Sys at start (or early-ish)
-	meshKey    string
+	privateKey  key.Private
+	publicKey   key.Public
+	logf        logger.Logf
+	memSys0     uint64 // runtime.MemStats.Sys at start (or early-ish)
+	meshKey     string
+	limitedLogf logger.Logf
 
 	// Counters:
-	_                        [pad32bit]byte
 	packetsSent, bytesSent   expvar.Int
 	packetsRecv, bytesRecv   expvar.Int
 	packetsRecvByKind        metrics.LabelMap
@@ -141,6 +162,7 @@ func NewServer(privateKey key.Private, logf logger.Logf) *Server {
 		privateKey:           privateKey,
 		publicKey:            privateKey.Public(),
 		logf:                 logf,
+		limitedLogf:          logger.RateLimitedFn(logf, 30*time.Second, 5, 100),
 		packetsRecvByKind:    metrics.LabelMap{Label: "kind"},
 		packetsDroppedReason: metrics.LabelMap{Label: "reason"},
 		clients:              map[key.Public]*sclient{},
@@ -624,6 +646,12 @@ func (c *sclient) sendPkt(dst *sclient, p pkt) error {
 		case <-dst.sendQueue:
 			s.packetsDropped.Add(1)
 			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)
+			}
 			if debug {
 				c.logf("dropping packet from client %x queue head", dstKey)
 			}
@@ -635,6 +663,12 @@ func (c *sclient) sendPkt(dst *sclient, p pkt) error {
 	// this case to keep reader unblocked.
 	s.packetsDropped.Add(1)
 	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)
 	}