tsnet: split user facing and backend logging

This adds a new `UserLogf` field to the `Server` struct.
When set this any logs generated by Server are logged using
`UserLogf` and all spammy backend logs are logged to `Logf`.

If it `UserLogf` is unset, we default to `log.Printf` and
if `Logf` is unset we discard all the spammy logs.

Fixes #12094

Signed-off-by: Maisem Ali <[email protected]>

cmd/pgproxy/pgproxy.go

@@ -28,7 +28,6 @@ import (
 	"tailscale.com/metrics"
 	"tailscale.com/tsnet"
 	"tailscale.com/tsweb"
-	"tailscale.com/types/logger"
 )
 
 var (
@@ -58,8 +57,6 @@ func main() {
 	ts := &tsnet.Server{
 		Dir:      *tailscaleDir,
 		Hostname: *hostname,
-		// Make the stdout logs a clean audit log of connections.
-		Logf: logger.Discard,
 	}
 
 	if os.Getenv("TS_AUTHKEY") == "" {

cmd/sniproxy/sniproxy_test.go

@@ -8,6 +8,7 @@ import (
 	"encoding/json"
 	"flag"
 	"fmt"
+	"log"
 	"net"
 	"net/http/httptest"
 	"net/netip"
@@ -99,8 +100,8 @@ func startNode(t *testing.T, ctx context.Context, controlURL, hostname string) (
 		Store:      new(mem.Store),
 		Ephemeral:  true,
 	}
-	if !*verboseNodes {
-		s.Logf = logger.Discard
+	if *verboseNodes {
+		s.Logf = log.Printf
 	}
 	t.Cleanup(func() { s.Close() })
 

cmd/tsidp/tsidp.go

@@ -40,7 +40,6 @@ import (
 	"tailscale.com/tsnet"
 	"tailscale.com/types/key"
 	"tailscale.com/types/lazy"
-	"tailscale.com/types/logger"
 	"tailscale.com/types/views"
 	"tailscale.com/util/mak"
 	"tailscale.com/util/must"
@@ -95,8 +94,8 @@ func main() {
 		ts := &tsnet.Server{
 			Hostname: "idp",
 		}
-		if !*flagVerbose {
-			ts.Logf = logger.Discard
+		if *flagVerbose {
+			ts.Logf = log.Printf
 		}
 		st, err = ts.Up(ctx)
 		if err != nil {

tsnet/example/tsnet-funnel/tsnet-funnel.go

@@ -16,14 +16,12 @@ import (
 	"net/http"
 
 	"tailscale.com/tsnet"
-	"tailscale.com/types/logger"
 )
 
 func main() {
 	flag.Parse()
 	s := &tsnet.Server{
 		Dir:      "./funnel-demo-config",
-		Logf:     logger.Discard,
 		Hostname: "fun",
 	}
 	defer s.Close()

tsnet/example_tsnet_test.go

@@ -89,15 +89,6 @@ func ExampleServer_multipleInstances() {
 	}()
 }
 
-// ExampleServer_ignoreLogs shows you how to ignore all of the log messages written
-// by a tsnet instance.
-func ExampleServer_ignoreLogs() {
-	srv := &tsnet.Server{
-		Logf: func(string, ...any) {},
-	}
-	_ = srv
-}
-
 // ExampleServer_ignoreLogsSometimes shows you how to ignore all of the log messages
 // written by a tsnet instance, but allows you to opt-into them if a command-line
 // flag is set.
@@ -107,7 +98,6 @@ func ExampleServer_ignoreLogsSometimes() {
 
 	srv := &tsnet.Server{
 		Hostname: *hostname,
-		Logf:     func(string, ...any) {},
 	}
 
 	if *tsnetVerbose {

tsnet/tsnet.go

@@ -89,8 +89,14 @@ type Server struct {
 	// If empty, the binary name is used.
 	Hostname string
 
-	// Logf, if non-nil, specifies the logger to use. By default,
-	// log.Printf is used.
+	// UserLogf, if non-nil, specifies the logger to use for logs generated by
+	// the Server itself intended to be seen by the user such as the AuthURL for
+	// login and status updates. If unset, log.Printf is used.
+	UserLogf logger.Logf
+
+	// Logf, if set is used for logs generated by the backend such as the
+	// LocalBackend and MagicSock. It is verbose and intended for debugging.
+	// If unset, logs are discarded.
 	Logf logger.Logf
 
 	// Ephemeral, if true, specifies that the instance should register
@@ -244,15 +250,15 @@ func (s *Server) Loopback() (addr string, proxyCred, localAPICred string, err er
 				s.logf("localapi tcp serve error: %v", err)
 			}
 		}()
-
+		s5l := logger.WithPrefix(s.logf, "socks5: ")
 		s5s := &socks5.Server{
-			Logf:     logger.WithPrefix(s.logf, "socks5: "),
+			Logf:     s5l,
 			Dialer:   s.dialer.UserDial,
 			Username: "tsnet",
 			Password: s.proxyCred,
 		}
 		go func() {
-			s.logf("SOCKS5 server exited: %v", s5s.Serve(socksLn))
+			s5l("SOCKS5 server exited: %v", s5s.Serve(socksLn))
 		}()
 	}
 
@@ -484,14 +490,12 @@ func (s *Server) start() (reterr error) {
 		}
 	}
 
-	logf := s.logf
-
 	if s.rootPath == "" {
 		confDir, err := os.UserConfigDir()
 		if err != nil {
 			return err
 		}
-		s.rootPath, err = getTSNetDir(logf, confDir, prog)
+		s.rootPath, err = getTSNetDir(s.logf, confDir, prog)
 		if err != nil {
 			return err
 		}
@@ -505,19 +509,29 @@ func (s *Server) start() (reterr error) {
 		return fmt.Errorf("%v is not a directory", s.rootPath)
 	}
 
+	tsLogf := func(format string, a ...any) {
+		if s.logtail != nil {
+			s.logtail.Logf(format, a...)
+		}
+		if s.Logf == nil {
+			return
+		}
+		s.Logf(format, a...)
+	}
+
 	sys := new(tsd.System)
-	if err := s.startLogger(&closePool, sys.HealthTracker()); err != nil {
+	if err := s.startLogger(&closePool, sys.HealthTracker(), tsLogf); err != nil {
 		return err
 	}
 
-	s.netMon, err = netmon.New(logf)
+	s.netMon, err = netmon.New(tsLogf)
 	if err != nil {
 		return err
 	}
 	closePool.add(s.netMon)
 
-	s.dialer = &tsdial.Dialer{Logf: logf} // mutated below (before used)
-	eng, err := wgengine.NewUserspaceEngine(logf, wgengine.Config{
+	s.dialer = &tsdial.Dialer{Logf: tsLogf} // mutated below (before used)
+	eng, err := wgengine.NewUserspaceEngine(tsLogf, wgengine.Config{
 		ListenPort:    s.Port,
 		NetMon:        s.netMon,
 		Dialer:        s.dialer,
@@ -532,7 +546,7 @@ func (s *Server) start() (reterr error) {
 	sys.Set(eng)
 
 	// TODO(oxtoacart): do we need to support Taildrive on tsnet, and if so, how?
-	ns, err := netstack.Create(logf, sys.Tun.Get(), eng, sys.MagicSock.Get(), s.dialer, sys.DNSManager.Get(), sys.ProxyMapper(), nil)
+	ns, err := netstack.Create(tsLogf, sys.Tun.Get(), eng, sys.MagicSock.Get(), s.dialer, sys.DNSManager.Get(), sys.ProxyMapper(), nil)
 	if err != nil {
 		return fmt.Errorf("netstack.Create: %w", err)
 	}
@@ -559,8 +573,8 @@ func (s *Server) start() (reterr error) {
 
 	if s.Store == nil {
 		stateFile := filepath.Join(s.rootPath, "tailscaled.state")
-		logf("tsnet running state path %s", stateFile)
-		s.Store, err = store.New(logf, stateFile)
+		s.logf("tsnet running state path %s", stateFile)
+		s.Store, err = store.New(tsLogf, stateFile)
 		if err != nil {
 			return err
 		}
@@ -571,13 +585,13 @@ func (s *Server) start() (reterr error) {
 	if s.Ephemeral {
 		loginFlags = controlclient.LoginEphemeral
 	}
-	lb, err := ipnlocal.NewLocalBackend(logf, s.logid, sys, loginFlags|controlclient.LocalBackendStartKeyOSNeutral)
+	lb, err := ipnlocal.NewLocalBackend(tsLogf, s.logid, sys, loginFlags|controlclient.LocalBackendStartKeyOSNeutral)
 	if err != nil {
 		return fmt.Errorf("NewLocalBackend: %v", err)
 	}
 	lb.SetTCPHandlerForFunnelFlow(s.getTCPHandlerForFunnelFlow)
 	lb.SetVarRoot(s.rootPath)
-	logf("tsnet starting with hostname %q, varRoot %q", s.hostname, s.rootPath)
+	s.logf("tsnet starting with hostname %q, varRoot %q", s.hostname, s.rootPath)
 	s.lb = lb
 	if err := ns.Start(lb); err != nil {
 		return fmt.Errorf("failed to start netstack: %w", err)
@@ -598,17 +612,17 @@ func (s *Server) start() (reterr error) {
 	}
 	st := lb.State()
 	if st == ipn.NeedsLogin || envknob.Bool("TSNET_FORCE_LOGIN") {
-		logf("LocalBackend state is %v; running StartLoginInteractive...", st)
+		s.logf("LocalBackend state is %v; running StartLoginInteractive...", st)
 		if err := s.lb.StartLoginInteractive(s.shutdownCtx); err != nil {
 			return fmt.Errorf("StartLoginInteractive: %w", err)
 		}
 	} else if authKey != "" {
-		logf("Authkey is set; but state is %v. Ignoring authkey. Re-run with TSNET_FORCE_LOGIN=1 to force use of authkey.", st)
+		s.logf("Authkey is set; but state is %v. Ignoring authkey. Re-run with TSNET_FORCE_LOGIN=1 to force use of authkey.", st)
 	}
 	go s.printAuthURLLoop()
 
 	// Run the localapi handler, to allow fetching LetsEncrypt certs.
-	lah := localapi.NewHandler(lb, logf, s.logid)
+	lah := localapi.NewHandler(lb, tsLogf, s.logid)
 	lah.PermitWrite = true
 	lah.PermitRead = true
 
@@ -621,14 +635,14 @@ func (s *Server) start() (reterr error) {
 	s.lb.ConfigureWebClient(s.localClient)
 	go func() {
 		if err := s.localAPIServer.Serve(lal); err != nil {
-			logf("localapi serve error: %v", err)
+			s.logf("localapi serve error: %v", err)
 		}
 	}()
 	closePool.add(s.localAPIListener)
 	return nil
 }
 
-func (s *Server) startLogger(closePool *closeOnErrorPool, health *health.Tracker) error {
+func (s *Server) startLogger(closePool *closeOnErrorPool, health *health.Tracker, tsLogf logger.Logf) error {
 	if testenv.InTest() {
 		return nil
 	}
@@ -659,10 +673,10 @@ func (s *Server) startLogger(closePool *closeOnErrorPool, health *health.Tracker
 		Stderr:       io.Discard, // log everything to Buffer
 		Buffer:       s.logbuffer,
 		CompressLogs: true,
-		HTTPC:        &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost, s.netMon, health, s.logf)},
+		HTTPC:        &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost, s.netMon, health, tsLogf)},
 		MetricsDelta: clientmetric.EncodeLogTailMetricsDelta,
 	}
-	s.logtail = logtail.NewLogger(c, s.logf)
+	s.logtail = logtail.NewLogger(c, tsLogf)
 	closePool.addFunc(func() { s.logtail.Shutdown(context.Background()) })
 	return nil
 }
@@ -683,8 +697,8 @@ func (s *Server) logf(format string, a ...any) {
 	if s.logtail != nil {
 		s.logtail.Logf(format, a...)
 	}
-	if s.Logf != nil {
-		s.Logf(format, a...)
+	if s.UserLogf != nil {
+		s.UserLogf(format, a...)
 		return
 	}
 	log.Printf(format, a...)
@@ -697,8 +711,8 @@ func (s *Server) printAuthURLLoop() {
 		if s.shutdownCtx.Err() != nil {
 			return
 		}
-		if st := s.lb.State(); st != ipn.NeedsLogin {
-			s.logf("printAuthURLLoop: state is %v; stopping", st)
+		if st := s.lb.State(); st != ipn.NeedsLogin && st != ipn.NoState {
+			s.logf("AuthLoop: state is %v; done", st)
 			return
 		}
 		st := s.lb.StatusWithoutPeers()

tsnet/tsnet_test.go

@@ -16,6 +16,7 @@ import (
 	"flag"
 	"fmt"
 	"io"
+	"log"
 	"math/big"
 	"net"
 	"net/http"
@@ -214,8 +215,8 @@ func startServer(t *testing.T, ctx context.Context, controlURL, hostname string)
 		Ephemeral:         true,
 		getCertForTesting: testCertRoot.getCert,
 	}
-	if !*verboseNodes {
-		s.Logf = logger.Discard
+	if *verboseNodes {
+		s.Logf = log.Printf
 	}
 	t.Cleanup(func() { s.Close() })