util/syspolicy, ipn: add "tailscale debug component-logs" support

Fixes #13313
Fixes #12687

Signed-off-by: Nick Khyl <nickk@tailscale.com>

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+

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+

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

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+

ipn/backend.go

@@ -238,6 +238,7 @@ type StateKey string
 var DebuggableComponents = []string{
 	"magicsock",
 	"sockstats",
+	"syspolicy",
 }
 
 type Options struct {

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)

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 {
+	printf(format, args...)
-		return logger.WithPrefix(log.Printf, errorPrefix)
-	})
-	errorf(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() {
-		return logger.WithPrefix(log.Printf, verbosePrefix)
+		printf(format, args...)
-	})
+	} else {
-	verbosef(format, args...)
+		verbosef(format, args...)
+	}
 }
 
-// SetForTest sets the specified errorf and verbosef functions for the duration
+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)
+	})(format, args...)
+}
+
+// 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) {
+func SetForTest(tb internal.TB, printf, verbosef logger.Logf) {
-	lazyErrorf.SetForTest(tb, errorf, nil)
+	lazyPrintf.SetForTest(tb, printf, nil)
 	lazyVerbosef.SetForTest(tb, verbosef, nil)
 }

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...)
+	}
+}

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)
+}