Merge branch 'ef-migrate-shell-check-and-principals-to-slog' into 'main'

migrate all bar gitlab-shell to new slog labkit setup

See merge request https://gitlab.com/gitlab-org/gitlab-shell/-/merge_requests/1380

Merged-by: Igor Drozdov <idrozdov@gitlab.com>
Approved-by: Vasilii Iakliushin <viakliushin@gitlab.com>
Approved-by: Igor Drozdov <idrozdov@gitlab.com>
Reviewed-by: Vasilii Iakliushin <viakliushin@gitlab.com>
Co-authored-by: e_forbes <eforbes@gitlab.com>

Author: 2 people

cmd/gitlab-shell-authorized-keys-check/main.go

@@ -54,8 +54,10 @@ func execute(readWriter *readwriter.ReadWriter) (int, error) {
 		return exitCodeFailure, fmt.Errorf("failed to read config, exiting")
 	}
 
-	logCloser := logger.Configure(config)
-	defer func() { _ = logCloser.Close() }()
+	logCloser := logger.ConfigureLogger(config)
+	if logCloser != nil {
+		defer logCloser.Close() //nolint:errcheck
+	}
 
 	cmd, err := cmd.New(os.Args[1:], config, readWriter)
 	if err != nil {

cmd/gitlab-shell-authorized-principals-check/main.go

@@ -46,8 +46,10 @@ func run() int {
 		return 1
 	}
 
-	logCloser := logger.Configure(config)
-	defer logCloser.Close() //nolint:errcheck
+	logCloser := logger.ConfigureLogger(config)
+	if logCloser != nil {
+		defer logCloser.Close() //nolint:errcheck
+	}
 
 	cmd, err := cmd.New(os.Args[1:], config, readWriter)
 	if err != nil {

cmd/gitlab-shell-check/main.go

@@ -51,8 +51,10 @@ func run() int {
 		return code
 	}
 
-	logCloser := logger.Configure(config)
-	defer logCloser.Close() //nolint:errcheck
+	logCloser := logger.ConfigureLogger(config)
+	if logCloser != nil {
+		defer logCloser.Close() //nolint:errcheck
+	}
 
 	cmd, err := checkCmd.New(config, readWriter)
 	if code := exitOnError(err, "Failed to create command"); code != 0 {

cmd/gitlab-sshd/main.go

@@ -59,26 +59,19 @@ func main() {
 			))
 		}
 	}
