[v15] Convert TeleportProcess to use slog for logging (#39398)

* Convert TeleportProcess to use slog for logging (#38551)

Begins the conversion away from logrus to slog for all messages
emitted from TeleportProcess. The logrus logger should now only
be in use for dependency injection to child components that haven't
been converted yet. There are still instances of the logrus logger
in the process configuration to emit messages, they will be converted
in a follow up PR.

* Make slog attributes output the same content regardless of format (#39428)

* Make slog attributes output the same content regardless of format

There were a few instances of fmt.Stringers being passed to slog
as attributes to delay their evaluation as per the performance
considerations of slog: https://pkg.go.dev/log/slog#hdr-Performance_considerations.
However, this resulted in the json handler emitting different
content since they check to see if attributes are json.Marshalers
and not fmt.Stringers. To rectify the situation, a new slog.LogValuer
implementation was added that wraps a fmt.Stringer so that attributes
can be lazily constructed while producing the same output no matter
the log output format.

* fix: wrap identity and correct typo

* Fix integrations ssh service tests (#39543)

Similar to #39315,
this updates the integrations test suite to use a regular
expression that will match output to know when the ssh_service is
ready now that Teleport is using slog instead of logrus.

integrations/lib/testing/integration/authservice.go

@@ -36,7 +36,7 @@ import (
 	"github.com/gravitational/teleport/integrations/lib/logger"
 )
 
-var regexpAuthStarting = regexp.MustCompile(`Auth service [^ ]+ is starting on [^ ]+:(\d+)`)
+var regexpAuthStarting = regexp.MustCompile(`Auth service.*listen_address:[^ ]+:(\d+)`)
 
 type AuthService struct {
 	mu           sync.Mutex

integrations/lib/testing/integration/proxyservice.go

@@ -37,9 +37,9 @@ import (
 	"github.com/gravitational/teleport/integrations/lib/logger"
 )
 
-var regexpWebProxyStarting = regexp.MustCompile(`Web proxy service [^ ]+ is starting on [^ ]+:(\d+)`)
-var regexpSSHProxyStarting = regexp.MustCompile(`SSH proxy service [^ ]+ is starting on [^ ]+:(\d+)`)
-var regexpReverseTunnelStarting = regexp.MustCompile(`Reverse tunnel service [^ ]+ is starting on [^ ]+:(\d+)`)
+var regexpWebProxyStarting = regexp.MustCompile(`Starting web proxy service.*listen_address:[^ ]+:(\d+)`)
+var regexpSSHProxyStarting = regexp.MustCompile(`Starting SSH proxy service.*listen_address:[^ ]+:(\d+)`)
+var regexpReverseTunnelStarting = regexp.MustCompile(`Starting reverse tunnel server.*listen_address:[^ ]+:(\d+)`)
 
 type ProxyService struct {
 	mu                sync.Mutex

integrations/lib/testing/integration/sshservice.go

@@ -36,7 +36,7 @@ import (
 	"github.com/gravitational/teleport/integrations/lib/logger"
 )
 
-var regexpSSHStarting = regexp.MustCompile(`Service [^ ]+ is starting on [^ ]+:(\d+)`)
+var regexpSSHStarting = regexp.MustCompile(`SSH Service is starting.*listen_address:[^ ]+:(\d+)`)
 
 type SSHService struct {
 	mu           sync.Mutex

lib/service/awsoidc.go

@@ -94,7 +94,7 @@ func (process *TeleportProcess) initAWSOIDCDeployServiceUpdater() error {
 		return trace.Wrap(err)
 	}
 
-	process.log.Infof("The new service has started successfully. Checking for deploy service updates every %v.", updateAWSOIDCDeployServiceInterval)
+	process.logger.InfoContext(process.ExitContext(), "The new service has started successfully.", "update_interval", updateAWSOIDCDeployServiceInterval)
 	return trace.Wrap(updater.Run(process.GracefulExitContext()))
 }
 

lib/service/db.go

@@ -47,10 +47,9 @@ func (process *TeleportProcess) initDatabases() {
 }
 
 func (process *TeleportProcess) initDatabaseService() (retErr error) {
-	log := process.log.WithField(trace.Component, teleport.Component(
-		teleport.ComponentDatabase, process.id))
+	logger := process.logger.With(trace.Component, teleport.Component(teleport.ComponentDatabase, process.id))
 
-	conn, err := process.WaitForConnector(DatabasesIdentityEvent, log)
+	conn, err := process.WaitForConnector(DatabasesIdentityEvent, logger)
 	if conn == nil {
 		return trace.Wrap(err)
 	}
@@ -88,7 +87,7 @@ func (process *TeleportProcess) initDatabaseService() (retErr error) {
 	lockWatcher, err := services.NewLockWatcher(process.ExitContext(), services.LockWatcherConfig{
 		ResourceWatcherConfig: services.ResourceWatcherConfig{
 			Component: teleport.ComponentDatabase,
-			Log:       log,
+			Log:       process.log.WithField(trace.Component, teleport.Component(teleport.ComponentDatabase, process.id)),
 			Client:    conn.Client,
 		},
 	})
@@ -101,7 +100,7 @@ func (process *TeleportProcess) initDatabaseService() (retErr error) {
 		ClusterName: clusterName,
 		AccessPoint: accessPoint,
 		LockWatcher: lockWatcher,
-		Logger:      log,
+		Logger:      process.log.WithField(trace.Component, teleport.Component(teleport.ComponentDatabase, process.id)),
 	})
 	if err != nil {
 		return trace.Wrap(err)
@@ -117,7 +116,7 @@ func (process *TeleportProcess) initDatabaseService() (retErr error) {
 	}
 	defer func() {
 		if retErr != nil {
-			warnOnErr(asyncEmitter.Close(), process.log)
+			warnOnErr(process.ExitContext(), asyncEmitter.Close(), logger)
 		}
 	}()
 
@@ -171,7 +170,7 @@ func (process *TeleportProcess) initDatabaseService() (retErr error) {
 	}
 	defer func() {
 		if retErr != nil {
-			warnOnErr(dbService.Close(), process.log)
+			warnOnErr(process.ExitContext(), dbService.Close(), logger)
 		}
 	}()
 
@@ -206,25 +205,25 @@ func (process *TeleportProcess) initDatabaseService() (retErr error) {
 	process.OnExit("db.stop", func(payload interface{}) {
 		if dbService != nil {
 			if payload == nil {
-				log.Info("Shutting down immediately.")
-				warnOnErr(dbService.Close(), log)
+				logger.InfoContext(process.ExitContext(), "Shutting down immediately.")
+				warnOnErr(process.ExitContext(), dbService.Close(), logger)
 			} else {
-				log.Info("Shutting down gracefully.")
-				warnOnErr(dbService.Shutdown(payloadContext(payload, log)), log)
+				logger.InfoContext(process.ExitContext(), "Shutting down gracefully.")
+				warnOnErr(process.ExitContext(), dbService.Shutdown(payloadContext(payload)), logger)
 			}
 		}
 		if asyncEmitter != nil {
-			warnOnErr(asyncEmitter.Close(), log)
+			warnOnErr(process.ExitContext(), asyncEmitter.Close(), logger)
 		}
 		if agentPool != nil {
 			agentPool.Stop()
 		}
-		warnOnErr(conn.Close(), log)
-		log.Info("Exited.")
+		warnOnErr(process.ExitContext(), conn.Close(), logger)
+		logger.InfoContext(process.ExitContext(), "Exited.")
 	})
 
 	process.BroadcastEvent(Event{Name: DatabasesReady, Payload: nil})
-	log.Infof("Database service has successfully started: %v.", databases)
+	logger.InfoContext(process.ExitContext(), "Database service has successfully started.", "database", databases)
 
 	// Block and wait while the server and agent pool are running.
 	if err := dbService.Wait(); err != nil {

lib/service/desktop.go

@@ -20,12 +20,12 @@ package service
 
 import (
 	"crypto/tls"
+	"log/slog"
 	"net"
 	"net/http"
 	"strconv"
 
 	"github.com/gravitational/trace"
-	"github.com/sirupsen/logrus"
 
 	"github.com/gravitational/teleport"
 	"github.com/gravitational/teleport/api/types"
@@ -44,28 +44,26 @@ import (
 )
 
 func (process *TeleportProcess) initWindowsDesktopService() {
-	log := process.log.WithFields(logrus.Fields{
-		trace.Component: teleport.Component(teleport.ComponentWindowsDesktop, process.id),
-	})
+	logger := process.logger.With(trace.Component, teleport.Component(teleport.ComponentWindowsDesktop, process.id))
 	process.RegisterWithAuthServer(types.RoleWindowsDesktop, WindowsDesktopIdentityEvent)
 	process.RegisterCriticalFunc("windows_desktop.init", func() error {
-		conn, err := process.WaitForConnector(WindowsDesktopIdentityEvent, log)
+		conn, err := process.WaitForConnector(WindowsDesktopIdentityEvent, logger)
 		if conn == nil {
 			return trace.Wrap(err)
 		}
 
-		if err := process.initWindowsDesktopServiceRegistered(log, conn); err != nil {
-			warnOnErr(conn.Close(), log)
+		if err := process.initWindowsDesktopServiceRegistered(logger, conn); err != nil {
+			warnOnErr(process.ExitContext(), conn.Close(), logger)
 			return trace.Wrap(err)
 		}
 		return nil
 	})
 }
 
-func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.Entry, conn *Connector) (retErr error) {
+func (process *TeleportProcess) initWindowsDesktopServiceRegistered(logger *slog.Logger, conn *Connector) (retErr error) {
 	defer func() {
 		if err := process.closeImportedDescriptors(teleport.ComponentWindowsDesktop); err != nil {
-			log.WithError(err).Warn("Failed closing imported file descriptors.")
+			logger.WarnContext(process.ExitContext(), "Failed closing imported file descriptors.")
 		}
 	}()
 	cfg := process.Config
@@ -98,14 +96,14 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 
 	// Start a local listener and let proxies dial in.
 	case !useTunnel && !cfg.WindowsDesktop.ListenAddr.IsEmpty():
-		log.Info("Using local listener and registering directly with auth server")
+		logger.InfoContext(process.ExitContext(), "Using local listener and registering directly with auth server")
 		listener, err = process.importOrCreateListener(ListenerWindowsDesktop, cfg.WindowsDesktop.ListenAddr.Addr)
 		if err != nil {
 			return trace.Wrap(err)
 		}
 		defer func() {
 			if retErr != nil {
-				warnOnErr(listener.Close(), log)
+				warnOnErr(process.ExitContext(), listener.Close(), logger)
 			}
 		}()
 
@@ -139,13 +137,13 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 				agentPool.Stop()
 			}
 		}()
-		log.Info("Using a reverse tunnel to register and handle proxy connections")
+		logger.InfoContext(process.ExitContext(), "Using a reverse tunnel to register and handle proxy connections")
 	}
 
 	lockWatcher, err := services.NewLockWatcher(process.ExitContext(), services.LockWatcherConfig{
 		ResourceWatcherConfig: services.ResourceWatcherConfig{
 			Component: teleport.ComponentWindowsDesktop,
-			Log:       log,
+			Log:       process.log.WithField(trace.Component, teleport.Component(teleport.ComponentWindowsDesktop, process.id)),
 			Clock:     cfg.Clock,
 			Client:    conn.Client,
 		},
@@ -160,7 +158,7 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 		ClusterName: clusterName,
 		AccessPoint: accessPoint,
 		LockWatcher: lockWatcher,
-		Logger:      log,
+		Logger:      process.log.WithField(trace.Component, teleport.Component(teleport.ComponentWindowsDesktop, process.id)),
 		// Device authorization breaks browser-based access.
 		DeviceAuthorization: authz.DeviceAuthorizationOpts{
 			DisableGlobalMode: true,
@@ -183,7 +181,7 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 		if info.ServerName != "" {
 			clusterName, err = apiutils.DecodeClusterName(info.ServerName)
 			if err != nil && !trace.IsNotFound(err) {
-				log.Debugf("Ignoring unsupported cluster name %q.", info.ServerName)
+				logger.DebugContext(process.ExitContext(), "Ignoring unsupported cluster name.", "cluster_name", info.ServerName)
 			}
 		}
 		pool, _, err := auth.DefaultClientCertPool(accessPoint, clusterName)
@@ -213,7 +211,7 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 
 	srv, err := desktop.NewWindowsService(desktop.WindowsServiceConfig{
 		DataDir:      process.Config.DataDir,
-		Log:          log,
+		Log:          process.log.WithField(trace.Component, teleport.Component(teleport.ComponentWindowsDesktop, process.id)),
 		Clock:        process.Clock,
 		Authorizer:   authorizer,
 		Emitter:      conn.Client,
@@ -244,14 +242,14 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 	}
 	defer func() {
 		if retErr != nil {
-			warnOnErr(srv.Close(), log)
+			warnOnErr(process.ExitContext(), srv.Close(), logger)
 		}
 	}()
 	process.RegisterCriticalFunc("windows_desktop.serve", func() error {
 		if useTunnel {
-			log.Info("Starting Windows desktop service via proxy reverse tunnel.")
+			logger.InfoContext(process.ExitContext(), "Starting Windows desktop service via proxy reverse tunnel.")
 		} else {
-			log.Infof("Starting Windows desktop service on %v.", listener.Addr())
+			logger.InfoContext(process.ExitContext(), "Starting Windows desktop service.", "listen_address", listener.Addr())
 		}
 		process.BroadcastEvent(Event{Name: WindowsDesktopReady, Payload: nil})
 
@@ -286,16 +284,16 @@ func (process *TeleportProcess) initWindowsDesktopServiceRegistered(log *logrus.
 	// Cleanup, when process is exiting.
 	process.OnExit("windows_desktop.shutdown", func(payload interface{}) {
 		// Fast shutdown.
-		warnOnErr(srv.Close(), log)
+		warnOnErr(process.ExitContext(), srv.Close(), logger)
 		agentPool.Stop()
 		if payload != nil {
 			// Graceful shutdown.
 			agentPool.Wait()
 		}
-		warnOnErr(listener.Close(), log)
-		warnOnErr(conn.Close(), log)
+		warnOnErr(process.ExitContext(), listener.Close(), logger)
+		warnOnErr(process.ExitContext(), conn.Close(), logger)
 
-		log.Info("Exited.")
+		logger.InfoContext(process.ExitContext(), "Exited.")
 	})
 	return nil
 }

lib/service/discovery.go

@@ -20,11 +20,11 @@ package service
 
 import (
 	"context"
+	"log/slog"
 	"os"
 	"time"
 
 	"github.com/gravitational/trace"
-	"github.com/sirupsen/logrus"
 
 	"github.com/gravitational/teleport"
 	"github.com/gravitational/teleport/api/types"
@@ -44,10 +44,9 @@ func (process *TeleportProcess) initDiscovery() {
 }
 
 func (process *TeleportProcess) initDiscoveryService() error {
-	log := process.log.WithField(trace.Component, teleport.Component(
-		teleport.ComponentDiscovery, process.id))
+	logger := process.logger.With(trace.Component, teleport.Component(teleport.ComponentDiscovery, process.id))
 
-	conn, err := process.WaitForConnector(DiscoveryIdentityEvent, log)
+	conn, err := process.WaitForConnector(DiscoveryIdentityEvent, logger)
 	if conn == nil {
 		return trace.Wrap(err)
 	}
@@ -76,7 +75,7 @@ func (process *TeleportProcess) initDiscoveryService() error {
 		process.ExitContext(),
 		process.Config,
 		process.getInstanceClient(),
-		log,
+		logger,
 	)
 	if err != nil {
 		return trace.Wrap(err, "failed to build access graph configuration")
@@ -107,23 +106,23 @@ func (process *TeleportProcess) initDiscoveryService() error {
 	}
 
 	process.OnExit("discovery.stop", func(payload interface{}) {
-		log.Info("Shutting down.")
+		logger.InfoContext(process.ExitContext(), "Shutting down.")
 		if discoveryService != nil {
 			discoveryService.Stop()
 		}
 		if asyncEmitter != nil {
-			warnOnErr(asyncEmitter.Close(), process.log)
+			warnOnErr(process.ExitContext(), asyncEmitter.Close(), logger)
 		}
-		warnOnErr(conn.Close(), log)
-		log.Info("Exited.")
+		warnOnErr(process.ExitContext(), conn.Close(), logger)
+		logger.InfoContext(process.ExitContext(), "Exited.")
 	})
 
 	process.BroadcastEvent(Event{Name: DiscoveryReady, Payload: nil})
 
 	if err := discoveryService.Start(); err != nil {
 		return trace.Wrap(err)
 	}
-	log.Infof("Discovery service has successfully started")
+	logger.InfoContext(process.ExitContext(), "Discovery service has successfully started")
 
 	if err := discoveryService.Wait(); err != nil {
 		return trace.Wrap(err)
@@ -143,7 +142,7 @@ func (process *TeleportProcess) integrationOnlyCredentials() bool {
 
 // buildAccessGraphFromTAGOrFallbackToAuth builds the AccessGraphConfig from the Teleport Agent configuration or falls back to the Auth server's configuration.
 // If the AccessGraph configuration is not enabled locally, it will fall back to the Auth server's configuration.
-func buildAccessGraphFromTAGOrFallbackToAuth(ctx context.Context, config *servicecfg.Config, client auth.ClientI, logger logrus.FieldLogger) (discovery.AccessGraphConfig, error) {
+func buildAccessGraphFromTAGOrFallbackToAuth(ctx context.Context, config *servicecfg.Config, client auth.ClientI, logger *slog.Logger) (discovery.AccessGraphConfig, error) {
 	var (
 		accessGraphCAData []byte
 		err               error
@@ -164,13 +163,13 @@ func buildAccessGraphFromTAGOrFallbackToAuth(ctx context.Context, config *servic
 		CA:       accessGraphCAData,
 	}
 	if !accessGraphCfg.Enabled {
-		logger.Debug("Access graph is disabled or not configured. Falling back to the Auth server's access graph configuration.")
+		logger.DebugContext(ctx, "Access graph is disabled or not configured. Falling back to the Auth server's access graph configuration.")
 		ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
 		rsp, err := client.GetClusterAccessGraphConfig(ctx)
 		cancel()
 		switch {
 		case trace.IsNotImplemented(err):
-			logger.Debug("Auth server does not support access graph's GetClusterAccessGraphConfig RPC")
+			logger.DebugContext(ctx, "Auth server does not support access graph's GetClusterAccessGraphConfig RPC")
 		case err != nil:
 			return discovery.AccessGraphConfig{}, trace.Wrap(err)
 		default:

lib/service/discovery_test.go

@@ -20,10 +20,10 @@ package service
 
 import (
 	"context"
+	"log/slog"
 	"testing"
 
 	"github.com/gravitational/trace"
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 
 	clusterconfigpb "github.com/gravitational/teleport/api/gen/proto/go/teleport/clusterconfig/v1"
@@ -157,7 +157,7 @@ func TestTeleportProcess_initDiscoveryService(t *testing.T) {
 					rsp: tt.rsp,
 					err: tt.err,
 				},
-				logrus.StandardLogger(),
+				slog.Default(),
 			)
 			tt.assertErr(t, err)
 			require.Equal(t, tt.want, accessGraphCfg)