From 43dd4d1626f84c50a3d814b45d97829ca5727e64 Mon Sep 17 00:00:00 2001 From: Andrew Dunham Date: Tue, 22 Oct 2024 15:25:12 -0500 Subject: [PATCH] wgengine/router: add debug logging component logs 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 Change-Id: I251a7705765f950d118850f1e14f465729ba45c5 --- ipn/ipnlocal/local.go | 8 +++++ wgengine/router/callback.go | 11 +++++++ wgengine/router/router.go | 4 +++ wgengine/router/router_fake.go | 4 +++ wgengine/router/router_linux.go | 39 +++++++++++++++++++++---- wgengine/router/router_openbsd.go | 5 ++++ wgengine/router/router_userspace_bsd.go | 4 +++ 7 files changed, 69 insertions(+), 6 deletions(-) diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index b01f3a0c0..3866e5b61 100644 --- a/ipn/ipnlocal/local.go +++ b/ipn/ipnlocal/local.go @@ -566,7 +566,9 @@ func componentStateKey(component string) ipn.StateKey { // The following components are recognized: // // - magicsock +// - router // - sockstats +// - syspolicy func (b *LocalBackend) SetComponentDebugLogging(component string, until time.Time) error { b.mu.Lock() defer b.mu.Unlock() @@ -575,6 +577,12 @@ func (b *LocalBackend) SetComponentDebugLogging(component string, until time.Tim switch component { case "magicsock": setEnabled = b.MagicConn().SetDebugLoggingEnabled + case "router": + if r, ok := b.sys.Router.GetOK(); ok { + setEnabled = r.SetDebugLoggingEnabled + } else { + return fmt.Errorf("no router available") + } case "sockstats": if b.sockstatLogger != nil { setEnabled = func(v bool) { 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 }