wgengine/magicsock: limit redundant log spam on packets from low-pri addresses

Fixes #407

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

wgengine/magicsock/magicsock.go

@@ -1655,6 +1655,13 @@ type AddrSet struct {
 
 	// lastSpray is the last time we sprayed a packet.
 	lastSpray time.Time
+
+	// loggedLogPriMask is a bit field of that tracks whether
+	// we've already logged about receiving a packet from a low
+	// priority ("low-pri") address when we already have curAddr
+	// set to a better one. This is only to suppress some
+	// redundant logs.
+	loggedLogPriMask uint32
 }
 
 // derpID returns this AddrSet's home DERP node, or 0 if none is found.
@@ -1774,17 +1781,23 @@ func (a *AddrSet) UpdateDst(new *net.UDPAddr) error {
 		a.Logf("magicsock: rx %s from known %s (%d), replaces roaming address %s", pk, new, index, a.roamAddr)
 		a.roamAddr = nil
 		a.curAddr = index
+		a.loggedLogPriMask = 0
 
 	case a.curAddr == -1:
 		a.Logf("magicsock: rx %s from %s (%d/%d), set as new priority", pk, new, index, len(a.addrs))
 		a.curAddr = index
+		a.loggedLogPriMask = 0
 
 	case index < a.curAddr:
+		if 1 <= index && index <= 32 && (a.loggedLogPriMask&1<<(index-1)) == 0 {
 			a.Logf("magicsock: rx %s from low-pri %s (%d), keeping current %s (%d)", pk, new, index, old, a.curAddr)
+			a.loggedLogPriMask |= 1 << (index - 1)
+		}
 
 	default: // index > a.curAddr
 		a.Logf("magicsock: rx %s from %s (%d/%d), replaces old priority %s", pk, new, index, len(a.addrs), old)
 		a.curAddr = index
+		a.loggedLogPriMask = 0
 	}
 
 	return nil

wgengine/magicsock/magicsock_test.go

@@ -715,6 +715,7 @@ func TestAddrSet(t *testing.T) {
 		name     string
 		as       *AddrSet
 		steps    []step
+		logCheck func(t *testing.T, logged []byte)
 	}{
 		{
 			name: "reg_packet_no_curaddr",
@@ -783,12 +784,32 @@ func TestAddrSet(t *testing.T) {
 				{advance: 3, b: regPacket, want: "10.0.0.1:123"},
 			},
 		},
+		{
+			name: "low_pri",
+			as: &AddrSet{
+				addrs:   udpAddrs("127.3.3.40:1", "123.45.67.89:123", "10.0.0.1:123"),
+				curAddr: 2,
+			},
+			steps: []step{
+				{updateDst: mustUDPAddr("123.45.67.89:123")},
+				{updateDst: mustUDPAddr("123.45.67.89:123")},
+			},
+			logCheck: func(t *testing.T, logged []byte) {
+				if n := bytes.Count(logged, []byte(", keeping current ")); n != 1 {
+					t.Errorf("low-prio keeping current logged %d times; want 1", n)
+				}
+			},
+		},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			setT(t)
 			faket := time.Unix(0, 0)
-			tt.as.Logf = logf
+			var logBuf bytes.Buffer
+			tt.as.Logf = func(format string, args ...interface{}) {
+				fmt.Fprintf(&logBuf, format, args...)
+				logf(format, args...)
+			}
 			tt.as.clock = func() time.Time { return faket }
 			for i, st := range tt.steps {
 				faket = faket.Add(st.advance)
@@ -804,6 +825,9 @@ func TestAddrSet(t *testing.T) {
 					t.Errorf("step %d: got %v; want %v", i, gotStr, st.want)
 				}
 			}
+			if tt.logCheck != nil {
+				tt.logCheck(t, logBuf.Bytes())
+			}
 		})
 		setT(t)
 	}