From bb55694c95fe63899c580bcc24526229a05da2a2 Mon Sep 17 00:00:00 2001 From: Wendi Yu <45118370+wendi-yu@users.noreply.github.com> Date: Fri, 15 May 2020 14:13:44 -0600 Subject: [PATCH] wgengine: log node IDs when peers are added/removed (#381) Also stop logging data sent/received from nodes we're not connected to (ie all those `x`s being logged in the `peers: ` line) Signed-off-by: Wendi --- cmd/tailscaled/tailscaled.go | 3 +- go.sum | 1 + ipn/ipnserver/server_test.go | 6 +-- ipn/local.go | 10 +++-- tailcfg/tailcfg.go | 2 +- types/logger/logger.go | 27 ++++++++++++-- types/logger/logger_test.go | 71 ++++++++++++++++++++++++++++-------- 7 files changed, 92 insertions(+), 28 deletions(-) diff --git a/cmd/tailscaled/tailscaled.go b/cmd/tailscaled/tailscaled.go index 63b4d3a0d..b3d41ddd2 100644 --- a/cmd/tailscaled/tailscaled.go +++ b/cmd/tailscaled/tailscaled.go @@ -15,6 +15,7 @@ import ( "net/http" "net/http/pprof" "runtime" + "time" "github.com/apenwarr/fixconsole" "github.com/pborman/getopt/v2" @@ -52,7 +53,7 @@ func main() { socketpath := getopt.StringLong("socket", 's', paths.DefaultTailscaledSocket(), "Path of the service unix socket") logf := wgengine.RusagePrefixLog(log.Printf) - logf = logger.RateLimitedFn(logf, 1, 1, 100) + logf = logger.RateLimitedFn(logf, 1*time.Second, 1, 100) err := fixconsole.FixConsoleIfNeeded() if err != nil { diff --git a/go.sum b/go.sum index 9bb08fe67..a07686ec5 100644 --- a/go.sum +++ b/go.sum @@ -132,6 +132,7 @@ golang.org/x/text v0.3.2 h1:tW2bmiBqwgJj/UpqtC8EpXEZVYOwU0yG4iWbprSVAcs= golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk= golang.org/x/time v0.0.0-20191024005414-555d28b269f0 h1:/5xXl8Y5W96D+TtHSlonuFqGHIWVuyCkGJLwGh9JJFs= golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= +golang.org/x/time v0.0.0-20200416051211-89c76fbcd5d1 h1:NusfzzA6yGQ+ua51ck7E3omNUX/JuqbFSaRGqU8CcLI= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543 h1:E7g+9GITq07hpfrRu66IVDexMakfv52eLZ2CXBWiKr4= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= diff --git a/ipn/ipnserver/server_test.go b/ipn/ipnserver/server_test.go index 582f53a53..549b617c3 100644 --- a/ipn/ipnserver/server_test.go +++ b/ipn/ipnserver/server_test.go @@ -13,8 +13,6 @@ import ( "strings" "testing" - "tailscale.com/types/logger" - "tailscale.com/ipn" "tailscale.com/ipn/ipnserver" "tailscale.com/safesocket" @@ -34,14 +32,12 @@ func TestRunMultipleAccepts(t *testing.T) { defer os.RemoveAll(td) socketPath := filepath.Join(td, "tailscale.sock") - ulogf := func(format string, args ...interface{}) { + logf := func(format string, args ...interface{}) { format = strings.TrimRight(format, "\n") println(fmt.Sprintf(format, args...)) t.Logf(format, args...) } - logf := logger.RateLimitedFn(ulogf, 1, 1, 100) - connect := func() { for i := 1; i <= 2; i++ { logf("connect %d ...", i) diff --git a/ipn/local.go b/ipn/local.go index 0164fe5be..f571bc98a 100644 --- a/ipn/local.go +++ b/ipn/local.go @@ -36,6 +36,7 @@ type LocalBackend struct { ctx context.Context // valid until Close ctxCancel context.CancelFunc // closes ctx logf logger.Logf + keyLogf logger.Logf e wgengine.Engine store StateStore serverURL string // tailcontrol URL @@ -85,6 +86,7 @@ func NewLocalBackend(logf logger.Logf, logid string, store StateStore, e wgengin ctx: ctx, ctxCancel: cancel, logf: logf, + keyLogf: logger.LogOnChange(logf, 5*time.Minute, time.Now), e: e, store: store, backendLogID: logid, @@ -554,22 +556,24 @@ func (b *LocalBackend) Expiry() time.Time { func (b *LocalBackend) parseWgStatus(s *wgengine.Status) EngineStatus { var ss []string + var ps []string var rx, tx wgengine.ByteCount peers := make(map[tailcfg.NodeKey]wgengine.PeerStatus) live := 0 for _, p := range s.Peers { - if p.LastHandshake.IsZero() { - ss = append(ss, "x") - } else { + if !p.LastHandshake.IsZero() { ss = append(ss, fmt.Sprintf("%d/%d", p.RxBytes, p.TxBytes)) live++ peers[p.NodeKey] = p + + ps = append(ps, p.NodeKey.ShortString()) } rx += p.RxBytes tx += p.TxBytes } if len(ss) != 0 { + b.keyLogf("peer keys: %s", strings.Join(ps, " ")) b.logf("v%v peers: %v", version.LONG, strings.Join(ss, " ")) } return EngineStatus{ diff --git a/tailcfg/tailcfg.go b/tailcfg/tailcfg.go index 7bcc46a70..f1ddb1ee8 100644 --- a/tailcfg/tailcfg.go +++ b/tailcfg/tailcfg.go @@ -35,7 +35,7 @@ type CapabilityID ID // MachineKey is the curve25519 public key for a machine. type MachineKey [32]byte -// MachineKey is the curve25519 public key for a node. +// NodeKey is the curve25519 public key for a node. type NodeKey [32]byte type Group struct { diff --git a/types/logger/logger.go b/types/logger/logger.go index 9e4bc72d9..f82f0b2d8 100644 --- a/types/logger/logger.go +++ b/types/logger/logger.go @@ -15,6 +15,7 @@ import ( "io/ioutil" "log" "sync" + "time" "golang.org/x/time/rate" ) @@ -60,10 +61,10 @@ type limitData struct { } // RateLimitedFn returns a rate-limiting Logf wrapping the given logf. -// Messages are allowed through at a maximum of f messages/second, in +// Messages are allowed through at a maximum of one message every f (where f is a time.Duration), in // bursts of up to burst messages at a time. Up to maxCache strings will be held at a time. -func RateLimitedFn(logf Logf, f float64, burst int, maxCache int) Logf { - r := rate.Limit(f) +func RateLimitedFn(logf Logf, f time.Duration, burst int, maxCache int) Logf { + r := rate.Every(f) var ( mu sync.Mutex msgLim = make(map[string]*limitData) // keyed by logf format @@ -109,9 +110,29 @@ func RateLimitedFn(logf Logf, f float64, burst int, maxCache int) Logf { case warn: logf("Repeated messages were suppressed by rate limiting. Original message: %s", fmt.Sprintf(format, args...)) + } + } +} +// LogOnChange logs a given line only if line != lastLine, or if maxInterval has passed +// since the last time this identical line was logged. +func LogOnChange(logf Logf, maxInterval time.Duration, timeNow func() time.Time) Logf { + var ( + sLastLogged string + tLastLogged = timeNow() + ) + + return func(format string, args ...interface{}) { + s := fmt.Sprintf(format, args...) + if s == sLastLogged && timeNow().Sub(tLastLogged) < maxInterval { + return } + + sLastLogged = s + tLastLogged = timeNow() + logf(s) } + } // ArgWriter is a fmt.Formatter that can be passed to any Logf func to diff --git a/types/logger/logger_test.go b/types/logger/logger_test.go index bd4470875..8bb38477f 100644 --- a/types/logger/logger_test.go +++ b/types/logger/logger_test.go @@ -10,6 +10,7 @@ import ( "fmt" "log" "testing" + "time" ) func TestFuncWriter(t *testing.T) { @@ -23,22 +24,21 @@ func TestStdLogger(t *testing.T) { lg.Printf("plumbed through") } -func TestRateLimiter(t *testing.T) { - - // Testing function. args[0] should indicate what should - logTester := func(want []string) Logf { - i := 0 - return func(format string, args ...interface{}) { - got := fmt.Sprintf(format, args...) - if i >= len(want) { - t.Fatalf("Logging continued past end of expected input: %s", got) - } - if got != want[i] { - t.Fatalf("wanted: %s \n got: %s", want[i], got) - } - i++ +func logTester(want []string, t *testing.T, i *int) Logf { + return func(format string, args ...interface{}) { + got := fmt.Sprintf(format, args...) + if *i >= len(want) { + t.Fatalf("Logging continued past end of expected input: %s", got) + } + if got != want[*i] { + t.Fatalf("wanted: %s \n got: %s", want[*i], got) } + t.Log(got) + *i++ } +} + +func TestRateLimiter(t *testing.T) { want := []string{ "boring string with constant formatting (constant)", @@ -51,7 +51,9 @@ func TestRateLimiter(t *testing.T) { "4 shouldn't get filtered.", } - lg := RateLimitedFn(logTester(want), 1, 2, 50) + testsRun := 0 + lgtest := logTester(want, t, &testsRun) + lg := RateLimitedFn(lgtest, 1*time.Second, 2, 50) var prefixed Logf for i := 0; i < 10; i++ { lg("boring string with constant formatting %s", "(constant)") @@ -62,7 +64,46 @@ func TestRateLimiter(t *testing.T) { prefixed(" shouldn't get filtered.") } } + if testsRun < len(want) { + t.Fatalf("Tests after %s weren't logged.", want[testsRun]) + } + +} +func testTimer(d time.Duration) func() time.Time { + timeNow := time.Now() + return func() time.Time { + timeNow = timeNow.Add(d) + return timeNow + } +} + +func TestLogOnChange(t *testing.T) { + want := []string{ + "1 2 3 4 5 6", + "1 2 3 4 5 6", + "1 2 3 4 5 7", + "1 2 3 4 5", + "1 2 3 4 5 6 7", + } + + timeNow := testTimer(1 * time.Second) + + testsRun := 0 + lgtest := logTester(want, t, &testsRun) + lg := LogOnChange(lgtest, 5*time.Second, timeNow) + + for i := 0; i < 10; i++ { + lg("%s", "1 2 3 4 5 6") + } + lg("1 2 3 4 5 7") + lg("1 2 3 4 5") + lg("1 2 3 4 5") + lg("1 2 3 4 5 6 7") + + if testsRun < len(want) { + t.Fatalf("'Wanted' lines including and after [%s] weren't logged.", want[testsRun]) + } } func TestArgWriter(t *testing.T) {