wgengine/router: add debug logging component logsandrew/wgengine-router-debug

This uses the "component logging" feature to allow turning on additional
debug logs for the Router at runtime. Currently, it's only implemented
on Linux and with the CallbackRouter at this time.

Updates #13887

Signed-off-by: Andrew Dunham <andrew@du.nham.ca>
Change-Id: I251a7705765f950d118850f1e14f465729ba45c5

6 files changed, 61 insertions, 6 deletions

diff --git a/wgengine/router/callback.go b/wgengine/router/callback.go
index 1d9091277..a90b0dfd9 100644
--- a/wgengine/router/callback.go
+++ b/wgengine/router/callback.go
@@ -30,6 +30,10 @@ type CallbackRouter struct {
 	// ignored thereafter.
 	InitialMTU uint32
 
+	// SetDebugLoggingEnabledFunc optionally specifies a function to call
+	// when the SetDebugLoggingEnabled method is called.
+	SetDebugLoggingEnabledFunc func(enabled bool)
+
 	mu        sync.Mutex    // protects all the following
 	didSetMTU bool          // if we set the MTU already
 	rcfg      *Config       // last applied router config
@@ -63,6 +67,13 @@ func (r *CallbackRouter) UpdateMagicsockPort(_ uint16, _ string) error {
 	return nil
 }
 
+// SetDebugLoggingEnabled implements the Router interface.
+func (r *CallbackRouter) SetDebugLoggingEnabled(enabled bool) {
+	if r.SetDebugLoggingEnabledFunc != nil {
+		r.SetDebugLoggingEnabledFunc(enabled)
+	}
+}
+
 // SetDNS implements dns.OSConfigurator.
 func (r *CallbackRouter) SetDNS(dcfg dns.OSConfig) error {
 	r.mu.Lock()
diff --git a/wgengine/router/router.go b/wgengine/router/router.go
index 423008978..03a6f0475 100644
--- a/wgengine/router/router.go
+++ b/wgengine/router/router.go
@@ -36,6 +36,10 @@ type Router interface {
 	// network should be either "udp4" or "udp6".
 	UpdateMagicsockPort(port uint16, network string) error
 
+	// SetDebugLoggingEnabled enables or disables debug logging in the
+	// router implementation.
+	SetDebugLoggingEnabled(enabled bool)
+
 	// Close closes the router.
 	Close() error
 }
diff --git a/wgengine/router/router_fake.go b/wgengine/router/router_fake.go
index 549867eca..fec2064cf 100644
--- a/wgengine/router/router_fake.go
+++ b/wgengine/router/router_fake.go
@@ -32,6 +32,10 @@ func (r fakeRouter) UpdateMagicsockPort(_ uint16, _ string) error {
 	return nil
 }
 
+func (r fakeRouter) SetDebugLoggingEnabled(_ bool) {
+	r.logf("[v1] warning: fakeRouter.SetDebugLoggingEnabled: not implemented.")
+}
+
 func (r fakeRouter) Close() error {
 	r.logf("[v1] warning: fakeRouter.Close: not implemented.")
 	return nil
diff --git a/wgengine/router/router_linux.go b/wgengine/router/router_linux.go
index 2af73e26d..dd30cdf1d 100644
--- a/wgengine/router/router_linux.go
+++ b/wgengine/router/router_linux.go
@@ -41,6 +41,7 @@ const (
 type linuxRouter struct {
 	closed            atomic.Bool
 	logf              func(fmt string, args ...any)
+	debugLogging      atomic.Bool
 	tunname           string
 	netMon            *netmon.Monitor
 	health            *health.Tracker
@@ -228,6 +229,14 @@ func useAmbientCaps() bool {
 	return distro.DSMVersion() >= 7
 }
 
+// dlogf will log a message if debug logging is turned on, at [v1] level.
+func (r *linuxRouter) dlogf(format string, args ...any) {
+	if !r.debugLogging.Load() {
+		return
+	}
+	r.logf("[v1] debug: "+format, args...)
+}
+
 var forceIPCommand = envknob.RegisterBool("TS_DEBUG_USE_IP_COMMAND")
 
 // useIPCommand reports whether r should use the "ip" command (or its
@@ -387,19 +396,19 @@ func (r *linuxRouter) Set(cfg *Config) error {
 		errs = append(errs, err)
 	}
 
-	newLocalRoutes, err := cidrDiff("localRoute", r.localRoutes, cfg.LocalRoutes, r.addThrowRoute, r.delThrowRoute, r.logf)
+	newLocalRoutes, err := cidrDiff("localRoute", r.localRoutes, cfg.LocalRoutes, r.addThrowRoute, r.delThrowRoute, r.logf, r.dlogf)
 	if err != nil {
 		errs = append(errs, err)
 	}
 	r.localRoutes = newLocalRoutes
 
-	newRoutes, err := cidrDiff("route", r.routes, cfg.Routes, r.addRoute, r.delRoute, r.logf)
+	newRoutes, err := cidrDiff("route", r.routes, cfg.Routes, r.addRoute, r.delRoute, r.logf, r.dlogf)
 	if err != nil {
 		errs = append(errs, err)
 	}
 	r.routes = newRoutes
 
-	newAddrs, err := cidrDiff("addr", r.addrs, cfg.LocalAddrs, r.addAddress, r.delAddress, r.logf)
+	newAddrs, err := cidrDiff("addr", r.addrs, cfg.LocalAddrs, r.addAddress, r.delAddress, r.logf, r.dlogf)
 	if err != nil {
 		errs = append(errs, err)
 	}
@@ -545,11 +554,16 @@ func (r *linuxRouter) UpdateMagicsockPort(port uint16, network string) error {
 	return nil
 }
 
+func (r *linuxRouter) SetDebugLoggingEnabled(enabled bool) {
+	r.debugLogging.Store(enabled)
+}
+
 // setNetfilterMode switches the router to the given netfilter
 // mode. Netfilter state is created or deleted appropriately to
 // reflect the new mode, and r.snatSubnetRoutes is updated to reflect
 // the current state of subnet SNATing.
 func (r *linuxRouter) setNetfilterMode(mode preftype.NetfilterMode) error {
+	r.dlogf("setNetfilterMode(%s), from=%s", mode, r.netfilterMode)
 	if !platformCanNetfilter() {
 		mode = netfilterOff
 	}
@@ -988,6 +1002,7 @@ func (r *linuxRouter) routeTable() int {
 
 // upInterface brings up the tunnel interface.
 func (r *linuxRouter) upInterface() error {
+	r.dlogf("setting interface up")
 	if r.useIPCommand() {
 		return r.cmd.run("ip", "link", "set", "dev", r.tunname, "up")
 	}
@@ -999,6 +1014,7 @@ func (r *linuxRouter) upInterface() error {
 }
 
 func (r *linuxRouter) enableIPForwarding() {
+	r.dlogf("enabling IP forwarding")
 	sysctls := map[string]string{
 		"net.ipv4.ip_forward":          "1",
 		"net.ipv6.conf.all.forwarding": "1",
@@ -1022,6 +1038,7 @@ func writeSysctl(key, val string) error {
 
 // downInterface sets the tunnel interface administratively down.
 func (r *linuxRouter) downInterface() error {
+	r.dlogf("setting interface down")
 	if r.useIPCommand() {
 		return r.cmd.run("ip", "link", "set", "dev", r.tunname, "down")
 	}
@@ -1431,7 +1448,7 @@ func (r *linuxRouter) delStatefulRule() error {
 // old and new match. Returns a map reflecting the actual new state
 // (which may be somewhere in between old and new if some commands
 // failed), and any error encountered while reconfiguring.
-func cidrDiff(kind string, old map[netip.Prefix]bool, new []netip.Prefix, add, del func(netip.Prefix) error, logf logger.Logf) (map[netip.Prefix]bool, error) {
+func cidrDiff(kind string, old map[netip.Prefix]bool, new []netip.Prefix, add, del func(netip.Prefix) error, logf, dlogf logger.Logf) (map[netip.Prefix]bool, error) {
 	newMap := make(map[netip.Prefix]bool, len(new))
 	for _, cidr := range new {
 		newMap[cidr] = true
@@ -1449,11 +1466,15 @@ func cidrDiff(kind string, old map[netip.Prefix]bool, new []netip.Prefix, add, d
 	// end up in a state where we have no addresses on an interface as that
 	// results in other kernel entities (like routes) pointing to that interface
 	// to also be deleted.
-	var addFail []error
+	var (
+		addFail []error
+		added   []netip.Prefix
+	)
 	for cidr := range newMap {
 		if old[cidr] {
 			continue
 		}
+		added = append(added, cidr)
 		if err := add(cidr); err != nil {
 			logf("%s add failed: %v", kind, err)
 			addFail = append(addFail, err)
@@ -1461,6 +1482,7 @@ func cidrDiff(kind string, old map[netip.Prefix]bool, new []netip.Prefix, add, d
 			ret[cidr] = true
 		}
 	}
+	dlogf("%s add %v", kind, added)
 
 	if len(addFail) == 1 {
 		return ret, addFail[0]
@@ -1469,11 +1491,15 @@ func cidrDiff(kind string, old map[netip.Prefix]bool, new []netip.Prefix, add, d
 		return ret, fmt.Errorf("%d add %s failures; first was: %w", len(addFail), kind, addFail[0])
 	}
 
-	var delFail []error
+	var (
+		delFail []error
+		deleted []netip.Prefix
+	)
 	for cidr := range old {
 		if newMap[cidr] {
 			continue
 		}
+		deleted = append(deleted, cidr)
 		if err := del(cidr); err != nil {
 			logf("%s del failed: %v", kind, err)
 			delFail = append(delFail, err)
@@ -1481,6 +1507,7 @@ func cidrDiff(kind string, old map[netip.Prefix]bool, new []netip.Prefix, add, d
 			delete(ret, cidr)
 		}
 	}
+	dlogf("%s del %v", kind, deleted)
 	if len(delFail) == 1 {
 		return ret, delFail[0]
 	}
diff --git a/wgengine/router/router_openbsd.go b/wgengine/router/router_openbsd.go
index 6fdd47ac9..0a840591c 100644
--- a/wgengine/router/router_openbsd.go
+++ b/wgengine/router/router_openbsd.go
@@ -236,6 +236,11 @@ func (r *openbsdRouter) UpdateMagicsockPort(_ uint16, _ string) error {
 	return nil
 }
 
+// SetDebugLoggingEnabled implements the Router interface.
+func (r *openbsdRouter) SetDebugLoggingEnabled(_ bool) {
+	// TODO(andrew-d): implement; see https://github.com/tailscale/tailscale/issues/13887
+}
+
 func (r *openbsdRouter) Close() error {
 	cleanUp(r.logf, r.tunname)
 	return nil
diff --git a/wgengine/router/router_userspace_bsd.go b/wgengine/router/router_userspace_bsd.go
index 0b7e4f36a..fcaf04d5e 100644
--- a/wgengine/router/router_userspace_bsd.go
+++ b/wgengine/router/router_userspace_bsd.go
@@ -206,6 +206,10 @@ func (r *userspaceBSDRouter) UpdateMagicsockPort(_ uint16, _ string) error {
 	return nil
 }
 
+func (r *userspaceBSDRouter) SetDebugLoggingEnabled(_ bool) {
+	// TODO(andrew-d): implement; see https://github.com/tailscale/tailscale/issues/13887
+}
+
 func (r *userspaceBSDRouter) Close() error {
 	return nil
 }