From da40609abd128b522684adcf06923d2faaad6fac Mon Sep 17 00:00:00 2001 From: Nick Khyl Date: Tue, 8 Oct 2024 13:59:50 -0500 Subject: [PATCH] util/syspolicy, ipn: add "tailscale debug component-logs" support Fixes #13313 Fixes #12687 Signed-off-by: Nick Khyl --- cmd/derper/depaware.txt | 3 +- cmd/k8s-operator/depaware.txt | 3 +- cmd/tailscale/depaware.txt | 3 +- cmd/tailscaled/depaware.txt | 3 +- ipn/backend.go | 1 + ipn/ipnlocal/local.go | 2 + util/syspolicy/internal/loggerx/logger.go | 42 ++++++++++----- .../syspolicy/internal/loggerx/logger_test.go | 53 +++++++++++++++++++ util/syspolicy/syspolicy.go | 6 +++ 9 files changed, 100 insertions(+), 16 deletions(-) create mode 100644 util/syspolicy/internal/loggerx/logger_test.go diff --git a/cmd/derper/depaware.txt b/cmd/derper/depaware.txt index eb9ba1619..417dbcfb0 100644 --- a/cmd/derper/depaware.txt +++ b/cmd/derper/depaware.txt @@ -162,7 +162,8 @@ tailscale.com/cmd/derper dependencies: (generated by github.com/tailscale/depawa tailscale.com/util/singleflight from tailscale.com/net/dnscache tailscale.com/util/slicesx from tailscale.com/cmd/derper+ tailscale.com/util/syspolicy from tailscale.com/ipn - tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting + tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting+ + tailscale.com/util/syspolicy/internal/loggerx from tailscale.com/util/syspolicy tailscale.com/util/syspolicy/setting from tailscale.com/util/syspolicy tailscale.com/util/usermetric from tailscale.com/health tailscale.com/util/vizerror from tailscale.com/tailcfg+ diff --git a/cmd/k8s-operator/depaware.txt b/cmd/k8s-operator/depaware.txt index 649296b59..c9f035372 100644 --- a/cmd/k8s-operator/depaware.txt +++ b/cmd/k8s-operator/depaware.txt @@ -809,7 +809,8 @@ tailscale.com/cmd/k8s-operator dependencies: (generated by github.com/tailscale/ tailscale.com/util/singleflight from tailscale.com/control/controlclient+ tailscale.com/util/slicesx from tailscale.com/appc+ tailscale.com/util/syspolicy from tailscale.com/control/controlclient+ - tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting + tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting+ + tailscale.com/util/syspolicy/internal/loggerx from tailscale.com/util/syspolicy tailscale.com/util/syspolicy/setting from tailscale.com/util/syspolicy tailscale.com/util/sysresources from tailscale.com/wgengine/magicsock tailscale.com/util/systemd from tailscale.com/control/controlclient+ diff --git a/cmd/tailscale/depaware.txt b/cmd/tailscale/depaware.txt index be6f42946..7b9d80af8 100644 --- a/cmd/tailscale/depaware.txt +++ b/cmd/tailscale/depaware.txt @@ -171,7 +171,8 @@ tailscale.com/cmd/tailscale dependencies: (generated by github.com/tailscale/dep tailscale.com/util/singleflight from tailscale.com/net/dnscache+ tailscale.com/util/slicesx from tailscale.com/net/dns/recursive+ tailscale.com/util/syspolicy from tailscale.com/ipn - tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting + tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting+ + tailscale.com/util/syspolicy/internal/loggerx from tailscale.com/util/syspolicy tailscale.com/util/syspolicy/setting from tailscale.com/util/syspolicy tailscale.com/util/testenv from tailscale.com/cmd/tailscale/cli tailscale.com/util/truncate from tailscale.com/cmd/tailscale/cli diff --git a/cmd/tailscaled/depaware.txt b/cmd/tailscaled/depaware.txt index 018e74fac..0d8e51eda 100644 --- a/cmd/tailscaled/depaware.txt +++ b/cmd/tailscaled/depaware.txt @@ -398,7 +398,8 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de tailscale.com/util/singleflight from tailscale.com/control/controlclient+ tailscale.com/util/slicesx from tailscale.com/net/dns/recursive+ tailscale.com/util/syspolicy from tailscale.com/cmd/tailscaled+ - tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting + tailscale.com/util/syspolicy/internal from tailscale.com/util/syspolicy/setting+ + tailscale.com/util/syspolicy/internal/loggerx from tailscale.com/util/syspolicy tailscale.com/util/syspolicy/setting from tailscale.com/util/syspolicy tailscale.com/util/sysresources from tailscale.com/wgengine/magicsock tailscale.com/util/systemd from tailscale.com/control/controlclient+ diff --git a/ipn/backend.go b/ipn/backend.go index d6ba95408..76ad1910b 100644 --- a/ipn/backend.go +++ b/ipn/backend.go @@ -238,6 +238,7 @@ type StateKey string var DebuggableComponents = []string{ "magicsock", "sockstats", + "syspolicy", } type Options struct { diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index 8fc78a36b..06dd84831 100644 --- a/ipn/ipnlocal/local.go +++ b/ipn/ipnlocal/local.go @@ -583,6 +583,8 @@ func (b *LocalBackend) SetComponentDebugLogging(component string, until time.Tim } } } + case "syspolicy": + setEnabled = syspolicy.SetDebugLoggingEnabled } if setEnabled == nil || !slices.Contains(ipn.DebuggableComponents, component) { return fmt.Errorf("unknown component %q", component) diff --git a/util/syspolicy/internal/loggerx/logger.go b/util/syspolicy/internal/loggerx/logger.go index b28610826..c29a5f084 100644 --- a/util/syspolicy/internal/loggerx/logger.go +++ b/util/syspolicy/internal/loggerx/logger.go @@ -6,6 +6,7 @@ package loggerx import ( "log" + "sync/atomic" "tailscale.com/types/lazy" "tailscale.com/types/logger" @@ -13,34 +14,51 @@ import ( ) const ( - errorPrefix = "syspolicy: " + normalPrefix = "syspolicy: " verbosePrefix = "syspolicy: [v2] " ) var ( - lazyErrorf lazy.SyncValue[logger.Logf] + debugLogging atomic.Bool // whether debugging logging is enabled + + lazyPrintf lazy.SyncValue[logger.Logf] lazyVerbosef lazy.SyncValue[logger.Logf] ) +// SetDebugLoggingEnabled controls whether spammy debug logging is enabled. +func SetDebugLoggingEnabled(v bool) { + debugLogging.Store(v) +} + // Errorf formats and writes an error message to the log. func Errorf(format string, args ...any) { - errorf := lazyErrorf.Get(func() logger.Logf { - return logger.WithPrefix(log.Printf, errorPrefix) - }) - errorf(format, args...) + printf(format, args...) } // Verbosef formats and writes an optional, verbose message to the log. func Verbosef(format string, args ...any) { - verbosef := lazyVerbosef.Get(func() logger.Logf { + if debugLogging.Load() { + printf(format, args...) + } else { + verbosef(format, args...) + } +} + +func printf(format string, args ...any) { + lazyPrintf.Get(func() logger.Logf { + return logger.WithPrefix(log.Printf, normalPrefix) + })(format, args...) +} + +func verbosef(format string, args ...any) { + lazyVerbosef.Get(func() logger.Logf { return logger.WithPrefix(log.Printf, verbosePrefix) - }) - verbosef(format, args...) + })(format, args...) } -// SetForTest sets the specified errorf and verbosef functions for the duration +// SetForTest sets the specified printf and verbosef functions for the duration // of tb and its subtests. -func SetForTest(tb internal.TB, errorf, verbosef logger.Logf) { - lazyErrorf.SetForTest(tb, errorf, nil) +func SetForTest(tb internal.TB, printf, verbosef logger.Logf) { + lazyPrintf.SetForTest(tb, printf, nil) lazyVerbosef.SetForTest(tb, verbosef, nil) } diff --git a/util/syspolicy/internal/loggerx/logger_test.go b/util/syspolicy/internal/loggerx/logger_test.go new file mode 100644 index 000000000..9735b5d30 --- /dev/null +++ b/util/syspolicy/internal/loggerx/logger_test.go @@ -0,0 +1,53 @@ +// Copyright (c) Tailscale Inc & AUTHORS +// SPDX-License-Identifier: BSD-3-Clause + +package loggerx + +import ( + "fmt" + "io" + "strings" + "testing" + + "tailscale.com/types/logger" +) + +func TestDebugLogging(t *testing.T) { + var normal, verbose strings.Builder + SetForTest(t, logfTo(&normal), logfTo(&verbose)) + + checkOutput := func(wantNormal, wantVerbose string) { + t.Helper() + if gotNormal := normal.String(); gotNormal != wantNormal { + t.Errorf("Unexpected normal output: got %q; want %q", gotNormal, wantNormal) + } + if gotVerbose := verbose.String(); gotVerbose != wantVerbose { + t.Errorf("Unexpected verbose output: got %q; want %q", gotVerbose, wantVerbose) + } + normal.Reset() + verbose.Reset() + } + + Errorf("This is an error message: %v", 42) + checkOutput("This is an error message: 42", "") + Verbosef("This is a verbose message: %v", 17) + checkOutput("", "This is a verbose message: 17") + + SetDebugLoggingEnabled(true) + Errorf("This is an error message: %v", 42) + checkOutput("This is an error message: 42", "") + Verbosef("This is a verbose message: %v", 17) + checkOutput("This is a verbose message: 17", "") + + SetDebugLoggingEnabled(false) + Errorf("This is an error message: %v", 42) + checkOutput("This is an error message: 42", "") + Verbosef("This is a verbose message: %v", 17) + checkOutput("", "This is a verbose message: 17") +} + +func logfTo(w io.Writer) logger.Logf { + return func(format string, args ...any) { + fmt.Fprintf(w, format, args...) + } +} diff --git a/util/syspolicy/syspolicy.go b/util/syspolicy/syspolicy.go index ccfd83347..abe42ed90 100644 --- a/util/syspolicy/syspolicy.go +++ b/util/syspolicy/syspolicy.go @@ -8,6 +8,7 @@ import ( "errors" "time" + "tailscale.com/util/syspolicy/internal/loggerx" "tailscale.com/util/syspolicy/setting" ) @@ -135,3 +136,8 @@ func SelectControlURL(reg, disk string) string { } return def } + +// SetDebugLoggingEnabled controls whether spammy debug logging is enabled. +func SetDebugLoggingEnabled(v bool) { + loggerx.SetDebugLoggingEnabled(v) +}