From 5de103ee21ab890649197fae232a8b20c052d03a Mon Sep 17 00:00:00 2001 From: Maisem Ali Date: Fri, 10 May 2024 13:12:11 -0700 Subject: [PATCH] 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 --- cmd/pgproxy/pgproxy.go | 3 - cmd/sniproxy/sniproxy_test.go | 5 +- cmd/tsidp/tsidp.go | 5 +- tsnet/example/tsnet-funnel/tsnet-funnel.go | 2 - tsnet/example_tsnet_test.go | 10 ---- tsnet/tsnet.go | 70 +++++++++++++--------- tsnet/tsnet_test.go | 5 +- 7 files changed, 50 insertions(+), 50 deletions(-) diff --git a/cmd/pgproxy/pgproxy.go b/cmd/pgproxy/pgproxy.go index a56613316..468649ee2 100644 --- a/cmd/pgproxy/pgproxy.go +++ b/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") == "" { diff --git a/cmd/sniproxy/sniproxy_test.go b/cmd/sniproxy/sniproxy_test.go index 9fa11b7ab..cd2e070bd 100644 --- a/cmd/sniproxy/sniproxy_test.go +++ b/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() }) diff --git a/cmd/tsidp/tsidp.go b/cmd/tsidp/tsidp.go index 3599ab141..43a3ae94b 100644 --- a/cmd/tsidp/tsidp.go +++ b/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 { diff --git a/tsnet/example/tsnet-funnel/tsnet-funnel.go b/tsnet/example/tsnet-funnel/tsnet-funnel.go index 3fc06c29e..1dac57a1e 100644 --- a/tsnet/example/tsnet-funnel/tsnet-funnel.go +++ b/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() diff --git a/tsnet/example_tsnet_test.go b/tsnet/example_tsnet_test.go index dd39d8aa5..c5a20ab77 100644 --- a/tsnet/example_tsnet_test.go +++ b/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 { diff --git a/tsnet/tsnet.go b/tsnet/tsnet.go index c665282ff..aca313a13 100644 --- a/tsnet/tsnet.go +++ b/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() diff --git a/tsnet/tsnet_test.go b/tsnet/tsnet_test.go index 85c3fa44f..e6408b06b 100644 --- a/tsnet/tsnet_test.go +++ b/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() })