From 280e8884dd53816cfcef36217ac532cb3e01fef0 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Thu, 11 Jun 2020 09:40:21 -0700 Subject: [PATCH] wgengine/magicsock: limit redundant log spam on packets from low-pri addresses Fixes #407 Signed-off-by: Brad Fitzpatrick --- wgengine/magicsock/magicsock.go | 15 ++++++++++++- wgengine/magicsock/magicsock_test.go | 32 ++++++++++++++++++++++++---- 2 files changed, 42 insertions(+), 5 deletions(-) diff --git a/wgengine/magicsock/magicsock.go b/wgengine/magicsock/magicsock.go index 7fa946c8f..1585f3f2e 100644 --- a/wgengine/magicsock/magicsock.go +++ b/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: - a.Logf("magicsock: rx %s from low-pri %s (%d), keeping current %s (%d)", pk, new, index, old, 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 diff --git a/wgengine/magicsock/magicsock_test.go b/wgengine/magicsock/magicsock_test.go index 859fb5b00..b13ddfa8b 100644 --- a/wgengine/magicsock/magicsock_test.go +++ b/wgengine/magicsock/magicsock_test.go @@ -712,9 +712,10 @@ func TestAddrSet(t *testing.T) { want string // comma-separated } tests := []struct { - name string - as *AddrSet - steps []step + 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) }