-	log, logCloser, err := logger.ConfigureLogger(cfg)
-	if err != nil {
-		log.ErrorContext(ctx, "failed to log to file, reverting to stderr", slog.String(fields.ErrorMessage, err.Error()))
-	} else {
-		// nolint
-		defer func() {
-			if err = logCloser.Close(); err != nil {
-				log.ErrorContext(ctx, "failed to close log file", slog.String(fields.ErrorMessage, err.Error()))
-			}
-		}()
+	logCloser := logger.ConfigureLogger(cfg)
+	if logCloser != nil {
+		defer logCloser.Close() //nolint:errcheck
 	}
-	log.InfoContext(ctx, "gitlab-sshd starting up...")
+	slog.InfoContext(ctx, "gitlab-sshd starting up...")
 
 	overrideConfigFromEnvironment(cfg)
 	if err := isConfigSane(cfg); err != nil {
 		ctx = v2log.WithFields(ctx, slog.String(fields.ErrorMessage, err.Error()))
 		if *configDir == "" {
-			log.ErrorContext(ctx, "no config-dir provided, using only environment variables")
+			slog.ErrorContext(ctx, "no config-dir provided, using only environment variables")
 		} else {
-			log.ErrorContext(ctx, "configuration error")
+			slog.ErrorContext(ctx, "configuration error")
 		}
 	}
 
@@ -90,14 +83,14 @@ func main() {
 
 	server, err := sshd.NewServer(cfg)
 	if err != nil {
-		log.ErrorContext(ctx, "Failed to start Gitlab built-in sshd", slog.String(
+		slog.ErrorContext(ctx, "Failed to start Gitlab built-in sshd", slog.String(
 			fields.ErrorMessage, err.Error(),
 		))
 	}
 
 	// Startup monitoring endpoint.
 	if cfg.Server.WebListen != "" {
-		startupMonitoringEndpoint(ctx, cfg, server, log)
+		startupMonitoringEndpoint(ctx, cfg, server)
 	}
 
 	ctx, cancel := context.WithCancel(ctx)
@@ -106,10 +99,10 @@ func main() {
 	done := make(chan os.Signal, 1)
 	signal.Notify(done, syscall.SIGINT, syscall.SIGTERM)
 
-	gracefulShutdown(ctx, done, cfg, server, cancel, log)
+	gracefulShutdown(ctx, done, cfg, server, cancel)
 
 	if err := server.ListenAndServe(ctx); err != nil {
-		log.ErrorContext(ctx, "GitLab built-in sshd failed to listen for new connections",
+		slog.ErrorContext(ctx, "GitLab built-in sshd failed to listen for new connections",
 			slog.String(fields.ErrorMessage, err.Error()))
 	}
 }
@@ -120,18 +113,17 @@ func gracefulShutdown(
 	cfg *config.Config,
 	server *sshd.Server,
 	cancel context.CancelFunc,
-	log *slog.Logger,
 ) {
 	go func() {
 		sig := <-done
 		signal.Reset(syscall.SIGINT, syscall.SIGTERM)
 
 		gracePeriod := time.Duration(cfg.Server.GracePeriod)
-		log.InfoContext(ctx, fmt.Sprintf("Shutdown initiated with grace period: %f", gracePeriod.Seconds()),
+		slog.InfoContext(ctx, fmt.Sprintf("Shutdown initiated with grace period: %f", gracePeriod.Seconds()),
 			slog.String("signal", sig.String()))
 
 		if err := server.Shutdown(); err != nil {
-			log.ErrorContext(ctx, "Error shutting down the server", slog.String(
+			slog.ErrorContext(ctx, "Error shutting down the server", slog.String(
 				fields.ErrorMessage, err.Error()))
 		}
 		<-time.After(gracePeriod)
@@ -140,15 +132,15 @@ func gracefulShutdown(
 	}()
 }
 
-func startupMonitoringEndpoint(ctx context.Context, cfg *config.Config, server *sshd.Server, log *slog.Logger) {
+func startupMonitoringEndpoint(ctx context.Context, cfg *config.Config, server *sshd.Server) {
 	go func() {
 		err := monitoring.Start(
 			monitoring.WithListenerAddress(cfg.Server.WebListen),
 			monitoring.WithBuildInformation(Version, BuildTime),
 			monitoring.WithServeMux(server.MonitoringServeMux()),
 		)
 
-		log.ErrorContext(ctx, "monitoring service raised an error", slog.String(
+		slog.ErrorContext(ctx, "monitoring service raised an error", slog.String(
 			fields.ErrorMessage, err.Error(),
 		))
 		panic(err)

internal/command/command.go

@@ -6,13 +6,16 @@ package command
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"os"
 	"path"
 	"strings"
 
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
 	"gitlab.com/gitlab-org/labkit/correlation"
+	"gitlab.com/gitlab-org/labkit/fields"
 	"gitlab.com/gitlab-org/labkit/tracing"
+	"gitlab.com/gitlab-org/labkit/v2/log"
 )
 
 // Command is the interface that all gitlab-shell commands must implement.
@@ -82,6 +85,7 @@ func Setup(serviceName string, config *config.Config) (context.Context, func())
 	if correlationID == "" {
 		correlationID := correlation.SafeRandomID()
 		ctx = correlation.ContextWithCorrelation(ctx, correlationID)
+		ctx = log.WithFields(ctx, slog.String(fields.CorrelationID, correlationID))
 	}
 
 	return ctx, func() {

internal/logger/logger.go

@@ -18,14 +18,21 @@ import (
 // ConfigureLogger - gitlab-sshd's log output can be configured to text as per the documentation:
 // https://docs.gitlab.com/omnibus/settings/logs/#json-logging
 // This is currently controlled by the GITLAB_LOG_FORMAT environment variable.
-func ConfigureLogger(cfg *config.Config) (*slog.Logger, io.Closer, error) {
+func ConfigureLogger(cfg *config.Config) io.Closer {
 	logConfig := &v2log.Config{
 		LogLevel: parseLogLevel(cfg.LogLevel),
 	}
 	if gitlabLogFormat := os.Getenv("GITLAB_LOG_FORMAT"); gitlabLogFormat == "text" {
 		logConfig.UseTextFormat = true
 	}
-	return v2log.NewWithFile(cfg.LogFile, logConfig)
+	logger, logCloser, err := v2log.NewWithFile(cfg.LogFile, logConfig)
+	slog.SetDefault(logger)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "failed to configure log file %q: %v\n", cfg.LogFile, err)
+		return nil
+	}
+
+	return logCloser
 }
 
 func parseLogLevel(level string) slog.Level {

internal/logger/logger_test.go

@@ -1,11 +1,14 @@
 package logger
 
 import (
+	"bytes"
 	"io"
+	"log/slog"
 	"os"
 	"regexp"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/labkit/log"
 
@@ -60,7 +63,6 @@ func TestConfigureWithPermissionError(t *testing.T) {
 		LogFile:   tempDir,
 		LogFormat: "json",
 	}
-
 	closer := Configure(&config)
 	defer MustClose(t, closer)
 
@@ -108,11 +110,12 @@ func TestConfigureLabkitV2Log(t *testing.T) {
 		LogLevel:  "debug",
 	}
 
-	logger, closer, err := ConfigureLogger(&config)
-	require.NoError(t, err)
-	defer MustClose(t, closer)
-	logger.Info("this is a test")
-	logger.Debug("debug log message")
+	closer := ConfigureLogger(&config)
+	if closer != nil {
+		defer MustClose(t, closer)
+	}
+	slog.Info("this is a test")
+	slog.Debug("debug log message")
 
 	data, err := os.ReadFile(tmpFile)
 	dataStr := string(data)
@@ -128,3 +131,32 @@ func TestConfigureLabkitV2Log(t *testing.T) {
 func MustClose(tb testing.TB, closer io.Closer) {
 	require.NoError(tb, closer.Close())
 }
+
+func TestConfigureLoggerDirectoryFailure(t *testing.T) {
+	tempDir := t.TempDir()
+
+	config := config.Config{
+		LogFile:   tempDir,
+		LogFormat: "json",
+	}
+
+	fileInfo, err := os.Stat(tempDir)
+	require.NoError(t, err)
+	assert.True(t, fileInfo.IsDir())
+
+	old := os.Stderr
+	r, w, _ := os.Pipe()
+	os.Stderr = w
+
+	closer := ConfigureLogger(&config)
+	assert.Nil(t, closer)
+	slog.Info("this is a test")
+
+	w.Close()
+	var buf bytes.Buffer
+	io.Copy(&buf, r)
+	os.Stderr = old
+
+	assert.Contains(t, buf.String(), "failed to configure log file", "capture the error in stderr")
+	assert.Contains(t, buf.String(), "this is a test", "we should still be logging to stderr in this case")
+}