net/tstun: rate limit "self disco out packet" logging

When this happens, it is incredibly noisy in the logs.
It accounts for about a third of all remaining
"unexpected" log lines from a recent investigation.

It's not clear that we know how to fix this,
we have a functioning workaround,
and we now have a (cheap and efficient) metric for this
that we can use for measurements.

So reduce the logging to approximately once per minute.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
(cherry picked from commit 73beaaf360)
This commit is contained in:
Josh Bleecher Snyder 2021-11-23 11:20:33 -08:00 committed by Brad Fitzpatrick
parent e399b0bec8
commit e055d10f5b
3 changed files with 14 additions and 10 deletions

View File

@ -217,7 +217,7 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de
tailscale.com/types/netmap from tailscale.com/control/controlclient+ tailscale.com/types/netmap from tailscale.com/control/controlclient+
tailscale.com/types/nettype from tailscale.com/wgengine/magicsock tailscale.com/types/nettype from tailscale.com/wgengine/magicsock
tailscale.com/types/opt from tailscale.com/control/controlclient+ tailscale.com/types/opt from tailscale.com/control/controlclient+
tailscale.com/types/pad32 from tailscale.com/derp+ tailscale.com/types/pad32 from tailscale.com/derp
tailscale.com/types/persist from tailscale.com/control/controlclient+ tailscale.com/types/persist from tailscale.com/control/controlclient+
tailscale.com/types/preftype from tailscale.com/ipn+ tailscale.com/types/preftype from tailscale.com/ipn+
tailscale.com/types/structs from tailscale.com/control/controlclient+ tailscale.com/types/structs from tailscale.com/control/controlclient+

View File

@ -26,7 +26,6 @@
"tailscale.com/types/ipproto" "tailscale.com/types/ipproto"
"tailscale.com/types/key" "tailscale.com/types/key"
"tailscale.com/types/logger" "tailscale.com/types/logger"
"tailscale.com/types/pad32"
"tailscale.com/util/clientmetric" "tailscale.com/util/clientmetric"
"tailscale.com/wgengine/filter" "tailscale.com/wgengine/filter"
) )
@ -69,13 +68,16 @@
// Wrapper augments a tun.Device with packet filtering and injection. // Wrapper augments a tun.Device with packet filtering and injection.
type Wrapper struct { type Wrapper struct {
logf logger.Logf logf logger.Logf
limitedLogf logger.Logf // aggressively rate-limited logf used for potentially high volume errors
// tdev is the underlying Wrapper device. // tdev is the underlying Wrapper device.
tdev tun.Device tdev tun.Device
isTAP bool // whether tdev is a TAP device isTAP bool // whether tdev is a TAP device
closeOnce sync.Once closeOnce sync.Once
_ pad32.Four // lastActivityAtomic is read/written atomically.
// On 32 bit systems, if the fields above change,
// you might need to add a pad32.Four field here.
lastActivityAtomic mono.Time // time of last send or receive lastActivityAtomic mono.Time // time of last send or receive
destIPActivity atomic.Value // of map[netaddr.IP]func() destIPActivity atomic.Value // of map[netaddr.IP]func()
@ -168,8 +170,10 @@ func Wrap(logf logger.Logf, tdev tun.Device) *Wrapper {
} }
func wrap(logf logger.Logf, tdev tun.Device, isTAP bool) *Wrapper { func wrap(logf logger.Logf, tdev tun.Device, isTAP bool) *Wrapper {
logf = logger.WithPrefix(logf, "tstun: ")
tun := &Wrapper{ tun := &Wrapper{
logf: logger.WithPrefix(logf, "tstun: "), logf: logf,
limitedLogf: logger.RateLimitedFn(logf, 1*time.Minute, 2, 10),
isTAP: isTAP, isTAP: isTAP,
tdev: tdev, tdev: tdev,
// bufferConsumed is conceptually a condition variable: // bufferConsumed is conceptually a condition variable:
@ -421,7 +425,7 @@ func (t *Wrapper) filterOut(p *packet.Parsed) filter.Response {
// macOS in Network Extension mode might be. // macOS in Network Extension mode might be.
if p.IPProto == ipproto.UDP && // disco is over UDP; avoid isSelfDisco call for TCP/etc if p.IPProto == ipproto.UDP && // disco is over UDP; avoid isSelfDisco call for TCP/etc
t.isSelfDisco(p) { t.isSelfDisco(p) {
t.logf("[unexpected] received self disco out packet over tstun; dropping") t.limitedLogf("[unexpected] received self disco out packet over tstun; dropping")
metricPacketOutDropSelfDisco.Add(1) metricPacketOutDropSelfDisco.Add(1)
return filter.DropSilently return filter.DropSilently
} }
@ -535,7 +539,7 @@ func (t *Wrapper) filterIn(buf []byte) filter.Response {
// macOS in Network Extension mode might be. // macOS in Network Extension mode might be.
if p.IPProto == ipproto.UDP && // disco is over UDP; avoid isSelfDisco call for TCP/etc if p.IPProto == ipproto.UDP && // disco is over UDP; avoid isSelfDisco call for TCP/etc
t.isSelfDisco(p) { t.isSelfDisco(p) {
t.logf("[unexpected] received self disco in packet over tstun; dropping") t.limitedLogf("[unexpected] received self disco in packet over tstun; dropping")
metricPacketInDropSelfDisco.Add(1) metricPacketInDropSelfDisco.Add(1)
return filter.DropSilently return filter.DropSilently
} }

View File

@ -495,7 +495,7 @@ func TestPeerAPIBypass(t *testing.T) {
func TestFilterDiscoLoop(t *testing.T) { func TestFilterDiscoLoop(t *testing.T) {
var memLog tstest.MemLogger var memLog tstest.MemLogger
discoPub := key.DiscoPublicFromRaw32(mem.B([]byte{1: 1, 2: 2, 31: 0})) discoPub := key.DiscoPublicFromRaw32(mem.B([]byte{1: 1, 2: 2, 31: 0}))
tw := &Wrapper{logf: memLog.Logf} tw := &Wrapper{logf: memLog.Logf, limitedLogf: memLog.Logf}
tw.SetDiscoKey(discoPub) tw.SetDiscoKey(discoPub)
uh := packet.UDP4Header{ uh := packet.UDP4Header{
IP4Header: packet.IP4Header{ IP4Header: packet.IP4Header{