From 61d0435ed9831982181b216994e9f185d673fb68 Mon Sep 17 00:00:00 2001
From: Brad Fitzpatrick <bradfitz@tailscale.com>
Date: Thu, 18 Nov 2021 10:48:53 -0800
Subject: [PATCH] wgengine/monitor: reduce Windows log spam

Fixes #3345

Change-Id: Icde9c92f88f98bb3b030d39b0424a7d389bceb88
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
---
 wgengine/monitor/monitor_windows.go | 40 +++++++++++++++++++++++++----
 1 file changed, 35 insertions(+), 5 deletions(-)

diff --git a/wgengine/monitor/monitor_windows.go b/wgengine/monitor/monitor_windows.go
index e35d28d1a..027c0c557 100644
--- a/wgengine/monitor/monitor_windows.go
+++ b/wgengine/monitor/monitor_windows.go
@@ -7,9 +7,13 @@
 import (
 	"context"
 	"errors"
+	"strings"
+	"sync"
 	"time"
 
 	"golang.zx2c4.com/wireguard/windows/tunnel/winipcfg"
+	"inet.af/netaddr"
+	"tailscale.com/net/tsaddr"
 	"tailscale.com/types/logger"
 )
 
@@ -31,6 +35,9 @@ type winMon struct {
 	addressChangeCallback *winipcfg.UnicastAddressChangeCallback
 	routeChangeCallback   *winipcfg.RouteChangeCallback
 
+	mu      sync.Mutex
+	lastLog time.Time // time we last logged about any windows change event
+
 	// noDeadlockTicker exists just to have something scheduled as
 	// far as the Go runtime is concerned. Otherwise "tailscaled
 	// debug --monitor" thinks it's deadlocked with nothing to do,
@@ -100,7 +107,20 @@ func (m *winMon) Receive() (message, error) {
 
 	select {
 	case msg := <-m.messagec:
-		m.logf("got windows change event after %v: evt=%s", time.Since(t0).Round(time.Millisecond), msg.eventType)
+		now := time.Now()
+		m.mu.Lock()
+		sinceLast := now.Sub(m.lastLog)
+		m.lastLog = now
+		m.mu.Unlock()
+		// If it's either been awhile since we last logged
+		// anything, or if this some route/addr that's not
+		// about a Tailscale IP ("ts" prefix), then log. This
+		// is mainly limited to suppress the flood about our own
+		// route updates after connecting to a large tailnet
+		// and all the IPv4 /32 routes.
+		if sinceLast > 5*time.Second || !strings.HasPrefix(msg.eventType, "ts") {
+			m.logf("got windows change event after %v: evt=%s", time.Since(t0).Round(time.Millisecond), msg.eventType)
+		}
 		return msg, nil
 	case <-m.ctx.Done():
 		return nil, errClosed
@@ -108,15 +128,25 @@ func (m *winMon) Receive() (message, error) {
 }
 
 // unicastAddressChanged is the callback we register with Windows to call when unicast address changes.
-func (m *winMon) unicastAddressChanged(_ winipcfg.MibNotificationType, _ *winipcfg.MibUnicastIPAddressRow) {
+func (m *winMon) unicastAddressChanged(_ winipcfg.MibNotificationType, row *winipcfg.MibUnicastIPAddressRow) {
+	what := "addr"
+	if ip, ok := netaddr.FromStdIP(row.Address.IP()); ok && tsaddr.IsTailscaleIP(ip) {
+		what = "tsaddr"
+	}
+
 	// start a goroutine to finish our work, to return to Windows out of this callback
-	go m.somethingChanged("addr")
+	go m.somethingChanged(what)
 }
 
 // routeChanged is the callback we register with Windows to call when route changes.
-func (m *winMon) routeChanged(_ winipcfg.MibNotificationType, _ *winipcfg.MibIPforwardRow2) {
+func (m *winMon) routeChanged(_ winipcfg.MibNotificationType, row *winipcfg.MibIPforwardRow2) {
+	what := "route"
+	ipn := row.DestinationPrefix.IPNet()
+	if cidr, ok := netaddr.FromStdIPNet(&ipn); ok && tsaddr.IsTailscaleIP(cidr.IP()) {
+		what = "tsroute"
+	}
 	// start a goroutine to finish our work, to return to Windows out of this callback
-	go m.somethingChanged("route")
+	go m.somethingChanged(what)
 }
 
 // somethingChanged gets called from OS callbacks whenever address or route changes.