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 <wendi.yu@yahoo.ca>

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 {

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=

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)

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{

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 {

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

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) {