refactor(logging): log user at startup

This logs user info at startup as a debug log message and additionally ensures the logger is configured much earlier for usage.

Signed-off-by: James Elliott <james-d-elliott@users.noreply.github.com>

internal/commands/context.go

@@ -5,6 +5,7 @@ import (
 	"crypto/x509"
 	"fmt"
 	"os"
+	"os/user"
 
 	"github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
@@ -228,6 +229,50 @@ func (ctx *CmdCtx) ConfigValidateRunE(_ *cobra.Command, _ []string) (err error)
 	return nil
 }
 
+func (ctx *CmdCtx) LogConfigure(_ *cobra.Command, _ []string) (err error) {
+	config := ctx.config.Log
+
+	switch config.Level {
+	case logging.LevelError, logging.LevelWarn, logging.LevelInfo, logging.LevelDebug, logging.LevelTrace:
+		break
+	default:
+		config.Level = logging.LevelTrace
+	}
+
+	switch config.Format {
+	case logging.FormatText, logging.FormatJSON:
+		break
+	default:
+		config.Format = logging.FormatText
+	}
+
+	config.KeepStdout = true
+
+	if err = logging.InitializeLogger(config, false); err != nil {
+		return fmt.Errorf("Cannot initialize logger: %w", err)
+	}
+
+	return nil
+}
+
+func (ctx *CmdCtx) LogProcessCurrentUserRunE(_ *cobra.Command, _ []string) (err error) {
+	var current *user.User
+
+	if current, err = user.Current(); err == nil {
+		var gids []string
+
+		fields := map[string]any{"uid": current.Uid, "gid": current.Gid, "username": current.Username, "name": current.Name}
+
+		if gids, err = current.GroupIds(); err != nil {
+			fields["gids"] = gids
+		}
+
+		ctx.log.WithFields(fields).Debug("Process user information")
+	}
+
+	return nil
+}
+
 // ConfigValidateLogRunE logs the warnings and errors detected during the validations that have ran.
 func (ctx *CmdCtx) ConfigValidateLogRunE(_ *cobra.Command, _ []string) (err error) {
 	warnings := ctx.cconfig.validator.Warnings()

internal/commands/root.go

@@ -28,6 +28,8 @@ func NewRootCmd() (cmd *cobra.Command) {
 		PreRunE: ctx.ChainRunE(
 			ctx.ConfigEnsureExistsRunE,
 			ctx.ConfigLoadRunE,
+			ctx.LogConfigure,
+			ctx.LogProcessCurrentUserRunE,
 			ctx.ConfigValidateKeysRunE,
 			ctx.ConfigValidateRunE,
 			ctx.ConfigValidateLogRunE,
@@ -63,8 +65,8 @@ func (ctx *CmdCtx) RootRunE(_ *cobra.Command, _ []string) (err error) {
 		ctx.log.Info("===> Authelia is running in development mode. <===")
 	}
 
-	if err = logging.InitializeLogger(ctx.config.Log, true); err != nil {
+	if err = logging.ConfigureLogger(ctx.config.Log, true); err != nil {
-		ctx.log.Fatalf("Cannot initialize logger: %v", err)
+		ctx.log.Fatalf("Cannot configure logger: %v", err)
 	}
 
 	warns, errs := ctx.LoadProviders()

internal/configuration/validator/const.go

@@ -7,6 +7,7 @@ import (
 	"github.com/valyala/fasthttp"
 
 	"github.com/authelia/authelia/v4/internal/configuration/schema"
+	"github.com/authelia/authelia/v4/internal/logging"
 	"github.com/authelia/authelia/v4/internal/oidc"
 )
 
@@ -324,7 +325,7 @@ const (
 
 	errFmtReplacedConfigurationKey = "invalid configuration key '%s' was replaced by '%s'"
 
-	errFmtLoggingLevelInvalid = "log: option 'level' must be one of %s but it's configured as '%s'"
+	errFmtLoggingInvalid = "log: option '%s' must be one of %s but it's configured as '%s'"
 
 	errFileHashing  = "config key incorrect: authentication_backend.file.hashing should be authentication_backend.file.password"
 	errFilePHashing = "config key incorrect: authentication_backend.file.password_hashing should be authentication_backend.file.password"
@@ -378,7 +379,8 @@ var (
 	validStoragePostgreSQLSSLModes           = []string{"disable", "require", "verify-ca", "verify-full"}
 	validThemeNames                          = []string{"light", "dark", "grey", auto}
 	validSessionSameSiteValues               = []string{"none", "lax", "strict"}
-	validLogLevels                           = []string{"trace", "debug", "info", "warn", "error"}
+	validLogLevels                           = []string{logging.LevelTrace, logging.LevelDebug, logging.LevelInfo, logging.LevelWarn, logging.LevelError}
+	validLogFormats                          = []string{logging.FormatText, logging.FormatJSON}
 	validWebAuthnConveyancePreferences       = []string{string(protocol.PreferNoAttestation), string(protocol.PreferIndirectAttestation), string(protocol.PreferDirectAttestation)}
 	validWebAuthnUserVerificationRequirement = []string{string(protocol.VerificationDiscouraged), string(protocol.VerificationPreferred), string(protocol.VerificationRequired)}
 	validRFC7231HTTPMethodVerbs              = []string{fasthttp.MethodGet, fasthttp.MethodHead, fasthttp.MethodPost, fasthttp.MethodPut, fasthttp.MethodPatch, fasthttp.MethodDelete, fasthttp.MethodTrace, fasthttp.MethodConnect, fasthttp.MethodOptions}

internal/configuration/validator/log.go

@@ -17,7 +17,11 @@ func ValidateLog(config *schema.Configuration, validator *schema.StructValidator
 		config.Log.Format = schema.DefaultLoggingConfiguration.Format
 	}
 
+	if !utils.IsStringInSlice(config.Log.Format, validLogFormats) {
+		validator.Push(fmt.Errorf(errFmtLoggingInvalid, "format", strJoinOr(validLogFormats), config.Log.Format))
+	}
+
 	if !utils.IsStringInSlice(config.Log.Level, validLogLevels) {
-		validator.Push(fmt.Errorf(errFmtLoggingLevelInvalid, strJoinOr(validLogLevels), config.Log.Level))
+		validator.Push(fmt.Errorf(errFmtLoggingInvalid, "level", strJoinOr(validLogLevels), config.Log.Level))
 	}
 }

internal/logging/const.go

@@ -1,3 +1,16 @@
 package logging
 
-const logFormatJSON = "json"
+// Log Format values.
+const (
+	FormatText = "text"
+	FormatJSON = "json"
+)
+
+// Log Level values.
+const (
+	LevelTrace = "trace"
+	LevelDebug = "debug"
+	LevelInfo  = "info"
+	LevelWarn  = "warn"
+	LevelError = "error"
+)

internal/logging/logger.go

@@ -33,60 +33,70 @@ func LoggerCtxPrintf(level logrus.Level) (logger *CtxPrintfLogger) {
 	}
 }
 
-// InitializeLogger configures the default loggers stack levels, formatting, and the output destinations.
+// InitializeLogger configures the default logger similar to ConfigureLogger but also configures the stack levels hook.
-func InitializeLogger(config schema.LogConfiguration, log bool) error {
+func InitializeLogger(config schema.LogConfiguration, log bool) (err error) {
-	setLevelStr(config.Level, log)
-
 	var callerLevels []logrus.Level
 
 	stackLevels := []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel}
 
 	logrus.AddHook(logrus_stack.NewHook(callerLevels, stackLevels))
 
-	if config.Format == logFormatJSON {
+	return ConfigureLogger(config, log)
+}
+
+// ConfigureLogger configures the default loggers level, formatting, and the output destinations.
+func ConfigureLogger(config schema.LogConfiguration, log bool) (err error) {
+	setLevelStr(config.Level, log)
+
+	switch config.Format {
+	case FormatJSON:
 		logrus.SetFormatter(&logrus.JSONFormatter{})
-	} else {
+	default:
 		logrus.SetFormatter(&logrus.TextFormatter{})
 	}
 
-	if config.FilePath != "" {
+	var writers []io.Writer
-		filePath := strings.ReplaceAll(config.FilePath, "%d", time.Now().Format(time.RFC3339))
 
-		f, err := os.OpenFile(filePath, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600)
+	switch {
+	case config.FilePath != "":
+		var file *os.File
 
-		if err != nil {
+		if file, err = os.OpenFile(strings.ReplaceAll(config.FilePath, "%d", time.Now().Format(time.RFC3339)), os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600); err != nil {
 			return err
 		}
 
-		if config.Format != logFormatJSON {
+		if config.Format != FormatJSON {
 			logrus.SetFormatter(&logrus.TextFormatter{
 				DisableColors: true,
 				FullTimestamp: true,
 			})
 		}
 
+		writers = []io.Writer{file}
+
 		if config.KeepStdout {
-			logLocations := io.MultiWriter(os.Stdout, f)
+			writers = append(writers, os.Stdout)
-			logrus.SetOutput(logLocations)
-		} else {
-			logrus.SetOutput(f)
 		}
+	default:
+		writers = []io.Writer{os.Stdout}
 	}
 
+	logrus.SetOutput(io.MultiWriter(writers...))
+
 	return nil
 }
 
 func setLevelStr(level string, log bool) {
 	switch level {
-	case "error":
+	case LevelError:
 		logrus.SetLevel(logrus.ErrorLevel)
-	case "warn":
+	case LevelWarn:
 		logrus.SetLevel(logrus.WarnLevel)
-	case "info":
+	case LevelInfo:
 		logrus.SetLevel(logrus.InfoLevel)
-	case "debug":
+	case LevelDebug:
 		logrus.SetLevel(logrus.DebugLevel)
-	case "trace":
+	case LevelTrace:
 		logrus.SetLevel(logrus.TraceLevel)
 	default:
 		level = "info (default)"