From 66f86554db972824dab6a200abe0be47a21cd694 Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 14:37:21 -0500 Subject: [PATCH 1/7] Refactor logging to use centralized logger utility - Removed direct usage of zerolog in multiple files and replaced it with a centralized logging utility in the `utils` package. - Introduced `Loggers` struct to manage different loggers (Audit, HTTP, App) with configurable levels and outputs. - Updated all relevant files to utilize the new logging structure, ensuring consistent logging practices across the application. - Enhanced error handling and logging messages for better traceability and debugging. --- cmd/tinyauth/create.go | 14 +-- cmd/tinyauth/generate.go | 14 +-- cmd/tinyauth/healthcheck.go | 12 +-- cmd/tinyauth/tinyauth.go | 35 ++++---- cmd/tinyauth/verify.go | 15 ++-- internal/bootstrap/app_bootstrap.go | 46 +++++----- internal/bootstrap/service_bootstrap.go | 5 +- internal/config/config.go | 14 ++- internal/controller/context_controller.go | 7 +- internal/controller/oauth_controller.go | 41 +++++---- internal/controller/proxy_controller.go | 41 +++++---- internal/controller/user_controller.go | 41 +++++---- internal/middleware/context_middleware.go | 21 +++-- internal/middleware/zerolog_middleware.go | 4 +- internal/service/access_controls_service.go | 10 +-- internal/service/auth_service.go | 53 ++++++------ internal/service/docker_service.go | 14 +-- internal/service/generic_oauth_service.go | 4 +- internal/service/ldap_service.go | 14 +-- internal/service/oauth_broker_service.go | 6 +- internal/utils/log_utils.go | 96 +++++++++++++++++++++ 21 files changed, 304 insertions(+), 203 deletions(-) create mode 100644 internal/utils/log_utils.go diff --git a/cmd/tinyauth/create.go b/cmd/tinyauth/create.go index 6179f1db..0319f5ad 100644 --- a/cmd/tinyauth/create.go +++ b/cmd/tinyauth/create.go @@ -3,13 +3,10 @@ package main import ( "errors" "fmt" - "os" "strings" - "time" "github.com/charmbracelet/huh" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/traefik/paerser/cli" "golang.org/x/crypto/bcrypt" ) @@ -43,7 +40,10 @@ func createUserCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}).With().Caller().Logger().Level(zerolog.InfoLevel) + utils.InitLogger(&utils.LoggerConfig{ + Level: "info", + Json: false, + }) if tCfg.Interactive { form := huh.NewForm( @@ -77,7 +77,7 @@ func createUserCmd() *cli.Command { return errors.New("username and password cannot be empty") } - log.Info().Str("username", tCfg.Username).Msg("Creating user") + utils.Log.App.Info().Str("username", tCfg.Username).Msg("Creating user") passwd, err := bcrypt.GenerateFromPassword([]byte(tCfg.Password), bcrypt.DefaultCost) if err != nil { @@ -90,7 +90,7 @@ func createUserCmd() *cli.Command { passwdStr = strings.ReplaceAll(passwdStr, "$", "$$") } - log.Info().Str("user", fmt.Sprintf("%s:%s", tCfg.Username, passwdStr)).Msg("User created") + utils.Log.App.Info().Str("user", fmt.Sprintf("%s:%s", tCfg.Username, passwdStr)).Msg("User created") return nil }, diff --git a/cmd/tinyauth/generate.go b/cmd/tinyauth/generate.go index 63eb671a..3fa4552b 100644 --- a/cmd/tinyauth/generate.go +++ b/cmd/tinyauth/generate.go @@ -5,15 +5,12 @@ import ( "fmt" "os" "strings" - "time" "github.com/steveiliop56/tinyauth/internal/utils" "github.com/charmbracelet/huh" "github.com/mdp/qrterminal/v3" "github.com/pquerna/otp/totp" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" "github.com/traefik/paerser/cli" ) @@ -42,7 +39,10 @@ func generateTotpCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}).With().Caller().Logger().Level(zerolog.InfoLevel) + utils.InitLogger(&utils.LoggerConfig{ + Level: "info", + Json: false, + }) if tCfg.Interactive { form := huh.NewForm( @@ -91,9 +91,9 @@ func generateTotpCmd() *cli.Command { secret := key.Secret() - log.Info().Str("secret", secret).Msg("Generated TOTP secret") + utils.Log.App.Info().Str("secret", secret).Msg("Generated TOTP secret") - log.Info().Msg("Generated QR code") + utils.Log.App.Info().Msg("Generated QR code") config := qrterminal.Config{ Level: qrterminal.L, @@ -112,7 +112,7 @@ func generateTotpCmd() *cli.Command { user.Password = strings.ReplaceAll(user.Password, "$", "$$") } - log.Info().Str("user", fmt.Sprintf("%s:%s:%s", user.Username, user.Password, user.TotpSecret)).Msg("Add the totp secret to your authenticator app then use the verify command to ensure everything is working correctly.") + utils.Log.App.Info().Str("user", fmt.Sprintf("%s:%s:%s", user.Username, user.Password, user.TotpSecret)).Msg("Add the totp secret to your authenticator app then use the verify command to ensure everything is working correctly.") return nil }, diff --git a/cmd/tinyauth/healthcheck.go b/cmd/tinyauth/healthcheck.go index 7b2fdcb9..184d5294 100644 --- a/cmd/tinyauth/healthcheck.go +++ b/cmd/tinyauth/healthcheck.go @@ -9,8 +9,7 @@ import ( "os" "time" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/traefik/paerser/cli" ) @@ -27,7 +26,10 @@ func healthcheckCmd() *cli.Command { Resources: nil, AllowArg: true, Run: func(args []string) error { - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}).With().Caller().Logger().Level(zerolog.InfoLevel) + utils.InitLogger(&utils.LoggerConfig{ + Level: "info", + Json: false, + }) appUrl := os.Getenv("TINYAUTH_APPURL") @@ -39,7 +41,7 @@ func healthcheckCmd() *cli.Command { return errors.New("TINYAUTH_APPURL is not set and no argument was provided") } - log.Info().Str("app_url", appUrl).Msg("Performing health check") + utils.Log.App.Info().Str("app_url", appUrl).Msg("Performing health check") client := http.Client{ Timeout: 30 * time.Second, @@ -77,7 +79,7 @@ func healthcheckCmd() *cli.Command { return fmt.Errorf("failed to decode response: %w", err) } - log.Info().Interface("response", healthResp).Msg("Tinyauth is healthy") + utils.Log.App.Info().Interface("response", healthResp).Msg("Tinyauth is healthy") return nil }, diff --git a/cmd/tinyauth/tinyauth.go b/cmd/tinyauth/tinyauth.go index 7d0dbf76..0f62957a 100644 --- a/cmd/tinyauth/tinyauth.go +++ b/cmd/tinyauth/tinyauth.go @@ -2,22 +2,18 @@ package main import ( "fmt" - "os" - "strings" - "time" "github.com/steveiliop56/tinyauth/internal/bootstrap" "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/steveiliop56/tinyauth/internal/utils/loaders" - "github.com/rs/zerolog" "github.com/rs/zerolog/log" "github.com/traefik/paerser/cli" ) func NewTinyauthCmdConfiguration() *config.Config { return &config.Config{ - LogLevel: "info", ResourcesDir: "./resources", DatabasePath: "./tinyauth.db", Server: config.ServerConfig{ @@ -39,6 +35,10 @@ func NewTinyauthCmdConfiguration() *config.Config { Insecure: false, SearchFilter: "(uid=%s)", }, + Log: config.LogConfig{ + Level: "info", + Json: false, + }, Experimental: config.ExperimentalConfig{ ConfigFile: "", }, @@ -102,21 +102,24 @@ func main() { } func runCmd(cfg config.Config) error { - logLevel, err := zerolog.ParseLevel(strings.ToLower(cfg.LogLevel)) - - if err != nil { - log.Error().Err(err).Msg("Invalid or missing log level, defaulting to info") - } else { - zerolog.SetGlobalLevel(logLevel) + outputs := make(map[string]utils.LoggerOutputConfig) + for name, out := range cfg.Log.Outputs { + outputs[name] = utils.LoggerOutputConfig{ + Enabled: out.Enabled, + Level: out.Level, + } } - log.Logger = log.With().Caller().Logger() - - if !cfg.LogJSON { - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}) + err := utils.InitLogger(&utils.LoggerConfig{ + Level: cfg.Log.Level, + Json: cfg.Log.Json, + Outputs: outputs, + }) + if err != nil { + log.Error().Err(err).Msg("Failed to initialize logger") } - log.Info().Str("version", config.Version).Msg("Starting tinyauth") + utils.Log.App.Info().Str("version", config.Version).Msg("Starting tinyauth") app := bootstrap.NewBootstrapApp(cfg) diff --git a/cmd/tinyauth/verify.go b/cmd/tinyauth/verify.go index 9634808d..34510dc1 100644 --- a/cmd/tinyauth/verify.go +++ b/cmd/tinyauth/verify.go @@ -3,15 +3,11 @@ package main import ( "errors" "fmt" - "os" - "time" "github.com/steveiliop56/tinyauth/internal/utils" "github.com/charmbracelet/huh" "github.com/pquerna/otp/totp" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" "github.com/traefik/paerser/cli" "golang.org/x/crypto/bcrypt" ) @@ -47,7 +43,10 @@ func verifyUserCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}).With().Caller().Logger().Level(zerolog.InfoLevel) + utils.InitLogger(&utils.LoggerConfig{ + Level: "info", + Json: false, + }) if tCfg.Interactive { form := huh.NewForm( @@ -101,9 +100,9 @@ func verifyUserCmd() *cli.Command { if user.TotpSecret == "" { if tCfg.Totp != "" { - log.Warn().Msg("User does not have TOTP secret") + utils.Log.App.Warn().Msg("User does not have TOTP secret") } - log.Info().Msg("User verified") + utils.Log.App.Info().Msg("User verified") return nil } @@ -113,7 +112,7 @@ func verifyUserCmd() *cli.Command { return fmt.Errorf("TOTP code incorrect") } - log.Info().Msg("User verified") + utils.Log.App.Info().Msg("User verified") return nil }, diff --git a/internal/bootstrap/app_bootstrap.go b/internal/bootstrap/app_bootstrap.go index 414beea5..22c02f36 100644 --- a/internal/bootstrap/app_bootstrap.go +++ b/internal/bootstrap/app_bootstrap.go @@ -16,8 +16,6 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/utils" - - "github.com/rs/zerolog/log" ) type BootstrapApp struct { @@ -103,13 +101,13 @@ func (app *BootstrapApp) Setup() error { app.context.redirectCookieName = fmt.Sprintf("%s-%s", config.RedirectCookieName, cookieId) // Dumps - log.Trace().Interface("config", app.config).Msg("Config dump") - log.Trace().Interface("users", app.context.users).Msg("Users dump") - log.Trace().Interface("oauthProviders", app.context.oauthProviders).Msg("OAuth providers dump") - log.Trace().Str("cookieDomain", app.context.cookieDomain).Msg("Cookie domain") - log.Trace().Str("sessionCookieName", app.context.sessionCookieName).Msg("Session cookie name") - log.Trace().Str("csrfCookieName", app.context.csrfCookieName).Msg("CSRF cookie name") - log.Trace().Str("redirectCookieName", app.context.redirectCookieName).Msg("Redirect cookie name") + utils.Log.App.Trace().Interface("config", app.config).Msg("Config dump") + utils.Log.App.Trace().Interface("users", app.context.users).Msg("Users dump") + utils.Log.App.Trace().Interface("oauthProviders", app.context.oauthProviders).Msg("OAuth providers dump") + utils.Log.App.Trace().Str("cookieDomain", app.context.cookieDomain).Msg("Cookie domain") + utils.Log.App.Trace().Str("sessionCookieName", app.context.sessionCookieName).Msg("Session cookie name") + utils.Log.App.Trace().Str("csrfCookieName", app.context.csrfCookieName).Msg("CSRF cookie name") + utils.Log.App.Trace().Str("redirectCookieName", app.context.redirectCookieName).Msg("Redirect cookie name") // Database db, err := app.SetupDatabase(app.config.DatabasePath) @@ -153,7 +151,7 @@ func (app *BootstrapApp) Setup() error { }) } - log.Debug().Interface("providers", configuredProviders).Msg("Authentication providers") + utils.Log.App.Debug().Interface("providers", configuredProviders).Msg("Authentication providers") if len(configuredProviders) == 0 { return fmt.Errorf("no authentication providers configured") @@ -169,28 +167,28 @@ func (app *BootstrapApp) Setup() error { } // Start db cleanup routine - log.Debug().Msg("Starting database cleanup routine") + utils.Log.App.Debug().Msg("Starting database cleanup routine") go app.dbCleanup(queries) // If analytics are not disabled, start heartbeat if !app.config.DisableAnalytics { - log.Debug().Msg("Starting heartbeat routine") + utils.Log.App.Debug().Msg("Starting heartbeat routine") go app.heartbeat() } // If we have an socket path, bind to it if app.config.Server.SocketPath != "" { if _, err := os.Stat(app.config.Server.SocketPath); err == nil { - log.Info().Msgf("Removing existing socket file %s", app.config.Server.SocketPath) + utils.Log.App.Info().Msgf("Removing existing socket file %s", app.config.Server.SocketPath) err := os.Remove(app.config.Server.SocketPath) if err != nil { return fmt.Errorf("failed to remove existing socket file: %w", err) } } - log.Info().Msgf("Starting server on unix socket %s", app.config.Server.SocketPath) + utils.Log.App.Info().Msgf("Starting server on unix socket %s", app.config.Server.SocketPath) if err := router.RunUnix(app.config.Server.SocketPath); err != nil { - log.Fatal().Err(err).Msg("Failed to start server") + utils.Log.App.Fatal().Err(err).Msg("Failed to start server") } return nil @@ -198,9 +196,9 @@ func (app *BootstrapApp) Setup() error { // Start server address := fmt.Sprintf("%s:%d", app.config.Server.Address, app.config.Server.Port) - log.Info().Msgf("Starting server on %s", address) + utils.Log.App.Info().Msgf("Starting server on %s", address) if err := router.Run(address); err != nil { - log.Fatal().Err(err).Msg("Failed to start server") + utils.Log.App.Fatal().Err(err).Msg("Failed to start server") } return nil @@ -223,7 +221,7 @@ func (app *BootstrapApp) heartbeat() { bodyJson, err := json.Marshal(body) if err != nil { - log.Error().Err(err).Msg("Failed to marshal heartbeat body") + utils.Log.App.Error().Err(err).Msg("Failed to marshal heartbeat body") return } @@ -234,12 +232,12 @@ func (app *BootstrapApp) heartbeat() { heartbeatURL := config.ApiServer + "/v1/instances/heartbeat" for ; true; <-ticker.C { - log.Debug().Msg("Sending heartbeat") + utils.Log.App.Debug().Msg("Sending heartbeat") req, err := http.NewRequest(http.MethodPost, heartbeatURL, bytes.NewReader(bodyJson)) if err != nil { - log.Error().Err(err).Msg("Failed to create heartbeat request") + utils.Log.App.Error().Err(err).Msg("Failed to create heartbeat request") continue } @@ -248,14 +246,14 @@ func (app *BootstrapApp) heartbeat() { res, err := client.Do(req) if err != nil { - log.Error().Err(err).Msg("Failed to send heartbeat") + utils.Log.App.Error().Err(err).Msg("Failed to send heartbeat") continue } res.Body.Close() if res.StatusCode != 200 && res.StatusCode != 201 { - log.Debug().Str("status", res.Status).Msg("Heartbeat returned non-200/201 status") + utils.Log.App.Debug().Str("status", res.Status).Msg("Heartbeat returned non-200/201 status") } } } @@ -266,10 +264,10 @@ func (app *BootstrapApp) dbCleanup(queries *repository.Queries) { ctx := context.Background() for ; true; <-ticker.C { - log.Debug().Msg("Cleaning up old database sessions") + utils.Log.App.Debug().Msg("Cleaning up old database sessions") err := queries.DeleteExpiredSessions(ctx, time.Now().Unix()) if err != nil { - log.Error().Err(err).Msg("Failed to clean up old database sessions") + utils.Log.App.Error().Err(err).Msg("Failed to clean up old database sessions") } } } diff --git a/internal/bootstrap/service_bootstrap.go b/internal/bootstrap/service_bootstrap.go index 02dd4530..f5de3995 100644 --- a/internal/bootstrap/service_bootstrap.go +++ b/internal/bootstrap/service_bootstrap.go @@ -3,8 +3,7 @@ package bootstrap import ( "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/service" - - "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/utils" ) type Services struct { @@ -34,7 +33,7 @@ func (app *BootstrapApp) initServices(queries *repository.Queries) (Services, er if err == nil { services.ldapService = ldapService } else { - log.Warn().Err(err).Msg("Failed to initialize LDAP service, continuing without it") + utils.Log.App.Warn().Err(err).Msg("Failed to initialize LDAP service, continuing without it") } dockerService := service.NewDockerService() diff --git a/internal/config/config.go b/internal/config/config.go index 920288d1..9c3b0aaf 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -16,13 +16,11 @@ var RedirectCookieName = "tinyauth-redirect" type Config struct { AppURL string `description:"The base URL where the app is hosted." yaml:"appUrl"` - LogLevel string `description:"Log level (trace, debug, info, warn, error)." yaml:"logLevel"` ResourcesDir string `description:"The directory where resources are stored." yaml:"resourcesDir"` DatabasePath string `description:"The path to the database file." yaml:"databasePath"` DisableAnalytics bool `description:"Disable analytics." yaml:"disableAnalytics"` DisableResources bool `description:"Disable resources server." yaml:"disableResources"` DisableUIWarnings bool `description:"Disable UI warnings." yaml:"disableUIWarnings"` - LogJSON bool `description:"Enable JSON formatted logs." yaml:"logJSON"` Server ServerConfig `description:"Server configuration." yaml:"server"` Auth AuthConfig `description:"Authentication configuration." yaml:"auth"` Apps map[string]App `description:"Application ACLs configuration." yaml:"apps"` @@ -30,6 +28,7 @@ type Config struct { UI UIConfig `description:"UI customization." yaml:"ui"` Ldap LdapConfig `description:"LDAP configuration." yaml:"ldap"` Experimental ExperimentalConfig `description:"Experimental features, use with caution." yaml:"experimental"` + Log LogConfig `description:"Logging configuration." yaml:"log"` } type ServerConfig struct { @@ -78,6 +77,17 @@ type LdapConfig struct { AuthKey string `description:"Certificate key for mTLS authentication." yaml:"authKey"` } +type LogConfig struct { + Level string `description:"Log level (trace, debug, info, warn, error)." yaml:"level"` + Json bool `description:"Enable JSON formatted logs." yaml:"json"` + Outputs map[string]LogOutputConfig `description:"Configuration for specific log outputs." yaml:"outputs"` +} + +type LogOutputConfig struct { + Enabled bool `description:"Enable this log output." yaml:"enabled"` + Level string `description:"Log level for this output (trace, debug, info, warn, error)." yaml:"level"` +} + type ExperimentalConfig struct { ConfigFile string `description:"Path to config file." yaml:"-"` } diff --git a/internal/controller/context_controller.go b/internal/controller/context_controller.go index 181c2f64..85581210 100644 --- a/internal/controller/context_controller.go +++ b/internal/controller/context_controller.go @@ -7,7 +7,6 @@ import ( "github.com/steveiliop56/tinyauth/internal/utils" "github.com/gin-gonic/gin" - "github.com/rs/zerolog/log" ) type UserContextResponse struct { @@ -61,7 +60,7 @@ type ContextController struct { func NewContextController(config ContextControllerConfig, router *gin.RouterGroup) *ContextController { if config.DisableUIWarnings { - log.Warn().Msg("UI warnings are disabled. This may expose users to security risks. Proceed with caution.") + utils.Log.App.Warn().Msg("UI warnings are disabled. This may expose users to security risks. Proceed with caution.") } return &ContextController{ @@ -94,7 +93,7 @@ func (controller *ContextController) userContextHandler(c *gin.Context) { } if err != nil { - log.Debug().Err(err).Msg("No user context found in request") + utils.Log.App.Debug().Err(err).Msg("No user context found in request") userContext.Status = 401 userContext.Message = "Unauthorized" userContext.IsLoggedIn = false @@ -108,7 +107,7 @@ func (controller *ContextController) userContextHandler(c *gin.Context) { func (controller *ContextController) appContextHandler(c *gin.Context) { appUrl, err := url.Parse(controller.config.AppURL) if err != nil { - log.Error().Err(err).Msg("Failed to parse app URL") + utils.Log.App.Error().Err(err).Msg("Failed to parse app URL") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", diff --git a/internal/controller/oauth_controller.go b/internal/controller/oauth_controller.go index 3635e85c..e533a2fa 100644 --- a/internal/controller/oauth_controller.go +++ b/internal/controller/oauth_controller.go @@ -12,7 +12,6 @@ import ( "github.com/gin-gonic/gin" "github.com/google/go-querystring/query" - "github.com/rs/zerolog/log" ) type OAuthRequest struct { @@ -54,7 +53,7 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - log.Error().Err(err).Msg("Failed to bind URI") + utils.Log.App.Error().Err(err).Msg("Failed to bind URI") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -65,7 +64,7 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { service, exists := controller.broker.GetService(req.Provider) if !exists { - log.Warn().Msgf("OAuth provider not found: %s", req.Provider) + utils.Log.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) c.JSON(404, gin.H{ "status": 404, "message": "Not Found", @@ -82,12 +81,12 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { isRedirectSafe := utils.IsRedirectSafe(redirectURI, controller.config.CookieDomain) if !isRedirectSafe { - log.Warn().Str("redirect_uri", redirectURI).Msg("Unsafe redirect URI detected, ignoring") + utils.Log.App.Warn().Str("redirect_uri", redirectURI).Msg("Unsafe redirect URI detected, ignoring") redirectURI = "" } if redirectURI != "" && isRedirectSafe { - log.Debug().Msg("Setting redirect URI cookie") + utils.Log.App.Debug().Msg("Setting redirect URI cookie") c.SetCookie(controller.config.RedirectCookieName, redirectURI, int(time.Hour.Seconds()), "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true) } @@ -103,7 +102,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - log.Error().Err(err).Msg("Failed to bind URI") + utils.Log.App.Error().Err(err).Msg("Failed to bind URI") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -115,7 +114,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { csrfCookie, err := c.Cookie(controller.config.CSRFCookieName) if err != nil || state != csrfCookie { - log.Warn().Err(err).Msg("CSRF token mismatch or cookie missing") + utils.Log.App.Warn().Err(err).Msg("CSRF token mismatch or cookie missing") c.SetCookie(controller.config.CSRFCookieName, "", -1, "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true) c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return @@ -127,14 +126,14 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { service, exists := controller.broker.GetService(req.Provider) if !exists { - log.Warn().Msgf("OAuth provider not found: %s", req.Provider) + utils.Log.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } err = service.VerifyCode(code) if err != nil { - log.Error().Err(err).Msg("Failed to verify OAuth code") + utils.Log.App.Error().Err(err).Msg("Failed to verify OAuth code") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -142,26 +141,26 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { user, err := controller.broker.GetUser(req.Provider) if err != nil { - log.Error().Err(err).Msg("Failed to get user from OAuth provider") + utils.Log.App.Error().Err(err).Msg("Failed to get user from OAuth provider") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } if user.Email == "" { - log.Error().Msg("OAuth provider did not return an email") + utils.Log.App.Error().Msg("OAuth provider did not return an email") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } if !controller.auth.IsEmailWhitelisted(user.Email) { - log.Warn().Str("email", user.Email).Msg("Email not whitelisted") + utils.Log.App.Warn().Str("email", user.Email).Msg("Email not whitelisted") queries, err := query.Values(config.UnauthorizedQuery{ Username: user.Email, }) if err != nil { - log.Error().Err(err).Msg("Failed to encode unauthorized query") + utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -173,20 +172,20 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { var name string if strings.TrimSpace(user.Name) != "" { - log.Debug().Msg("Using name from OAuth provider") + utils.Log.App.Debug().Msg("Using name from OAuth provider") name = user.Name } else { - log.Debug().Msg("No name from OAuth provider, using pseudo name") + utils.Log.App.Debug().Msg("No name from OAuth provider, using pseudo name") name = fmt.Sprintf("%s (%s)", utils.Capitalize(strings.Split(user.Email, "@")[0]), strings.Split(user.Email, "@")[1]) } var username string if strings.TrimSpace(user.PreferredUsername) != "" { - log.Debug().Msg("Using preferred username from OAuth provider") + utils.Log.App.Debug().Msg("Using preferred username from OAuth provider") username = user.PreferredUsername } else { - log.Debug().Msg("No preferred username from OAuth provider, using pseudo username") + utils.Log.App.Debug().Msg("No preferred username from OAuth provider, using pseudo username") username = strings.Replace(user.Email, "@", "_", -1) } @@ -200,12 +199,12 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { OAuthSub: user.Sub, } - log.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") + utils.Log.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") err = controller.auth.CreateSessionCookie(c, &sessionCookie) if err != nil { - log.Error().Err(err).Msg("Failed to create session cookie") + utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -213,7 +212,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { redirectURI, err := c.Cookie(controller.config.RedirectCookieName) if err != nil || !utils.IsRedirectSafe(redirectURI, controller.config.CookieDomain) { - log.Debug().Msg("No redirect URI cookie found, redirecting to app root") + utils.Log.App.Debug().Msg("No redirect URI cookie found, redirecting to app root") c.Redirect(http.StatusTemporaryRedirect, controller.config.AppURL) return } @@ -223,7 +222,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { }) if err != nil { - log.Error().Err(err).Msg("Failed to encode redirect URI query") + utils.Log.App.Error().Err(err).Msg("Failed to encode redirect URI query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } diff --git a/internal/controller/proxy_controller.go b/internal/controller/proxy_controller.go index 2520bfbf..3c8df988 100644 --- a/internal/controller/proxy_controller.go +++ b/internal/controller/proxy_controller.go @@ -12,7 +12,6 @@ import ( "github.com/gin-gonic/gin" "github.com/google/go-querystring/query" - "github.com/rs/zerolog/log" ) var SupportedProxies = []string{"nginx", "traefik", "caddy", "envoy"} @@ -52,7 +51,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - log.Error().Err(err).Msg("Failed to bind URI") + utils.Log.App.Error().Err(err).Msg("Failed to bind URI") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -61,7 +60,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { } if !slices.Contains(SupportedProxies, req.Proxy) { - log.Warn().Str("proxy", req.Proxy).Msg("Invalid proxy") + utils.Log.App.Warn().Str("proxy", req.Proxy).Msg("Invalid proxy") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -73,7 +72,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { // Envoy uses the original client method for the external auth request // so we allow Any standard HTTP method for /api/auth/envoy if req.Proxy != "envoy" && c.Request.Method != http.MethodGet { - log.Warn().Str("method", c.Request.Method).Msg("Invalid method for proxy") + utils.Log.App.Warn().Str("method", c.Request.Method).Msg("Invalid method for proxy") c.Header("Allow", "GET") c.JSON(405, gin.H{ "status": 405, @@ -85,9 +84,9 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { isBrowser := strings.Contains(c.Request.Header.Get("Accept"), "text/html") if isBrowser { - log.Debug().Msg("Request identified as (most likely) coming from a browser") + utils.Log.App.Debug().Msg("Request identified as (most likely) coming from a browser") } else { - log.Debug().Msg("Request identified as (most likely) coming from a non-browser client") + utils.Log.App.Debug().Msg("Request identified as (most likely) coming from a non-browser client") } uri := c.Request.Header.Get("X-Forwarded-Uri") @@ -98,12 +97,12 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { acls, err := controller.acls.GetAccessControls(host) if err != nil { - log.Error().Err(err).Msg("Failed to get access controls for resource") + utils.Log.App.Error().Err(err).Msg("Failed to get access controls for resource") controller.handleError(c, req, isBrowser) return } - log.Trace().Interface("acls", acls).Msg("ACLs for resource") + utils.Log.App.Trace().Interface("acls", acls).Msg("ACLs for resource") clientIP := c.ClientIP() @@ -119,13 +118,13 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { authEnabled, err := controller.auth.IsAuthEnabled(uri, acls.Path) if err != nil { - log.Error().Err(err).Msg("Failed to check if auth is enabled for resource") + utils.Log.App.Error().Err(err).Msg("Failed to check if auth is enabled for resource") controller.handleError(c, req, isBrowser) return } if !authEnabled { - log.Debug().Msg("Authentication disabled for resource, allowing access") + utils.Log.App.Debug().Msg("Authentication disabled for resource, allowing access") controller.setHeaders(c, acls) c.JSON(200, gin.H{ "status": 200, @@ -149,7 +148,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.Error().Err(err).Msg("Failed to encode unauthorized query") + utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -163,7 +162,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { context, err := utils.GetContext(c) if err != nil { - log.Debug().Msg("No user context found in request, treating as not logged in") + utils.Log.App.Debug().Msg("No user context found in request, treating as not logged in") userContext = config.UserContext{ IsLoggedIn: false, } @@ -171,10 +170,10 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { userContext = context } - log.Trace().Interface("context", userContext).Msg("User context from request") + utils.Log.App.Trace().Interface("context", userContext).Msg("User context from request") if userContext.Provider == "basic" && userContext.TotpEnabled { - log.Debug().Msg("User has TOTP enabled, denying basic auth access") + utils.Log.App.Debug().Msg("User has TOTP enabled, denying basic auth access") userContext.IsLoggedIn = false } @@ -182,7 +181,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { userAllowed := controller.auth.IsUserAllowed(c, userContext, acls) if !userAllowed { - log.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User not allowed to access resource") + utils.Log.App.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User not allowed to access resource") if req.Proxy == "nginx" || !isBrowser { c.JSON(403, gin.H{ @@ -197,7 +196,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.Error().Err(err).Msg("Failed to encode unauthorized query") + utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -216,7 +215,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { groupOK := controller.auth.IsInOAuthGroup(c, userContext, acls.OAuth.Groups) if !groupOK { - log.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User OAuth groups do not match resource requirements") + utils.Log.App.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User OAuth groups do not match resource requirements") if req.Proxy == "nginx" || !isBrowser { c.JSON(403, gin.H{ @@ -232,7 +231,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.Error().Err(err).Msg("Failed to encode unauthorized query") + utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -276,7 +275,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.Error().Err(err).Msg("Failed to encode redirect URI query") + utils.Log.App.Error().Err(err).Msg("Failed to encode redirect URI query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -290,14 +289,14 @@ func (controller *ProxyController) setHeaders(c *gin.Context, acls config.App) { headers := utils.ParseHeaders(acls.Response.Headers) for key, value := range headers { - log.Debug().Str("header", key).Msg("Setting header") + utils.Log.App.Debug().Str("header", key).Msg("Setting header") c.Header(key, value) } basicPassword := utils.GetSecret(acls.Response.BasicAuth.Password, acls.Response.BasicAuth.PasswordFile) if acls.Response.BasicAuth.Username != "" && basicPassword != "" { - log.Debug().Str("username", acls.Response.BasicAuth.Username).Msg("Setting basic auth header") + utils.Log.App.Debug().Str("username", acls.Response.BasicAuth.Username).Msg("Setting basic auth header") c.Header("Authorization", fmt.Sprintf("Basic %s", utils.GetBasicAuth(acls.Response.BasicAuth.Username, basicPassword))) } } diff --git a/internal/controller/user_controller.go b/internal/controller/user_controller.go index 5670dd2d..6eb7d16c 100644 --- a/internal/controller/user_controller.go +++ b/internal/controller/user_controller.go @@ -11,7 +11,6 @@ import ( "github.com/gin-gonic/gin" "github.com/pquerna/otp/totp" - "github.com/rs/zerolog/log" ) type LoginRequest struct { @@ -53,7 +52,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { err := c.ShouldBindJSON(&req) if err != nil { - log.Error().Err(err).Msg("Failed to bind JSON") + utils.Log.App.Error().Err(err).Msg("Failed to bind JSON") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -61,12 +60,12 @@ func (controller *UserController) loginHandler(c *gin.Context) { return } - log.Debug().Str("username", req.Username).Msg("Login attempt") + utils.Log.App.Debug().Str("username", req.Username).Msg("Login attempt") isLocked, remaining := controller.auth.IsAccountLocked(req.Username) if isLocked { - log.Warn().Str("username", req.Username).Msg("Account is locked due to too many failed login attempts") + utils.Log.App.Warn().Str("username", req.Username).Msg("Account is locked due to too many failed login attempts") c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.JSON(429, gin.H{ @@ -79,7 +78,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { userSearch := controller.auth.SearchUser(req.Username) if userSearch.Type == "unknown" { - log.Warn().Str("username", req.Username).Msg("User not found") + utils.Log.App.Warn().Str("username", req.Username).Msg("User not found") controller.auth.RecordLoginAttempt(req.Username, false) c.JSON(401, gin.H{ "status": 401, @@ -89,7 +88,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { } if !controller.auth.VerifyUser(userSearch, req.Password) { - log.Warn().Str("username", req.Username).Msg("Invalid password") + utils.Log.App.Warn().Str("username", req.Username).Msg("Invalid password") controller.auth.RecordLoginAttempt(req.Username, false) c.JSON(401, gin.H{ "status": 401, @@ -98,7 +97,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { return } - log.Info().Str("username", req.Username).Msg("Login successful") + utils.Log.App.Info().Str("username", req.Username).Msg("Login successful") controller.auth.RecordLoginAttempt(req.Username, true) @@ -106,7 +105,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { user := controller.auth.GetLocalUser(userSearch.Username) if user.TotpSecret != "" { - log.Debug().Str("username", req.Username).Msg("User has TOTP enabled, requiring TOTP verification") + utils.Log.App.Debug().Str("username", req.Username).Msg("User has TOTP enabled, requiring TOTP verification") err := controller.auth.CreateSessionCookie(c, &config.SessionCookie{ Username: user.Username, @@ -117,7 +116,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { }) if err != nil { - log.Error().Err(err).Msg("Failed to create session cookie") + utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -141,12 +140,12 @@ func (controller *UserController) loginHandler(c *gin.Context) { Provider: "username", } - log.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") + utils.Log.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") err = controller.auth.CreateSessionCookie(c, &sessionCookie) if err != nil { - log.Error().Err(err).Msg("Failed to create session cookie") + utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -161,7 +160,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { } func (controller *UserController) logoutHandler(c *gin.Context) { - log.Debug().Msg("Logout request received") + utils.Log.App.Debug().Msg("Logout request received") controller.auth.DeleteSessionCookie(c) @@ -176,7 +175,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { err := c.ShouldBindJSON(&req) if err != nil { - log.Error().Err(err).Msg("Failed to bind JSON") + utils.Log.App.Error().Err(err).Msg("Failed to bind JSON") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -187,7 +186,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { context, err := utils.GetContext(c) if err != nil { - log.Error().Err(err).Msg("Failed to get user context") + utils.Log.App.Error().Err(err).Msg("Failed to get user context") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -196,7 +195,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { } if !context.TotpPending { - log.Warn().Msg("TOTP attempt without a pending TOTP session") + utils.Log.App.Warn().Msg("TOTP attempt without a pending TOTP session") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -204,12 +203,12 @@ func (controller *UserController) totpHandler(c *gin.Context) { return } - log.Debug().Str("username", context.Username).Msg("TOTP verification attempt") + utils.Log.App.Debug().Str("username", context.Username).Msg("TOTP verification attempt") isLocked, remaining := controller.auth.IsAccountLocked(context.Username) if isLocked { - log.Warn().Str("username", context.Username).Msg("Account is locked due to too many failed TOTP attempts") + utils.Log.App.Warn().Str("username", context.Username).Msg("Account is locked due to too many failed TOTP attempts") c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.JSON(429, gin.H{ @@ -224,7 +223,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { ok := totp.Validate(req.Code, user.TotpSecret) if !ok { - log.Warn().Str("username", context.Username).Msg("Invalid TOTP code") + utils.Log.App.Warn().Str("username", context.Username).Msg("Invalid TOTP code") controller.auth.RecordLoginAttempt(context.Username, false) c.JSON(401, gin.H{ "status": 401, @@ -233,7 +232,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { return } - log.Info().Str("username", context.Username).Msg("TOTP verification successful") + utils.Log.App.Info().Str("username", context.Username).Msg("TOTP verification successful") controller.auth.RecordLoginAttempt(context.Username, true) @@ -244,12 +243,12 @@ func (controller *UserController) totpHandler(c *gin.Context) { Provider: "username", } - log.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") + utils.Log.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") err = controller.auth.CreateSessionCookie(c, &sessionCookie) if err != nil { - log.Error().Err(err).Msg("Failed to create session cookie") + utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", diff --git a/internal/middleware/context_middleware.go b/internal/middleware/context_middleware.go index a6bddc96..9c401945 100644 --- a/internal/middleware/context_middleware.go +++ b/internal/middleware/context_middleware.go @@ -10,7 +10,6 @@ import ( "github.com/steveiliop56/tinyauth/internal/utils" "github.com/gin-gonic/gin" - "github.com/rs/zerolog/log" ) type ContextMiddlewareConfig struct { @@ -40,7 +39,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { cookie, err := m.auth.GetSessionCookie(c) if err != nil { - log.Debug().Err(err).Msg("No valid session cookie found") + utils.Log.App.Debug().Err(err).Msg("No valid session cookie found") goto basic } @@ -62,7 +61,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { userSearch := m.auth.SearchUser(cookie.Username) if userSearch.Type == "unknown" || userSearch.Type == "error" { - log.Debug().Msg("User from session cookie not found") + utils.Log.App.Debug().Msg("User from session cookie not found") m.auth.DeleteSessionCookie(c) goto basic } @@ -81,13 +80,13 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { _, exists := m.broker.GetService(cookie.Provider) if !exists { - log.Debug().Msg("OAuth provider from session cookie not found") + utils.Log.App.Debug().Msg("OAuth provider from session cookie not found") m.auth.DeleteSessionCookie(c) goto basic } if !m.auth.IsEmailWhitelisted(cookie.Email) { - log.Debug().Msg("Email from session cookie not whitelisted") + utils.Log.App.Debug().Msg("Email from session cookie not whitelisted") m.auth.DeleteSessionCookie(c) goto basic } @@ -112,7 +111,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { basic := m.auth.GetBasicAuth(c) if basic == nil { - log.Debug().Msg("No basic auth provided") + utils.Log.App.Debug().Msg("No basic auth provided") c.Next() return } @@ -120,7 +119,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { locked, remaining := m.auth.IsAccountLocked(basic.Username) if locked { - log.Debug().Msgf("Account for user %s is locked for %d seconds, denying auth", basic.Username, remaining) + utils.Log.App.Debug().Msgf("Account for user %s is locked for %d seconds, denying auth", basic.Username, remaining) c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.Next() @@ -131,14 +130,14 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { if userSearch.Type == "unknown" || userSearch.Type == "error" { m.auth.RecordLoginAttempt(basic.Username, false) - log.Debug().Msg("User from basic auth not found") + utils.Log.App.Debug().Msg("User from basic auth not found") c.Next() return } if !m.auth.VerifyUser(userSearch, basic.Password) { m.auth.RecordLoginAttempt(basic.Username, false) - log.Debug().Msg("Invalid password for basic auth user") + utils.Log.App.Debug().Msg("Invalid password for basic auth user") c.Next() return } @@ -147,7 +146,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { switch userSearch.Type { case "local": - log.Debug().Msg("Basic auth user is local") + utils.Log.App.Debug().Msg("Basic auth user is local") user := m.auth.GetLocalUser(basic.Username) @@ -162,7 +161,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { c.Next() return case "ldap": - log.Debug().Msg("Basic auth user is LDAP") + utils.Log.App.Debug().Msg("Basic auth user is LDAP") c.Set("context", &config.UserContext{ Username: basic.Username, Name: utils.Capitalize(basic.Username), diff --git a/internal/middleware/zerolog_middleware.go b/internal/middleware/zerolog_middleware.go index f3ca4855..1d62d467 100644 --- a/internal/middleware/zerolog_middleware.go +++ b/internal/middleware/zerolog_middleware.go @@ -5,7 +5,7 @@ import ( "time" "github.com/gin-gonic/gin" - "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/utils" ) var ( @@ -49,7 +49,7 @@ func (m *ZerologMiddleware) Middleware() gin.HandlerFunc { latency := time.Since(tStart).String() - subLogger := log.With().Str("method", method). + subLogger := utils.Log.HTTP.With().Str("method", method). Str("path", path). Str("address", address). Str("client_ip", clientIP). diff --git a/internal/service/access_controls_service.go b/internal/service/access_controls_service.go index 74117ea4..cbb0ba42 100644 --- a/internal/service/access_controls_service.go +++ b/internal/service/access_controls_service.go @@ -4,8 +4,8 @@ import ( "errors" "strings" - "github.com/rs/zerolog/log" "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils" ) type AccessControlsService struct { @@ -27,12 +27,12 @@ func (acls *AccessControlsService) Init() error { func (acls *AccessControlsService) lookupStaticACLs(domain string) (config.App, error) { for app, config := range acls.static { if config.Config.Domain == domain { - log.Debug().Str("name", app).Msg("Found matching container by domain") + utils.Log.App.Debug().Str("name", app).Msg("Found matching container by domain") return config, nil } if strings.SplitN(domain, ".", 2)[0] == app { - log.Debug().Str("name", app).Msg("Found matching container by app name") + utils.Log.App.Debug().Str("name", app).Msg("Found matching container by app name") return config, nil } } @@ -44,11 +44,11 @@ func (acls *AccessControlsService) GetAccessControls(domain string) (config.App, app, err := acls.lookupStaticACLs(domain) if err == nil { - log.Debug().Msg("Using ACls from static configuration") + utils.Log.App.Debug().Msg("Using ACls from static configuration") return app, nil } // Fallback to Docker labels - log.Debug().Msg("Falling back to Docker labels for ACLs") + utils.Log.App.Debug().Msg("Falling back to Docker labels for ACLs") return acls.docker.GetLabels(domain) } diff --git a/internal/service/auth_service.go b/internal/service/auth_service.go index 6d829c67..13feec62 100644 --- a/internal/service/auth_service.go +++ b/internal/service/auth_service.go @@ -15,7 +15,6 @@ import ( "github.com/gin-gonic/gin" "github.com/google/uuid" - "github.com/rs/zerolog/log" "golang.org/x/crypto/bcrypt" ) @@ -73,7 +72,7 @@ func (auth *AuthService) SearchUser(username string) config.UserSearch { userDN, err := auth.ldap.Search(username) if err != nil { - log.Warn().Err(err).Str("username", username).Msg("Failed to search for user in LDAP") + utils.Log.App.Warn().Err(err).Str("username", username).Msg("Failed to search for user in LDAP") return config.UserSearch{ Type: "error", } @@ -99,24 +98,24 @@ func (auth *AuthService) VerifyUser(search config.UserSearch, password string) b if auth.ldap != nil { err := auth.ldap.Bind(search.Username, password) if err != nil { - log.Warn().Err(err).Str("username", search.Username).Msg("Failed to bind to LDAP") + utils.Log.App.Warn().Err(err).Str("username", search.Username).Msg("Failed to bind to LDAP") return false } err = auth.ldap.BindService(true) if err != nil { - log.Error().Err(err).Msg("Failed to rebind with service account after user authentication") + utils.Log.App.Error().Err(err).Msg("Failed to rebind with service account after user authentication") return false } return true } default: - log.Debug().Str("type", search.Type).Msg("Unknown user type for authentication") + utils.Log.App.Debug().Str("type", search.Type).Msg("Unknown user type for authentication") return false } - log.Warn().Str("username", search.Username).Msg("User authentication failed") + utils.Log.App.Warn().Str("username", search.Username).Msg("User authentication failed") return false } @@ -127,7 +126,7 @@ func (auth *AuthService) GetLocalUser(username string) config.User { } } - log.Warn().Str("username", username).Msg("Local user not found") + utils.Log.App.Warn().Str("username", username).Msg("Local user not found") return config.User{} } @@ -182,7 +181,7 @@ func (auth *AuthService) RecordLoginAttempt(identifier string, success bool) { if attempt.FailedAttempts >= auth.config.LoginMaxRetries { attempt.LockedUntil = time.Now().Add(time.Duration(auth.config.LoginTimeout) * time.Second) - log.Warn().Str("identifier", identifier).Int("timeout", auth.config.LoginTimeout).Msg("Account locked due to too many failed login attempts") + utils.Log.App.Warn().Str("identifier", identifier).Int("timeout", auth.config.LoginTimeout).Msg("Account locked due to too many failed login attempts") } } @@ -277,7 +276,7 @@ func (auth *AuthService) RefreshSessionCookie(c *gin.Context) error { } c.SetCookie(auth.config.SessionCookieName, cookie, int(newExpiry-currentTime), "/", fmt.Sprintf(".%s", auth.config.CookieDomain), auth.config.SecureCookie, true) - log.Trace().Str("username", session.Username).Msg("Session cookie refreshed") + utils.Log.App.Trace().Str("username", session.Username).Msg("Session cookie refreshed") return nil } @@ -322,7 +321,7 @@ func (auth *AuthService) GetSessionCookie(c *gin.Context) (config.SessionCookie, if currentTime-session.CreatedAt > int64(auth.config.SessionMaxLifetime) { err = auth.queries.DeleteSession(c, cookie) if err != nil { - log.Error().Err(err).Msg("Failed to delete session exceeding max lifetime") + utils.Log.App.Error().Err(err).Msg("Failed to delete session exceeding max lifetime") } return config.SessionCookie{}, fmt.Errorf("session expired due to max lifetime exceeded") } @@ -331,7 +330,7 @@ func (auth *AuthService) GetSessionCookie(c *gin.Context) (config.SessionCookie, if currentTime > session.Expiry { err = auth.queries.DeleteSession(c, cookie) if err != nil { - log.Error().Err(err).Msg("Failed to delete expired session") + utils.Log.App.Error().Err(err).Msg("Failed to delete expired session") } return config.SessionCookie{}, fmt.Errorf("session expired") } @@ -355,18 +354,18 @@ func (auth *AuthService) UserAuthConfigured() bool { func (auth *AuthService) IsUserAllowed(c *gin.Context, context config.UserContext, acls config.App) bool { if context.OAuth { - log.Debug().Msg("Checking OAuth whitelist") + utils.Log.App.Debug().Msg("Checking OAuth whitelist") return utils.CheckFilter(acls.OAuth.Whitelist, context.Email) } if acls.Users.Block != "" { - log.Debug().Msg("Checking blocked users") + utils.Log.App.Debug().Msg("Checking blocked users") if utils.CheckFilter(acls.Users.Block, context.Username) { return false } } - log.Debug().Msg("Checking users") + utils.Log.App.Debug().Msg("Checking users") return utils.CheckFilter(acls.Users.Allow, context.Username) } @@ -377,19 +376,19 @@ func (auth *AuthService) IsInOAuthGroup(c *gin.Context, context config.UserConte for id := range config.OverrideProviders { if context.Provider == id { - log.Info().Str("provider", id).Msg("OAuth groups not supported for this provider") + utils.Log.App.Info().Str("provider", id).Msg("OAuth groups not supported for this provider") return true } } for userGroup := range strings.SplitSeq(context.OAuthGroups, ",") { if utils.CheckFilter(requiredGroups, strings.TrimSpace(userGroup)) { - log.Trace().Str("group", userGroup).Str("required", requiredGroups).Msg("User group matched") + utils.Log.App.Trace().Str("group", userGroup).Str("required", requiredGroups).Msg("User group matched") return true } } - log.Debug().Msg("No groups matched") + utils.Log.App.Debug().Msg("No groups matched") return false } @@ -426,7 +425,7 @@ func (auth *AuthService) IsAuthEnabled(uri string, path config.AppPath) (bool, e func (auth *AuthService) GetBasicAuth(c *gin.Context) *config.User { username, password, ok := c.Request.BasicAuth() if !ok { - log.Debug().Msg("No basic auth provided") + utils.Log.App.Debug().Msg("No basic auth provided") return nil } return &config.User{ @@ -443,11 +442,11 @@ func (auth *AuthService) CheckIP(acls config.AppIP, ip string) bool { for _, blocked := range blockedIps { res, err := utils.FilterIP(blocked, ip) if err != nil { - log.Warn().Err(err).Str("item", blocked).Msg("Invalid IP/CIDR in block list") + utils.Log.App.Warn().Err(err).Str("item", blocked).Msg("Invalid IP/CIDR in block list") continue } if res { - log.Debug().Str("ip", ip).Str("item", blocked).Msg("IP is in blocked list, denying access") + utils.Log.App.Debug().Str("ip", ip).Str("item", blocked).Msg("IP is in blocked list, denying access") return false } } @@ -455,21 +454,21 @@ func (auth *AuthService) CheckIP(acls config.AppIP, ip string) bool { for _, allowed := range allowedIPs { res, err := utils.FilterIP(allowed, ip) if err != nil { - log.Warn().Err(err).Str("item", allowed).Msg("Invalid IP/CIDR in allow list") + utils.Log.App.Warn().Err(err).Str("item", allowed).Msg("Invalid IP/CIDR in allow list") continue } if res { - log.Debug().Str("ip", ip).Str("item", allowed).Msg("IP is in allowed list, allowing access") + utils.Log.App.Debug().Str("ip", ip).Str("item", allowed).Msg("IP is in allowed list, allowing access") return true } } if len(allowedIPs) > 0 { - log.Debug().Str("ip", ip).Msg("IP not in allow list, denying access") + utils.Log.App.Debug().Str("ip", ip).Msg("IP not in allow list, denying access") return false } - log.Debug().Str("ip", ip).Msg("IP not in allow or block list, allowing by default") + utils.Log.App.Debug().Str("ip", ip).Msg("IP not in allow or block list, allowing by default") return true } @@ -477,15 +476,15 @@ func (auth *AuthService) IsBypassedIP(acls config.AppIP, ip string) bool { for _, bypassed := range acls.Bypass { res, err := utils.FilterIP(bypassed, ip) if err != nil { - log.Warn().Err(err).Str("item", bypassed).Msg("Invalid IP/CIDR in bypass list") + utils.Log.App.Warn().Err(err).Str("item", bypassed).Msg("Invalid IP/CIDR in bypass list") continue } if res { - log.Debug().Str("ip", ip).Str("item", bypassed).Msg("IP is in bypass list, allowing access") + utils.Log.App.Debug().Str("ip", ip).Str("item", bypassed).Msg("IP is in bypass list, allowing access") return true } } - log.Debug().Str("ip", ip).Msg("IP not in bypass list, continuing with authentication") + utils.Log.App.Debug().Str("ip", ip).Msg("IP not in bypass list, continuing with authentication") return false } diff --git a/internal/service/docker_service.go b/internal/service/docker_service.go index a0693b27..9063fa6a 100644 --- a/internal/service/docker_service.go +++ b/internal/service/docker_service.go @@ -5,11 +5,11 @@ import ( "strings" "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/steveiliop56/tinyauth/internal/utils/decoders" container "github.com/docker/docker/api/types/container" "github.com/docker/docker/client" - "github.com/rs/zerolog/log" ) type DockerService struct { @@ -37,7 +37,7 @@ func (docker *DockerService) Init() error { _, err = docker.client.Ping(docker.context) if err != nil { - log.Debug().Err(err).Msg("Docker not connected") + utils.Log.App.Debug().Err(err).Msg("Docker not connected") docker.isConnected = false docker.client = nil docker.context = nil @@ -45,7 +45,7 @@ func (docker *DockerService) Init() error { } docker.isConnected = true - log.Debug().Msg("Docker connected") + utils.Log.App.Debug().Msg("Docker connected") return nil } @@ -68,7 +68,7 @@ func (docker *DockerService) inspectContainer(containerId string) (container.Ins func (docker *DockerService) GetLabels(appDomain string) (config.App, error) { if !docker.isConnected { - log.Debug().Msg("Docker not connected, returning empty labels") + utils.Log.App.Debug().Msg("Docker not connected, returning empty labels") return config.App{}, nil } @@ -90,17 +90,17 @@ func (docker *DockerService) GetLabels(appDomain string) (config.App, error) { for appName, appLabels := range labels.Apps { if appLabels.Config.Domain == appDomain { - log.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by domain") + utils.Log.App.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by domain") return appLabels, nil } if strings.SplitN(appDomain, ".", 2)[0] == appName { - log.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by app name") + utils.Log.App.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by app name") return appLabels, nil } } } - log.Debug().Msg("No matching container found, returning empty labels") + utils.Log.App.Debug().Msg("No matching container found, returning empty labels") return config.App{}, nil } diff --git a/internal/service/generic_oauth_service.go b/internal/service/generic_oauth_service.go index ac3252c8..4c1f07f7 100644 --- a/internal/service/generic_oauth_service.go +++ b/internal/service/generic_oauth_service.go @@ -12,8 +12,8 @@ import ( "time" "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils" - "github.com/rs/zerolog/log" "golang.org/x/oauth2" ) @@ -117,7 +117,7 @@ func (generic *GenericOAuthService) Userinfo() (config.Claims, error) { return user, err } - log.Trace().Str("body", string(body)).Msg("Userinfo response body") + utils.Log.App.Trace().Str("body", string(body)).Msg("Userinfo response body") err = json.Unmarshal(body, &user) if err != nil { diff --git a/internal/service/ldap_service.go b/internal/service/ldap_service.go index b64c1dfd..16eada1c 100644 --- a/internal/service/ldap_service.go +++ b/internal/service/ldap_service.go @@ -9,7 +9,7 @@ import ( "github.com/cenkalti/backoff/v5" ldapgo "github.com/go-ldap/ldap/v3" - "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/utils" ) type LdapServiceConfig struct { @@ -44,7 +44,7 @@ func (ldap *LdapService) Init() error { return fmt.Errorf("failed to initialize LDAP with mTLS authentication: %w", err) } ldap.cert = &cert - log.Info().Msg("Using LDAP with mTLS authentication") + utils.Log.App.Info().Msg("Using LDAP with mTLS authentication") // TODO: Add optional extra CA certificates, instead of `InsecureSkipVerify` /* @@ -66,12 +66,12 @@ func (ldap *LdapService) Init() error { for range time.Tick(time.Duration(5) * time.Minute) { err := ldap.heartbeat() if err != nil { - log.Error().Err(err).Msg("LDAP connection heartbeat failed") + utils.Log.App.Error().Err(err).Msg("LDAP connection heartbeat failed") if reconnectErr := ldap.reconnect(); reconnectErr != nil { - log.Error().Err(reconnectErr).Msg("Failed to reconnect to LDAP server") + utils.Log.App.Error().Err(reconnectErr).Msg("Failed to reconnect to LDAP server") continue } - log.Info().Msg("Successfully reconnected to LDAP server") + utils.Log.App.Info().Msg("Successfully reconnected to LDAP server") } } }() @@ -169,7 +169,7 @@ func (ldap *LdapService) Bind(userDN string, password string) error { } func (ldap *LdapService) heartbeat() error { - log.Debug().Msg("Performing LDAP connection heartbeat") + utils.Log.App.Debug().Msg("Performing LDAP connection heartbeat") searchRequest := ldapgo.NewSearchRequest( "", @@ -191,7 +191,7 @@ func (ldap *LdapService) heartbeat() error { } func (ldap *LdapService) reconnect() error { - log.Info().Msg("Reconnecting to LDAP server") + utils.Log.App.Info().Msg("Reconnecting to LDAP server") exp := backoff.NewExponentialBackOff() exp.InitialInterval = 500 * time.Millisecond diff --git a/internal/service/oauth_broker_service.go b/internal/service/oauth_broker_service.go index 2c7d4cf3..ac19c7b0 100644 --- a/internal/service/oauth_broker_service.go +++ b/internal/service/oauth_broker_service.go @@ -4,8 +4,8 @@ import ( "errors" "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils" - "github.com/rs/zerolog/log" "golang.org/x/exp/slices" ) @@ -49,10 +49,10 @@ func (broker *OAuthBrokerService) Init() error { for name, service := range broker.services { err := service.Init() if err != nil { - log.Error().Err(err).Msgf("Failed to initialize OAuth service: %T", name) + utils.Log.App.Error().Err(err).Msgf("Failed to initialize OAuth service: %T", name) return err } - log.Info().Str("service", name).Msg("Initialized OAuth service") + utils.Log.App.Info().Str("service", name).Msg("Initialized OAuth service") } return nil diff --git a/internal/utils/log_utils.go b/internal/utils/log_utils.go new file mode 100644 index 00000000..2ce701be --- /dev/null +++ b/internal/utils/log_utils.go @@ -0,0 +1,96 @@ +package utils + +import ( + "fmt" + "os" + "slices" + "strings" + "time" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +type Loggers struct { + Audit zerolog.Logger + HTTP zerolog.Logger + App zerolog.Logger +} + +// utils.Log.Access, utils.log.HTTP... +var Log *Loggers + +type LoggerConfig struct { + Level string + Json bool + Outputs map[string]LoggerOutputConfig +} + +type LoggerOutputConfig struct { + Enabled bool + Level string +} + +// InitLogger initializes all loggers with the provided configuration +func InitLogger(cfg *LoggerConfig) error { + if cfg == nil { + return fmt.Errorf("logger config cannot be nil") + } + + zerolog.SetGlobalLevel(parseLogLevel(cfg.Level)) + zerolog.TimeFieldFormat = time.RFC3339 + + baseLogger := log.With().Timestamp().Caller().Logger() + + if !cfg.Json { + baseLogger = baseLogger.Output(zerolog.ConsoleWriter{ + Out: os.Stderr, + TimeFormat: time.RFC3339, + }) + } + + // set as global logger + log.Logger = baseLogger + + // create sub-loggers + Log = &Loggers{ + Audit: createLogger("audit", cfg, baseLogger), + HTTP: createLogger("http", cfg, baseLogger), + App: createLogger("app", cfg, baseLogger), + } + + return nil +} + +func createLogger(loggerType string, cfg *LoggerConfig, baseLogger zerolog.Logger) zerolog.Logger { + logCfg, exists := cfg.Outputs[loggerType] + if !exists { + logCfg = LoggerOutputConfig{ + Enabled: slices.Contains([]string{"http", "app"}, loggerType), + Level: "", + } + } + + if !logCfg.Enabled { + return zerolog.Nop() + } + + logger := baseLogger.With().Str("component", loggerType).Logger() + if logCfg.Level != "" { // if log level is overriden + logger = logger.Level(parseLogLevel(logCfg.Level)) + } + return logger +} + +// parseLogLevel parses a log level string +func parseLogLevel(level string) zerolog.Level { + if level == "" { + return zerolog.InfoLevel + } + parsedLevel, err := zerolog.ParseLevel(strings.ToLower(level)) + if err != nil { + log.Warn().Err(err).Str("level", level).Msg("Invalid log level, defaulting to info") + parsedLevel = zerolog.InfoLevel + } + return parsedLevel +} From 4f0b698ca4511673e2cdd2ca8aaae624e2097280 Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 17:38:46 -0500 Subject: [PATCH 2/7] refactor: update logging implementation to use new logger structure --- cmd/tinyauth/create.go | 5 +- cmd/tinyauth/generate.go | 5 +- cmd/tinyauth/healthcheck.go | 5 +- cmd/tinyauth/tinyauth.go | 34 +++---- cmd/tinyauth/verify.go | 5 +- internal/config/config.go | 18 ++-- .../controller/context_controller_test.go | 3 + internal/controller/proxy_controller_test.go | 3 + internal/controller/user_controller_test.go | 3 + internal/utils/log_utils.go | 82 +++++++--------- internal/utils/log_utils_test.go | 96 +++++++++++++++++++ 11 files changed, 171 insertions(+), 88 deletions(-) create mode 100644 internal/utils/log_utils_test.go diff --git a/cmd/tinyauth/create.go b/cmd/tinyauth/create.go index 0319f5ad..dbf79669 100644 --- a/cmd/tinyauth/create.go +++ b/cmd/tinyauth/create.go @@ -40,10 +40,7 @@ func createUserCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - utils.InitLogger(&utils.LoggerConfig{ - Level: "info", - Json: false, - }) + utils.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( diff --git a/cmd/tinyauth/generate.go b/cmd/tinyauth/generate.go index 3fa4552b..e0e83337 100644 --- a/cmd/tinyauth/generate.go +++ b/cmd/tinyauth/generate.go @@ -39,10 +39,7 @@ func generateTotpCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - utils.InitLogger(&utils.LoggerConfig{ - Level: "info", - Json: false, - }) + utils.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( diff --git a/cmd/tinyauth/healthcheck.go b/cmd/tinyauth/healthcheck.go index 184d5294..7774346d 100644 --- a/cmd/tinyauth/healthcheck.go +++ b/cmd/tinyauth/healthcheck.go @@ -26,10 +26,7 @@ func healthcheckCmd() *cli.Command { Resources: nil, AllowArg: true, Run: func(args []string) error { - utils.InitLogger(&utils.LoggerConfig{ - Level: "info", - Json: false, - }) + utils.NewSimpleLogger().Init() appUrl := os.Getenv("TINYAUTH_APPURL") diff --git a/cmd/tinyauth/tinyauth.go b/cmd/tinyauth/tinyauth.go index 0f62957a..c52d4cfa 100644 --- a/cmd/tinyauth/tinyauth.go +++ b/cmd/tinyauth/tinyauth.go @@ -38,6 +38,20 @@ func NewTinyauthCmdConfiguration() *config.Config { Log: config.LogConfig{ Level: "info", Json: false, + Streams: config.LogStreams{ + HTTP: config.LogStreamConfig{ + Enabled: true, + Level: "", + }, + App: config.LogStreamConfig{ + Enabled: true, + Level: "", + }, + Audit: config.LogStreamConfig{ + Enabled: false, + Level: "", + }, + }, }, Experimental: config.ExperimentalConfig{ ConfigFile: "", @@ -102,28 +116,14 @@ func main() { } func runCmd(cfg config.Config) error { - outputs := make(map[string]utils.LoggerOutputConfig) - for name, out := range cfg.Log.Outputs { - outputs[name] = utils.LoggerOutputConfig{ - Enabled: out.Enabled, - Level: out.Level, - } - } - - err := utils.InitLogger(&utils.LoggerConfig{ - Level: cfg.Log.Level, - Json: cfg.Log.Json, - Outputs: outputs, - }) - if err != nil { - log.Error().Err(err).Msg("Failed to initialize logger") - } + logger := utils.NewLogger(cfg.Log) + logger.Init() utils.Log.App.Info().Str("version", config.Version).Msg("Starting tinyauth") app := bootstrap.NewBootstrapApp(cfg) - err = app.Setup() + err := app.Setup() if err != nil { return fmt.Errorf("failed to bootstrap app: %w", err) diff --git a/cmd/tinyauth/verify.go b/cmd/tinyauth/verify.go index 34510dc1..3d95e2b2 100644 --- a/cmd/tinyauth/verify.go +++ b/cmd/tinyauth/verify.go @@ -43,10 +43,7 @@ func verifyUserCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - utils.InitLogger(&utils.LoggerConfig{ - Level: "info", - Json: false, - }) + utils.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( diff --git a/internal/config/config.go b/internal/config/config.go index 9c3b0aaf..62e06c91 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -78,14 +78,20 @@ type LdapConfig struct { } type LogConfig struct { - Level string `description:"Log level (trace, debug, info, warn, error)." yaml:"level"` - Json bool `description:"Enable JSON formatted logs." yaml:"json"` - Outputs map[string]LogOutputConfig `description:"Configuration for specific log outputs." yaml:"outputs"` + Level string `description:"Log level (trace, debug, info, warn, error)." yaml:"level"` + Json bool `description:"Enable JSON formatted logs." yaml:"json"` + Streams LogStreams `description:"Configuration for specific log streams." yaml:"streams"` } -type LogOutputConfig struct { - Enabled bool `description:"Enable this log output." yaml:"enabled"` - Level string `description:"Log level for this output (trace, debug, info, warn, error)." yaml:"level"` +type LogStreams struct { + HTTP LogStreamConfig `description:"HTTP request logging." yaml:"http"` + App LogStreamConfig `description:"Application logging." yaml:"app"` + Audit LogStreamConfig `description:"Audit logging." yaml:"audit"` +} + +type LogStreamConfig struct { + Enabled bool `description:"Enable this log stream." yaml:"enabled"` + Level string `description:"Log level for this stream. Use global if empty." yaml:"level"` } type ExperimentalConfig struct { diff --git a/internal/controller/context_controller_test.go b/internal/controller/context_controller_test.go index 7dee2c8c..7b041279 100644 --- a/internal/controller/context_controller_test.go +++ b/internal/controller/context_controller_test.go @@ -7,6 +7,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/controller" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/gin-gonic/gin" "gotest.tools/v3/assert" @@ -48,6 +49,8 @@ var userContext = config.UserContext{ } func setupContextController(middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder) { + utils.NewSimpleLogger().Init() + // Setup gin.SetMode(gin.TestMode) router := gin.Default() diff --git a/internal/controller/proxy_controller_test.go b/internal/controller/proxy_controller_test.go index 57711fca..519981f4 100644 --- a/internal/controller/proxy_controller_test.go +++ b/internal/controller/proxy_controller_test.go @@ -9,12 +9,15 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/service" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/gin-gonic/gin" "gotest.tools/v3/assert" ) func setupProxyController(t *testing.T, middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder, *service.AuthService) { + utils.NewSimpleLogger().Init() + // Setup gin.SetMode(gin.TestMode) router := gin.Default() diff --git a/internal/controller/user_controller_test.go b/internal/controller/user_controller_test.go index 99768c70..fc0e5e80 100644 --- a/internal/controller/user_controller_test.go +++ b/internal/controller/user_controller_test.go @@ -13,6 +13,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/service" + "github.com/steveiliop56/tinyauth/internal/utils" "github.com/gin-gonic/gin" "github.com/pquerna/otp/totp" @@ -23,6 +24,8 @@ var cookieValue string var totpSecret = "6WFZXPEZRK5MZHHYAFW4DAOUYQMCASBJ" func setupUserController(t *testing.T, middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder) { + utils.NewSimpleLogger().Init() + // Setup gin.SetMode(gin.TestMode) router := gin.Default() diff --git a/internal/utils/log_utils.go b/internal/utils/log_utils.go index 2ce701be..1c651326 100644 --- a/internal/utils/log_utils.go +++ b/internal/utils/log_utils.go @@ -1,46 +1,29 @@ package utils import ( - "fmt" "os" - "slices" "strings" "time" "github.com/rs/zerolog" "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/config" ) -type Loggers struct { +type Logger struct { Audit zerolog.Logger HTTP zerolog.Logger App zerolog.Logger } -// utils.Log.Access, utils.log.HTTP... -var Log *Loggers +var Log *Logger -type LoggerConfig struct { - Level string - Json bool - Outputs map[string]LoggerOutputConfig -} - -type LoggerOutputConfig struct { - Enabled bool - Level string -} - -// InitLogger initializes all loggers with the provided configuration -func InitLogger(cfg *LoggerConfig) error { - if cfg == nil { - return fmt.Errorf("logger config cannot be nil") - } - - zerolog.SetGlobalLevel(parseLogLevel(cfg.Level)) - zerolog.TimeFieldFormat = time.RFC3339 - - baseLogger := log.With().Timestamp().Caller().Logger() +func NewLogger(cfg config.LogConfig) *Logger { + baseLogger := log.With(). + Timestamp(). + Caller(). + Logger(). + Level(parseLogLevel(cfg.Level)) if !cfg.Json { baseLogger = baseLogger.Output(zerolog.ConsoleWriter{ @@ -49,40 +32,41 @@ func InitLogger(cfg *LoggerConfig) error { }) } - // set as global logger - log.Logger = baseLogger - - // create sub-loggers - Log = &Loggers{ - Audit: createLogger("audit", cfg, baseLogger), - HTTP: createLogger("http", cfg, baseLogger), - App: createLogger("app", cfg, baseLogger), + return &Logger{ + Audit: createLogger("audit", cfg.Streams.Audit, baseLogger), + HTTP: createLogger("http", cfg.Streams.HTTP, baseLogger), + App: createLogger("app", cfg.Streams.App, baseLogger), } +} - return nil +func NewSimpleLogger() *Logger { + return NewLogger(config.LogConfig{ + Level: "info", + Json: false, + Streams: config.LogStreams{ + HTTP: config.LogStreamConfig{Enabled: true}, + App: config.LogStreamConfig{Enabled: true}, + Audit: config.LogStreamConfig{Enabled: false}, + }, + }) } -func createLogger(loggerType string, cfg *LoggerConfig, baseLogger zerolog.Logger) zerolog.Logger { - logCfg, exists := cfg.Outputs[loggerType] - if !exists { - logCfg = LoggerOutputConfig{ - Enabled: slices.Contains([]string{"http", "app"}, loggerType), - Level: "", - } - } +func (l *Logger) Init() { + Log = l +} - if !logCfg.Enabled { +func createLogger(component string, streamCfg config.LogStreamConfig, baseLogger zerolog.Logger) zerolog.Logger { + if !streamCfg.Enabled { return zerolog.Nop() } - - logger := baseLogger.With().Str("component", loggerType).Logger() - if logCfg.Level != "" { // if log level is overriden - logger = logger.Level(parseLogLevel(logCfg.Level)) + logger := baseLogger.With().Str("log_stream", component).Logger() + // override level if specified, otherwise use base level + if streamCfg.Level != "" { + logger = logger.Level(parseLogLevel(streamCfg.Level)) } return logger } -// parseLogLevel parses a log level string func parseLogLevel(level string) zerolog.Level { if level == "" { return zerolog.InfoLevel diff --git a/internal/utils/log_utils_test.go b/internal/utils/log_utils_test.go new file mode 100644 index 00000000..e98b1cfb --- /dev/null +++ b/internal/utils/log_utils_test.go @@ -0,0 +1,96 @@ +package utils_test + +import ( + "bytes" + "encoding/json" + "testing" + + "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils" + + "github.com/rs/zerolog" + "gotest.tools/v3/assert" +) + +func TestNewLogger(t *testing.T) { + cfg := config.LogConfig{ + Level: "debug", + Json: true, + Streams: config.LogStreams{ + HTTP: config.LogStreamConfig{Enabled: true, Level: "info"}, + App: config.LogStreamConfig{Enabled: true, Level: ""}, + Audit: config.LogStreamConfig{Enabled: false, Level: ""}, + }, + } + + logger := utils.NewLogger(cfg) + + assert.Assert(t, logger != nil) + assert.Assert(t, utils.Log == nil) + assert.Assert(t, logger.HTTP.GetLevel() == zerolog.InfoLevel) + assert.Assert(t, logger.App.GetLevel() == zerolog.DebugLevel) + assert.Assert(t, logger.Audit.GetLevel() == zerolog.Disabled) +} + +func TestNewSimpleLogger(t *testing.T) { + logger := utils.NewSimpleLogger() + + assert.Assert(t, logger != nil) + assert.Assert(t, logger.HTTP.GetLevel() == zerolog.InfoLevel) + assert.Assert(t, logger.App.GetLevel() == zerolog.InfoLevel) + assert.Assert(t, logger.Audit.GetLevel() == zerolog.Disabled) +} + +func TestLoggerInit(t *testing.T) { + logger := utils.NewSimpleLogger() + logger.Init() + + assert.Assert(t, utils.Log != nil) + assert.Assert(t, utils.Log.App.GetLevel() != zerolog.Disabled) +} + +func TestLoggerWithDisabledStreams(t *testing.T) { + cfg := config.LogConfig{ + Level: "info", + Json: false, + Streams: config.LogStreams{ + HTTP: config.LogStreamConfig{Enabled: false}, + App: config.LogStreamConfig{Enabled: false}, + Audit: config.LogStreamConfig{Enabled: false}, + }, + } + + logger := utils.NewLogger(cfg) + + assert.Assert(t, logger.HTTP.GetLevel() == zerolog.Disabled) + assert.Assert(t, logger.App.GetLevel() == zerolog.Disabled) + assert.Assert(t, logger.Audit.GetLevel() == zerolog.Disabled) +} + +func TestLogStreamField(t *testing.T) { + var buf bytes.Buffer + + cfg := config.LogConfig{ + Level: "info", + Json: true, + Streams: config.LogStreams{ + HTTP: config.LogStreamConfig{Enabled: true}, + App: config.LogStreamConfig{Enabled: true}, + Audit: config.LogStreamConfig{Enabled: true}, + }, + } + + logger := utils.NewLogger(cfg) + + // Override output for HTTP logger to capture output + logger.HTTP = logger.HTTP.Output(&buf) + + logger.HTTP.Info().Msg("test message") + + var logEntry map[string]interface{} + err := json.Unmarshal(buf.Bytes(), &logEntry) + assert.NilError(t, err) + + assert.Equal(t, "http", logEntry["log_stream"]) + assert.Equal(t, "test message", logEntry["message"]) +} From 144eed5065e186f8eac9952a1d45606b1d5512b5 Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 19:49:57 -0500 Subject: [PATCH 3/7] Refactor logging to use tlog package - Replaced instances of utils logging with tlog in various controllers, services, and middleware. - Introduced audit logging for login success, login failure, and logout events. - Created tlog package with structured logging capabilities using zerolog. - Added tests for the new tlog logger functionality. --- cmd/tinyauth/create.go | 8 +-- cmd/tinyauth/generate.go | 9 ++-- cmd/tinyauth/healthcheck.go | 8 +-- cmd/tinyauth/tinyauth.go | 6 +-- cmd/tinyauth/verify.go | 9 ++-- internal/bootstrap/app_bootstrap.go | 45 ++++++++-------- internal/bootstrap/service_bootstrap.go | 4 +- internal/controller/context_controller.go | 7 +-- .../controller/context_controller_test.go | 4 +- internal/controller/oauth_controller.go | 43 ++++++++------- internal/controller/proxy_controller.go | 41 +++++++------- internal/controller/proxy_controller_test.go | 4 +- internal/controller/user_controller.go | 52 +++++++++++------- internal/controller/user_controller_test.go | 4 +- internal/middleware/context_middleware.go | 21 ++++---- internal/middleware/zerolog_middleware.go | 4 +- internal/service/access_controls_service.go | 10 ++-- internal/service/auth_service.go | 53 ++++++++++--------- internal/service/docker_service.go | 14 ++--- internal/service/generic_oauth_service.go | 4 +- internal/service/ldap_service.go | 14 ++--- internal/service/oauth_broker_service.go | 6 +-- internal/utils/tlog/log_audit.go | 33 ++++++++++++ .../{log_utils.go => tlog/log_wrapper.go} | 18 ++++--- .../log_wrapper_test.go} | 19 +++---- 25 files changed, 249 insertions(+), 191 deletions(-) create mode 100644 internal/utils/tlog/log_audit.go rename internal/utils/{log_utils.go => tlog/log_wrapper.go} (85%) rename internal/utils/{log_utils_test.go => tlog/log_wrapper_test.go} (85%) diff --git a/cmd/tinyauth/create.go b/cmd/tinyauth/create.go index dbf79669..8e7139b1 100644 --- a/cmd/tinyauth/create.go +++ b/cmd/tinyauth/create.go @@ -6,7 +6,7 @@ import ( "strings" "github.com/charmbracelet/huh" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/traefik/paerser/cli" "golang.org/x/crypto/bcrypt" ) @@ -40,7 +40,7 @@ func createUserCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( @@ -74,7 +74,7 @@ func createUserCmd() *cli.Command { return errors.New("username and password cannot be empty") } - utils.Log.App.Info().Str("username", tCfg.Username).Msg("Creating user") + tlog.App.Info().Str("username", tCfg.Username).Msg("Creating user") passwd, err := bcrypt.GenerateFromPassword([]byte(tCfg.Password), bcrypt.DefaultCost) if err != nil { @@ -87,7 +87,7 @@ func createUserCmd() *cli.Command { passwdStr = strings.ReplaceAll(passwdStr, "$", "$$") } - utils.Log.App.Info().Str("user", fmt.Sprintf("%s:%s", tCfg.Username, passwdStr)).Msg("User created") + tlog.App.Info().Str("user", fmt.Sprintf("%s:%s", tCfg.Username, passwdStr)).Msg("User created") return nil }, diff --git a/cmd/tinyauth/generate.go b/cmd/tinyauth/generate.go index e0e83337..0a632619 100644 --- a/cmd/tinyauth/generate.go +++ b/cmd/tinyauth/generate.go @@ -7,6 +7,7 @@ import ( "strings" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/charmbracelet/huh" "github.com/mdp/qrterminal/v3" @@ -39,7 +40,7 @@ func generateTotpCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( @@ -88,9 +89,9 @@ func generateTotpCmd() *cli.Command { secret := key.Secret() - utils.Log.App.Info().Str("secret", secret).Msg("Generated TOTP secret") + tlog.App.Info().Str("secret", secret).Msg("Generated TOTP secret") - utils.Log.App.Info().Msg("Generated QR code") + tlog.App.Info().Msg("Generated QR code") config := qrterminal.Config{ Level: qrterminal.L, @@ -109,7 +110,7 @@ func generateTotpCmd() *cli.Command { user.Password = strings.ReplaceAll(user.Password, "$", "$$") } - utils.Log.App.Info().Str("user", fmt.Sprintf("%s:%s:%s", user.Username, user.Password, user.TotpSecret)).Msg("Add the totp secret to your authenticator app then use the verify command to ensure everything is working correctly.") + tlog.App.Info().Str("user", fmt.Sprintf("%s:%s:%s", user.Username, user.Password, user.TotpSecret)).Msg("Add the totp secret to your authenticator app then use the verify command to ensure everything is working correctly.") return nil }, diff --git a/cmd/tinyauth/healthcheck.go b/cmd/tinyauth/healthcheck.go index 7774346d..ca224e38 100644 --- a/cmd/tinyauth/healthcheck.go +++ b/cmd/tinyauth/healthcheck.go @@ -9,7 +9,7 @@ import ( "os" "time" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/traefik/paerser/cli" ) @@ -26,7 +26,7 @@ func healthcheckCmd() *cli.Command { Resources: nil, AllowArg: true, Run: func(args []string) error { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() appUrl := os.Getenv("TINYAUTH_APPURL") @@ -38,7 +38,7 @@ func healthcheckCmd() *cli.Command { return errors.New("TINYAUTH_APPURL is not set and no argument was provided") } - utils.Log.App.Info().Str("app_url", appUrl).Msg("Performing health check") + tlog.App.Info().Str("app_url", appUrl).Msg("Performing health check") client := http.Client{ Timeout: 30 * time.Second, @@ -76,7 +76,7 @@ func healthcheckCmd() *cli.Command { return fmt.Errorf("failed to decode response: %w", err) } - utils.Log.App.Info().Interface("response", healthResp).Msg("Tinyauth is healthy") + tlog.App.Info().Interface("response", healthResp).Msg("Tinyauth is healthy") return nil }, diff --git a/cmd/tinyauth/tinyauth.go b/cmd/tinyauth/tinyauth.go index c52d4cfa..c1e652dc 100644 --- a/cmd/tinyauth/tinyauth.go +++ b/cmd/tinyauth/tinyauth.go @@ -5,8 +5,8 @@ import ( "github.com/steveiliop56/tinyauth/internal/bootstrap" "github.com/steveiliop56/tinyauth/internal/config" - "github.com/steveiliop56/tinyauth/internal/utils" "github.com/steveiliop56/tinyauth/internal/utils/loaders" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/rs/zerolog/log" "github.com/traefik/paerser/cli" @@ -116,10 +116,10 @@ func main() { } func runCmd(cfg config.Config) error { - logger := utils.NewLogger(cfg.Log) + logger := tlog.NewLogger(cfg.Log) logger.Init() - utils.Log.App.Info().Str("version", config.Version).Msg("Starting tinyauth") + tlog.App.Info().Str("version", config.Version).Msg("Starting tinyauth") app := bootstrap.NewBootstrapApp(cfg) diff --git a/cmd/tinyauth/verify.go b/cmd/tinyauth/verify.go index 3d95e2b2..aa98cbd1 100644 --- a/cmd/tinyauth/verify.go +++ b/cmd/tinyauth/verify.go @@ -5,6 +5,7 @@ import ( "fmt" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/charmbracelet/huh" "github.com/pquerna/otp/totp" @@ -43,7 +44,7 @@ func verifyUserCmd() *cli.Command { Configuration: tCfg, Resources: loaders, Run: func(_ []string) error { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( @@ -97,9 +98,9 @@ func verifyUserCmd() *cli.Command { if user.TotpSecret == "" { if tCfg.Totp != "" { - utils.Log.App.Warn().Msg("User does not have TOTP secret") + tlog.App.Warn().Msg("User does not have TOTP secret") } - utils.Log.App.Info().Msg("User verified") + tlog.App.Info().Msg("User verified") return nil } @@ -109,7 +110,7 @@ func verifyUserCmd() *cli.Command { return fmt.Errorf("TOTP code incorrect") } - utils.Log.App.Info().Msg("User verified") + tlog.App.Info().Msg("User verified") return nil }, diff --git a/internal/bootstrap/app_bootstrap.go b/internal/bootstrap/app_bootstrap.go index 22c02f36..20355fc4 100644 --- a/internal/bootstrap/app_bootstrap.go +++ b/internal/bootstrap/app_bootstrap.go @@ -16,6 +16,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" ) type BootstrapApp struct { @@ -101,13 +102,13 @@ func (app *BootstrapApp) Setup() error { app.context.redirectCookieName = fmt.Sprintf("%s-%s", config.RedirectCookieName, cookieId) // Dumps - utils.Log.App.Trace().Interface("config", app.config).Msg("Config dump") - utils.Log.App.Trace().Interface("users", app.context.users).Msg("Users dump") - utils.Log.App.Trace().Interface("oauthProviders", app.context.oauthProviders).Msg("OAuth providers dump") - utils.Log.App.Trace().Str("cookieDomain", app.context.cookieDomain).Msg("Cookie domain") - utils.Log.App.Trace().Str("sessionCookieName", app.context.sessionCookieName).Msg("Session cookie name") - utils.Log.App.Trace().Str("csrfCookieName", app.context.csrfCookieName).Msg("CSRF cookie name") - utils.Log.App.Trace().Str("redirectCookieName", app.context.redirectCookieName).Msg("Redirect cookie name") + tlog.App.Trace().Interface("config", app.config).Msg("Config dump") + tlog.App.Trace().Interface("users", app.context.users).Msg("Users dump") + tlog.App.Trace().Interface("oauthProviders", app.context.oauthProviders).Msg("OAuth providers dump") + tlog.App.Trace().Str("cookieDomain", app.context.cookieDomain).Msg("Cookie domain") + tlog.App.Trace().Str("sessionCookieName", app.context.sessionCookieName).Msg("Session cookie name") + tlog.App.Trace().Str("csrfCookieName", app.context.csrfCookieName).Msg("CSRF cookie name") + tlog.App.Trace().Str("redirectCookieName", app.context.redirectCookieName).Msg("Redirect cookie name") // Database db, err := app.SetupDatabase(app.config.DatabasePath) @@ -151,7 +152,7 @@ func (app *BootstrapApp) Setup() error { }) } - utils.Log.App.Debug().Interface("providers", configuredProviders).Msg("Authentication providers") + tlog.App.Debug().Interface("providers", configuredProviders).Msg("Authentication providers") if len(configuredProviders) == 0 { return fmt.Errorf("no authentication providers configured") @@ -167,28 +168,28 @@ func (app *BootstrapApp) Setup() error { } // Start db cleanup routine - utils.Log.App.Debug().Msg("Starting database cleanup routine") + tlog.App.Debug().Msg("Starting database cleanup routine") go app.dbCleanup(queries) // If analytics are not disabled, start heartbeat if !app.config.DisableAnalytics { - utils.Log.App.Debug().Msg("Starting heartbeat routine") + tlog.App.Debug().Msg("Starting heartbeat routine") go app.heartbeat() } // If we have an socket path, bind to it if app.config.Server.SocketPath != "" { if _, err := os.Stat(app.config.Server.SocketPath); err == nil { - utils.Log.App.Info().Msgf("Removing existing socket file %s", app.config.Server.SocketPath) + tlog.App.Info().Msgf("Removing existing socket file %s", app.config.Server.SocketPath) err := os.Remove(app.config.Server.SocketPath) if err != nil { return fmt.Errorf("failed to remove existing socket file: %w", err) } } - utils.Log.App.Info().Msgf("Starting server on unix socket %s", app.config.Server.SocketPath) + tlog.App.Info().Msgf("Starting server on unix socket %s", app.config.Server.SocketPath) if err := router.RunUnix(app.config.Server.SocketPath); err != nil { - utils.Log.App.Fatal().Err(err).Msg("Failed to start server") + tlog.App.Fatal().Err(err).Msg("Failed to start server") } return nil @@ -196,9 +197,9 @@ func (app *BootstrapApp) Setup() error { // Start server address := fmt.Sprintf("%s:%d", app.config.Server.Address, app.config.Server.Port) - utils.Log.App.Info().Msgf("Starting server on %s", address) + tlog.App.Info().Msgf("Starting server on %s", address) if err := router.Run(address); err != nil { - utils.Log.App.Fatal().Err(err).Msg("Failed to start server") + tlog.App.Fatal().Err(err).Msg("Failed to start server") } return nil @@ -221,7 +222,7 @@ func (app *BootstrapApp) heartbeat() { bodyJson, err := json.Marshal(body) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to marshal heartbeat body") + tlog.App.Error().Err(err).Msg("Failed to marshal heartbeat body") return } @@ -232,12 +233,12 @@ func (app *BootstrapApp) heartbeat() { heartbeatURL := config.ApiServer + "/v1/instances/heartbeat" for ; true; <-ticker.C { - utils.Log.App.Debug().Msg("Sending heartbeat") + tlog.App.Debug().Msg("Sending heartbeat") req, err := http.NewRequest(http.MethodPost, heartbeatURL, bytes.NewReader(bodyJson)) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to create heartbeat request") + tlog.App.Error().Err(err).Msg("Failed to create heartbeat request") continue } @@ -246,14 +247,14 @@ func (app *BootstrapApp) heartbeat() { res, err := client.Do(req) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to send heartbeat") + tlog.App.Error().Err(err).Msg("Failed to send heartbeat") continue } res.Body.Close() if res.StatusCode != 200 && res.StatusCode != 201 { - utils.Log.App.Debug().Str("status", res.Status).Msg("Heartbeat returned non-200/201 status") + tlog.App.Debug().Str("status", res.Status).Msg("Heartbeat returned non-200/201 status") } } } @@ -264,10 +265,10 @@ func (app *BootstrapApp) dbCleanup(queries *repository.Queries) { ctx := context.Background() for ; true; <-ticker.C { - utils.Log.App.Debug().Msg("Cleaning up old database sessions") + tlog.App.Debug().Msg("Cleaning up old database sessions") err := queries.DeleteExpiredSessions(ctx, time.Now().Unix()) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to clean up old database sessions") + tlog.App.Error().Err(err).Msg("Failed to clean up old database sessions") } } } diff --git a/internal/bootstrap/service_bootstrap.go b/internal/bootstrap/service_bootstrap.go index f5de3995..e68c2f26 100644 --- a/internal/bootstrap/service_bootstrap.go +++ b/internal/bootstrap/service_bootstrap.go @@ -3,7 +3,7 @@ package bootstrap import ( "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/service" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" ) type Services struct { @@ -33,7 +33,7 @@ func (app *BootstrapApp) initServices(queries *repository.Queries) (Services, er if err == nil { services.ldapService = ldapService } else { - utils.Log.App.Warn().Err(err).Msg("Failed to initialize LDAP service, continuing without it") + tlog.App.Warn().Err(err).Msg("Failed to initialize LDAP service, continuing without it") } dockerService := service.NewDockerService() diff --git a/internal/controller/context_controller.go b/internal/controller/context_controller.go index 85581210..3c6f008c 100644 --- a/internal/controller/context_controller.go +++ b/internal/controller/context_controller.go @@ -5,6 +5,7 @@ import ( "net/url" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" ) @@ -60,7 +61,7 @@ type ContextController struct { func NewContextController(config ContextControllerConfig, router *gin.RouterGroup) *ContextController { if config.DisableUIWarnings { - utils.Log.App.Warn().Msg("UI warnings are disabled. This may expose users to security risks. Proceed with caution.") + tlog.App.Warn().Msg("UI warnings are disabled. This may expose users to security risks. Proceed with caution.") } return &ContextController{ @@ -93,7 +94,7 @@ func (controller *ContextController) userContextHandler(c *gin.Context) { } if err != nil { - utils.Log.App.Debug().Err(err).Msg("No user context found in request") + tlog.App.Debug().Err(err).Msg("No user context found in request") userContext.Status = 401 userContext.Message = "Unauthorized" userContext.IsLoggedIn = false @@ -107,7 +108,7 @@ func (controller *ContextController) userContextHandler(c *gin.Context) { func (controller *ContextController) appContextHandler(c *gin.Context) { appUrl, err := url.Parse(controller.config.AppURL) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to parse app URL") + tlog.App.Error().Err(err).Msg("Failed to parse app URL") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", diff --git a/internal/controller/context_controller_test.go b/internal/controller/context_controller_test.go index 7b041279..1a28e54d 100644 --- a/internal/controller/context_controller_test.go +++ b/internal/controller/context_controller_test.go @@ -7,7 +7,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/controller" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "gotest.tools/v3/assert" @@ -49,7 +49,7 @@ var userContext = config.UserContext{ } func setupContextController(middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder) { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() // Setup gin.SetMode(gin.TestMode) diff --git a/internal/controller/oauth_controller.go b/internal/controller/oauth_controller.go index e533a2fa..2eac77b8 100644 --- a/internal/controller/oauth_controller.go +++ b/internal/controller/oauth_controller.go @@ -9,6 +9,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/service" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "github.com/google/go-querystring/query" @@ -53,7 +54,7 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to bind URI") + tlog.App.Error().Err(err).Msg("Failed to bind URI") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -64,7 +65,7 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { service, exists := controller.broker.GetService(req.Provider) if !exists { - utils.Log.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) + tlog.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) c.JSON(404, gin.H{ "status": 404, "message": "Not Found", @@ -81,12 +82,12 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { isRedirectSafe := utils.IsRedirectSafe(redirectURI, controller.config.CookieDomain) if !isRedirectSafe { - utils.Log.App.Warn().Str("redirect_uri", redirectURI).Msg("Unsafe redirect URI detected, ignoring") + tlog.App.Warn().Str("redirect_uri", redirectURI).Msg("Unsafe redirect URI detected, ignoring") redirectURI = "" } if redirectURI != "" && isRedirectSafe { - utils.Log.App.Debug().Msg("Setting redirect URI cookie") + tlog.App.Debug().Msg("Setting redirect URI cookie") c.SetCookie(controller.config.RedirectCookieName, redirectURI, int(time.Hour.Seconds()), "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true) } @@ -102,7 +103,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to bind URI") + tlog.App.Error().Err(err).Msg("Failed to bind URI") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -114,7 +115,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { csrfCookie, err := c.Cookie(controller.config.CSRFCookieName) if err != nil || state != csrfCookie { - utils.Log.App.Warn().Err(err).Msg("CSRF token mismatch or cookie missing") + tlog.App.Warn().Err(err).Msg("CSRF token mismatch or cookie missing") c.SetCookie(controller.config.CSRFCookieName, "", -1, "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true) c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return @@ -126,14 +127,14 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { service, exists := controller.broker.GetService(req.Provider) if !exists { - utils.Log.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) + tlog.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } err = service.VerifyCode(code) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to verify OAuth code") + tlog.App.Error().Err(err).Msg("Failed to verify OAuth code") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -141,26 +142,26 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { user, err := controller.broker.GetUser(req.Provider) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to get user from OAuth provider") + tlog.App.Error().Err(err).Msg("Failed to get user from OAuth provider") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } if user.Email == "" { - utils.Log.App.Error().Msg("OAuth provider did not return an email") + tlog.App.Error().Msg("OAuth provider did not return an email") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } if !controller.auth.IsEmailWhitelisted(user.Email) { - utils.Log.App.Warn().Str("email", user.Email).Msg("Email not whitelisted") + tlog.App.Warn().Str("email", user.Email).Msg("Email not whitelisted") queries, err := query.Values(config.UnauthorizedQuery{ Username: user.Email, }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") + tlog.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -172,20 +173,20 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { var name string if strings.TrimSpace(user.Name) != "" { - utils.Log.App.Debug().Msg("Using name from OAuth provider") + tlog.App.Debug().Msg("Using name from OAuth provider") name = user.Name } else { - utils.Log.App.Debug().Msg("No name from OAuth provider, using pseudo name") + tlog.App.Debug().Msg("No name from OAuth provider, using pseudo name") name = fmt.Sprintf("%s (%s)", utils.Capitalize(strings.Split(user.Email, "@")[0]), strings.Split(user.Email, "@")[1]) } var username string if strings.TrimSpace(user.PreferredUsername) != "" { - utils.Log.App.Debug().Msg("Using preferred username from OAuth provider") + tlog.App.Debug().Msg("Using preferred username from OAuth provider") username = user.PreferredUsername } else { - utils.Log.App.Debug().Msg("No preferred username from OAuth provider, using pseudo username") + tlog.App.Debug().Msg("No preferred username from OAuth provider, using pseudo username") username = strings.Replace(user.Email, "@", "_", -1) } @@ -199,20 +200,22 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { OAuthSub: user.Sub, } - utils.Log.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") + tlog.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") err = controller.auth.CreateSessionCookie(c, &sessionCookie) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") + tlog.App.Error().Err(err).Msg("Failed to create session cookie") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } + tlog.AuditLoginSuccess(c, sessionCookie.Username, sessionCookie.Provider) + redirectURI, err := c.Cookie(controller.config.RedirectCookieName) if err != nil || !utils.IsRedirectSafe(redirectURI, controller.config.CookieDomain) { - utils.Log.App.Debug().Msg("No redirect URI cookie found, redirecting to app root") + tlog.App.Debug().Msg("No redirect URI cookie found, redirecting to app root") c.Redirect(http.StatusTemporaryRedirect, controller.config.AppURL) return } @@ -222,7 +225,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to encode redirect URI query") + tlog.App.Error().Err(err).Msg("Failed to encode redirect URI query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } diff --git a/internal/controller/proxy_controller.go b/internal/controller/proxy_controller.go index 3c8df988..bb62712e 100644 --- a/internal/controller/proxy_controller.go +++ b/internal/controller/proxy_controller.go @@ -9,6 +9,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/service" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "github.com/google/go-querystring/query" @@ -51,7 +52,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to bind URI") + tlog.App.Error().Err(err).Msg("Failed to bind URI") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -60,7 +61,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { } if !slices.Contains(SupportedProxies, req.Proxy) { - utils.Log.App.Warn().Str("proxy", req.Proxy).Msg("Invalid proxy") + tlog.App.Warn().Str("proxy", req.Proxy).Msg("Invalid proxy") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -72,7 +73,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { // Envoy uses the original client method for the external auth request // so we allow Any standard HTTP method for /api/auth/envoy if req.Proxy != "envoy" && c.Request.Method != http.MethodGet { - utils.Log.App.Warn().Str("method", c.Request.Method).Msg("Invalid method for proxy") + tlog.App.Warn().Str("method", c.Request.Method).Msg("Invalid method for proxy") c.Header("Allow", "GET") c.JSON(405, gin.H{ "status": 405, @@ -84,9 +85,9 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { isBrowser := strings.Contains(c.Request.Header.Get("Accept"), "text/html") if isBrowser { - utils.Log.App.Debug().Msg("Request identified as (most likely) coming from a browser") + tlog.App.Debug().Msg("Request identified as (most likely) coming from a browser") } else { - utils.Log.App.Debug().Msg("Request identified as (most likely) coming from a non-browser client") + tlog.App.Debug().Msg("Request identified as (most likely) coming from a non-browser client") } uri := c.Request.Header.Get("X-Forwarded-Uri") @@ -97,12 +98,12 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { acls, err := controller.acls.GetAccessControls(host) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to get access controls for resource") + tlog.App.Error().Err(err).Msg("Failed to get access controls for resource") controller.handleError(c, req, isBrowser) return } - utils.Log.App.Trace().Interface("acls", acls).Msg("ACLs for resource") + tlog.App.Trace().Interface("acls", acls).Msg("ACLs for resource") clientIP := c.ClientIP() @@ -118,13 +119,13 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { authEnabled, err := controller.auth.IsAuthEnabled(uri, acls.Path) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to check if auth is enabled for resource") + tlog.App.Error().Err(err).Msg("Failed to check if auth is enabled for resource") controller.handleError(c, req, isBrowser) return } if !authEnabled { - utils.Log.App.Debug().Msg("Authentication disabled for resource, allowing access") + tlog.App.Debug().Msg("Authentication disabled for resource, allowing access") controller.setHeaders(c, acls) c.JSON(200, gin.H{ "status": 200, @@ -148,7 +149,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") + tlog.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -162,7 +163,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { context, err := utils.GetContext(c) if err != nil { - utils.Log.App.Debug().Msg("No user context found in request, treating as not logged in") + tlog.App.Debug().Msg("No user context found in request, treating as not logged in") userContext = config.UserContext{ IsLoggedIn: false, } @@ -170,10 +171,10 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { userContext = context } - utils.Log.App.Trace().Interface("context", userContext).Msg("User context from request") + tlog.App.Trace().Interface("context", userContext).Msg("User context from request") if userContext.Provider == "basic" && userContext.TotpEnabled { - utils.Log.App.Debug().Msg("User has TOTP enabled, denying basic auth access") + tlog.App.Debug().Msg("User has TOTP enabled, denying basic auth access") userContext.IsLoggedIn = false } @@ -181,7 +182,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { userAllowed := controller.auth.IsUserAllowed(c, userContext, acls) if !userAllowed { - utils.Log.App.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User not allowed to access resource") + tlog.App.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User not allowed to access resource") if req.Proxy == "nginx" || !isBrowser { c.JSON(403, gin.H{ @@ -196,7 +197,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") + tlog.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -215,7 +216,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { groupOK := controller.auth.IsInOAuthGroup(c, userContext, acls.OAuth.Groups) if !groupOK { - utils.Log.App.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User OAuth groups do not match resource requirements") + tlog.App.Warn().Str("user", userContext.Username).Str("resource", strings.Split(host, ".")[0]).Msg("User OAuth groups do not match resource requirements") if req.Proxy == "nginx" || !isBrowser { c.JSON(403, gin.H{ @@ -231,7 +232,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to encode unauthorized query") + tlog.App.Error().Err(err).Msg("Failed to encode unauthorized query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -275,7 +276,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to encode redirect URI query") + tlog.App.Error().Err(err).Msg("Failed to encode redirect URI query") c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL)) return } @@ -289,14 +290,14 @@ func (controller *ProxyController) setHeaders(c *gin.Context, acls config.App) { headers := utils.ParseHeaders(acls.Response.Headers) for key, value := range headers { - utils.Log.App.Debug().Str("header", key).Msg("Setting header") + tlog.App.Debug().Str("header", key).Msg("Setting header") c.Header(key, value) } basicPassword := utils.GetSecret(acls.Response.BasicAuth.Password, acls.Response.BasicAuth.PasswordFile) if acls.Response.BasicAuth.Username != "" && basicPassword != "" { - utils.Log.App.Debug().Str("username", acls.Response.BasicAuth.Username).Msg("Setting basic auth header") + tlog.App.Debug().Str("username", acls.Response.BasicAuth.Username).Msg("Setting basic auth header") c.Header("Authorization", fmt.Sprintf("Basic %s", utils.GetBasicAuth(acls.Response.BasicAuth.Username, basicPassword))) } } diff --git a/internal/controller/proxy_controller_test.go b/internal/controller/proxy_controller_test.go index 519981f4..cc6a3e40 100644 --- a/internal/controller/proxy_controller_test.go +++ b/internal/controller/proxy_controller_test.go @@ -9,14 +9,14 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/service" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "gotest.tools/v3/assert" ) func setupProxyController(t *testing.T, middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder, *service.AuthService) { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() // Setup gin.SetMode(gin.TestMode) diff --git a/internal/controller/user_controller.go b/internal/controller/user_controller.go index 6eb7d16c..e35048b7 100644 --- a/internal/controller/user_controller.go +++ b/internal/controller/user_controller.go @@ -8,6 +8,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/service" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "github.com/pquerna/otp/totp" @@ -52,7 +53,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { err := c.ShouldBindJSON(&req) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to bind JSON") + tlog.App.Error().Err(err).Msg("Failed to bind JSON") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -60,12 +61,13 @@ func (controller *UserController) loginHandler(c *gin.Context) { return } - utils.Log.App.Debug().Str("username", req.Username).Msg("Login attempt") + tlog.App.Debug().Str("username", req.Username).Msg("Login attempt") isLocked, remaining := controller.auth.IsAccountLocked(req.Username) if isLocked { - utils.Log.App.Warn().Str("username", req.Username).Msg("Account is locked due to too many failed login attempts") + tlog.App.Warn().Str("username", req.Username).Msg("Account is locked due to too many failed login attempts") + tlog.AuditLoginFailure(c, req.Username, "username") c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.JSON(429, gin.H{ @@ -78,8 +80,9 @@ func (controller *UserController) loginHandler(c *gin.Context) { userSearch := controller.auth.SearchUser(req.Username) if userSearch.Type == "unknown" { - utils.Log.App.Warn().Str("username", req.Username).Msg("User not found") + tlog.App.Warn().Str("username", req.Username).Msg("User not found") controller.auth.RecordLoginAttempt(req.Username, false) + tlog.AuditLoginFailure(c, req.Username, "username") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -88,8 +91,9 @@ func (controller *UserController) loginHandler(c *gin.Context) { } if !controller.auth.VerifyUser(userSearch, req.Password) { - utils.Log.App.Warn().Str("username", req.Username).Msg("Invalid password") + tlog.App.Warn().Str("username", req.Username).Msg("Invalid password") controller.auth.RecordLoginAttempt(req.Username, false) + tlog.AuditLoginFailure(c, req.Username, "username") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -97,7 +101,8 @@ func (controller *UserController) loginHandler(c *gin.Context) { return } - utils.Log.App.Info().Str("username", req.Username).Msg("Login successful") + tlog.App.Info().Str("username", req.Username).Msg("Login successful") + tlog.AuditLoginSuccess(c, req.Username, "username") controller.auth.RecordLoginAttempt(req.Username, true) @@ -105,7 +110,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { user := controller.auth.GetLocalUser(userSearch.Username) if user.TotpSecret != "" { - utils.Log.App.Debug().Str("username", req.Username).Msg("User has TOTP enabled, requiring TOTP verification") + tlog.App.Debug().Str("username", req.Username).Msg("User has TOTP enabled, requiring TOTP verification") err := controller.auth.CreateSessionCookie(c, &config.SessionCookie{ Username: user.Username, @@ -116,7 +121,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { }) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") + tlog.App.Error().Err(err).Msg("Failed to create session cookie") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -140,12 +145,12 @@ func (controller *UserController) loginHandler(c *gin.Context) { Provider: "username", } - utils.Log.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") + tlog.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") err = controller.auth.CreateSessionCookie(c, &sessionCookie) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") + tlog.App.Error().Err(err).Msg("Failed to create session cookie") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -160,10 +165,15 @@ func (controller *UserController) loginHandler(c *gin.Context) { } func (controller *UserController) logoutHandler(c *gin.Context) { - utils.Log.App.Debug().Msg("Logout request received") + tlog.App.Debug().Msg("Logout request received") controller.auth.DeleteSessionCookie(c) + context, err := utils.GetContext(c) + if err == nil && context.IsLoggedIn { + tlog.AuditLogout(c, context.Username, context.Provider) + } + c.JSON(200, gin.H{ "status": 200, "message": "Logout successful", @@ -175,7 +185,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { err := c.ShouldBindJSON(&req) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to bind JSON") + tlog.App.Error().Err(err).Msg("Failed to bind JSON") c.JSON(400, gin.H{ "status": 400, "message": "Bad Request", @@ -186,7 +196,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { context, err := utils.GetContext(c) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to get user context") + tlog.App.Error().Err(err).Msg("Failed to get user context") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -195,7 +205,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { } if !context.TotpPending { - utils.Log.App.Warn().Msg("TOTP attempt without a pending TOTP session") + tlog.App.Warn().Msg("TOTP attempt without a pending TOTP session") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -203,12 +213,12 @@ func (controller *UserController) totpHandler(c *gin.Context) { return } - utils.Log.App.Debug().Str("username", context.Username).Msg("TOTP verification attempt") + tlog.App.Debug().Str("username", context.Username).Msg("TOTP verification attempt") isLocked, remaining := controller.auth.IsAccountLocked(context.Username) if isLocked { - utils.Log.App.Warn().Str("username", context.Username).Msg("Account is locked due to too many failed TOTP attempts") + tlog.App.Warn().Str("username", context.Username).Msg("Account is locked due to too many failed TOTP attempts") c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.JSON(429, gin.H{ @@ -223,8 +233,9 @@ func (controller *UserController) totpHandler(c *gin.Context) { ok := totp.Validate(req.Code, user.TotpSecret) if !ok { - utils.Log.App.Warn().Str("username", context.Username).Msg("Invalid TOTP code") + tlog.App.Warn().Str("username", context.Username).Msg("Invalid TOTP code") controller.auth.RecordLoginAttempt(context.Username, false) + tlog.AuditLoginFailure(c, context.Username, "totp") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -232,7 +243,8 @@ func (controller *UserController) totpHandler(c *gin.Context) { return } - utils.Log.App.Info().Str("username", context.Username).Msg("TOTP verification successful") + tlog.App.Info().Str("username", context.Username).Msg("TOTP verification successful") + tlog.AuditLoginSuccess(c, context.Username, "totp") controller.auth.RecordLoginAttempt(context.Username, true) @@ -243,12 +255,12 @@ func (controller *UserController) totpHandler(c *gin.Context) { Provider: "username", } - utils.Log.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") + tlog.App.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie") err = controller.auth.CreateSessionCookie(c, &sessionCookie) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to create session cookie") + tlog.App.Error().Err(err).Msg("Failed to create session cookie") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", diff --git a/internal/controller/user_controller_test.go b/internal/controller/user_controller_test.go index fc0e5e80..ef104874 100644 --- a/internal/controller/user_controller_test.go +++ b/internal/controller/user_controller_test.go @@ -13,7 +13,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/service" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "github.com/pquerna/otp/totp" @@ -24,7 +24,7 @@ var cookieValue string var totpSecret = "6WFZXPEZRK5MZHHYAFW4DAOUYQMCASBJ" func setupUserController(t *testing.T, middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder) { - utils.NewSimpleLogger().Init() + tlog.NewSimpleLogger().Init() // Setup gin.SetMode(gin.TestMode) diff --git a/internal/middleware/context_middleware.go b/internal/middleware/context_middleware.go index 9c401945..22749a78 100644 --- a/internal/middleware/context_middleware.go +++ b/internal/middleware/context_middleware.go @@ -8,6 +8,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/service" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" ) @@ -39,7 +40,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { cookie, err := m.auth.GetSessionCookie(c) if err != nil { - utils.Log.App.Debug().Err(err).Msg("No valid session cookie found") + tlog.App.Debug().Err(err).Msg("No valid session cookie found") goto basic } @@ -61,7 +62,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { userSearch := m.auth.SearchUser(cookie.Username) if userSearch.Type == "unknown" || userSearch.Type == "error" { - utils.Log.App.Debug().Msg("User from session cookie not found") + tlog.App.Debug().Msg("User from session cookie not found") m.auth.DeleteSessionCookie(c) goto basic } @@ -80,13 +81,13 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { _, exists := m.broker.GetService(cookie.Provider) if !exists { - utils.Log.App.Debug().Msg("OAuth provider from session cookie not found") + tlog.App.Debug().Msg("OAuth provider from session cookie not found") m.auth.DeleteSessionCookie(c) goto basic } if !m.auth.IsEmailWhitelisted(cookie.Email) { - utils.Log.App.Debug().Msg("Email from session cookie not whitelisted") + tlog.App.Debug().Msg("Email from session cookie not whitelisted") m.auth.DeleteSessionCookie(c) goto basic } @@ -111,7 +112,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { basic := m.auth.GetBasicAuth(c) if basic == nil { - utils.Log.App.Debug().Msg("No basic auth provided") + tlog.App.Debug().Msg("No basic auth provided") c.Next() return } @@ -119,7 +120,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { locked, remaining := m.auth.IsAccountLocked(basic.Username) if locked { - utils.Log.App.Debug().Msgf("Account for user %s is locked for %d seconds, denying auth", basic.Username, remaining) + tlog.App.Debug().Msgf("Account for user %s is locked for %d seconds, denying auth", basic.Username, remaining) c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.Next() @@ -130,14 +131,14 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { if userSearch.Type == "unknown" || userSearch.Type == "error" { m.auth.RecordLoginAttempt(basic.Username, false) - utils.Log.App.Debug().Msg("User from basic auth not found") + tlog.App.Debug().Msg("User from basic auth not found") c.Next() return } if !m.auth.VerifyUser(userSearch, basic.Password) { m.auth.RecordLoginAttempt(basic.Username, false) - utils.Log.App.Debug().Msg("Invalid password for basic auth user") + tlog.App.Debug().Msg("Invalid password for basic auth user") c.Next() return } @@ -146,7 +147,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { switch userSearch.Type { case "local": - utils.Log.App.Debug().Msg("Basic auth user is local") + tlog.App.Debug().Msg("Basic auth user is local") user := m.auth.GetLocalUser(basic.Username) @@ -161,7 +162,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { c.Next() return case "ldap": - utils.Log.App.Debug().Msg("Basic auth user is LDAP") + tlog.App.Debug().Msg("Basic auth user is LDAP") c.Set("context", &config.UserContext{ Username: basic.Username, Name: utils.Capitalize(basic.Username), diff --git a/internal/middleware/zerolog_middleware.go b/internal/middleware/zerolog_middleware.go index 1d62d467..b88556bf 100644 --- a/internal/middleware/zerolog_middleware.go +++ b/internal/middleware/zerolog_middleware.go @@ -5,7 +5,7 @@ import ( "time" "github.com/gin-gonic/gin" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" ) var ( @@ -49,7 +49,7 @@ func (m *ZerologMiddleware) Middleware() gin.HandlerFunc { latency := time.Since(tStart).String() - subLogger := utils.Log.HTTP.With().Str("method", method). + subLogger := tlog.HTTP.With().Str("method", method). Str("path", path). Str("address", address). Str("client_ip", clientIP). diff --git a/internal/service/access_controls_service.go b/internal/service/access_controls_service.go index cbb0ba42..087ce883 100644 --- a/internal/service/access_controls_service.go +++ b/internal/service/access_controls_service.go @@ -5,7 +5,7 @@ import ( "strings" "github.com/steveiliop56/tinyauth/internal/config" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" ) type AccessControlsService struct { @@ -27,12 +27,12 @@ func (acls *AccessControlsService) Init() error { func (acls *AccessControlsService) lookupStaticACLs(domain string) (config.App, error) { for app, config := range acls.static { if config.Config.Domain == domain { - utils.Log.App.Debug().Str("name", app).Msg("Found matching container by domain") + tlog.App.Debug().Str("name", app).Msg("Found matching container by domain") return config, nil } if strings.SplitN(domain, ".", 2)[0] == app { - utils.Log.App.Debug().Str("name", app).Msg("Found matching container by app name") + tlog.App.Debug().Str("name", app).Msg("Found matching container by app name") return config, nil } } @@ -44,11 +44,11 @@ func (acls *AccessControlsService) GetAccessControls(domain string) (config.App, app, err := acls.lookupStaticACLs(domain) if err == nil { - utils.Log.App.Debug().Msg("Using ACls from static configuration") + tlog.App.Debug().Msg("Using ACls from static configuration") return app, nil } // Fallback to Docker labels - utils.Log.App.Debug().Msg("Falling back to Docker labels for ACLs") + tlog.App.Debug().Msg("Falling back to Docker labels for ACLs") return acls.docker.GetLabels(domain) } diff --git a/internal/service/auth_service.go b/internal/service/auth_service.go index 13feec62..cddb613f 100644 --- a/internal/service/auth_service.go +++ b/internal/service/auth_service.go @@ -12,6 +12,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" "github.com/google/uuid" @@ -72,7 +73,7 @@ func (auth *AuthService) SearchUser(username string) config.UserSearch { userDN, err := auth.ldap.Search(username) if err != nil { - utils.Log.App.Warn().Err(err).Str("username", username).Msg("Failed to search for user in LDAP") + tlog.App.Warn().Err(err).Str("username", username).Msg("Failed to search for user in LDAP") return config.UserSearch{ Type: "error", } @@ -98,24 +99,24 @@ func (auth *AuthService) VerifyUser(search config.UserSearch, password string) b if auth.ldap != nil { err := auth.ldap.Bind(search.Username, password) if err != nil { - utils.Log.App.Warn().Err(err).Str("username", search.Username).Msg("Failed to bind to LDAP") + tlog.App.Warn().Err(err).Str("username", search.Username).Msg("Failed to bind to LDAP") return false } err = auth.ldap.BindService(true) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to rebind with service account after user authentication") + tlog.App.Error().Err(err).Msg("Failed to rebind with service account after user authentication") return false } return true } default: - utils.Log.App.Debug().Str("type", search.Type).Msg("Unknown user type for authentication") + tlog.App.Debug().Str("type", search.Type).Msg("Unknown user type for authentication") return false } - utils.Log.App.Warn().Str("username", search.Username).Msg("User authentication failed") + tlog.App.Warn().Str("username", search.Username).Msg("User authentication failed") return false } @@ -126,7 +127,7 @@ func (auth *AuthService) GetLocalUser(username string) config.User { } } - utils.Log.App.Warn().Str("username", username).Msg("Local user not found") + tlog.App.Warn().Str("username", username).Msg("Local user not found") return config.User{} } @@ -181,7 +182,7 @@ func (auth *AuthService) RecordLoginAttempt(identifier string, success bool) { if attempt.FailedAttempts >= auth.config.LoginMaxRetries { attempt.LockedUntil = time.Now().Add(time.Duration(auth.config.LoginTimeout) * time.Second) - utils.Log.App.Warn().Str("identifier", identifier).Int("timeout", auth.config.LoginTimeout).Msg("Account locked due to too many failed login attempts") + tlog.App.Warn().Str("identifier", identifier).Int("timeout", auth.config.LoginTimeout).Msg("Account locked due to too many failed login attempts") } } @@ -276,7 +277,7 @@ func (auth *AuthService) RefreshSessionCookie(c *gin.Context) error { } c.SetCookie(auth.config.SessionCookieName, cookie, int(newExpiry-currentTime), "/", fmt.Sprintf(".%s", auth.config.CookieDomain), auth.config.SecureCookie, true) - utils.Log.App.Trace().Str("username", session.Username).Msg("Session cookie refreshed") + tlog.App.Trace().Str("username", session.Username).Msg("Session cookie refreshed") return nil } @@ -321,7 +322,7 @@ func (auth *AuthService) GetSessionCookie(c *gin.Context) (config.SessionCookie, if currentTime-session.CreatedAt > int64(auth.config.SessionMaxLifetime) { err = auth.queries.DeleteSession(c, cookie) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to delete session exceeding max lifetime") + tlog.App.Error().Err(err).Msg("Failed to delete session exceeding max lifetime") } return config.SessionCookie{}, fmt.Errorf("session expired due to max lifetime exceeded") } @@ -330,7 +331,7 @@ func (auth *AuthService) GetSessionCookie(c *gin.Context) (config.SessionCookie, if currentTime > session.Expiry { err = auth.queries.DeleteSession(c, cookie) if err != nil { - utils.Log.App.Error().Err(err).Msg("Failed to delete expired session") + tlog.App.Error().Err(err).Msg("Failed to delete expired session") } return config.SessionCookie{}, fmt.Errorf("session expired") } @@ -354,18 +355,18 @@ func (auth *AuthService) UserAuthConfigured() bool { func (auth *AuthService) IsUserAllowed(c *gin.Context, context config.UserContext, acls config.App) bool { if context.OAuth { - utils.Log.App.Debug().Msg("Checking OAuth whitelist") + tlog.App.Debug().Msg("Checking OAuth whitelist") return utils.CheckFilter(acls.OAuth.Whitelist, context.Email) } if acls.Users.Block != "" { - utils.Log.App.Debug().Msg("Checking blocked users") + tlog.App.Debug().Msg("Checking blocked users") if utils.CheckFilter(acls.Users.Block, context.Username) { return false } } - utils.Log.App.Debug().Msg("Checking users") + tlog.App.Debug().Msg("Checking users") return utils.CheckFilter(acls.Users.Allow, context.Username) } @@ -376,19 +377,19 @@ func (auth *AuthService) IsInOAuthGroup(c *gin.Context, context config.UserConte for id := range config.OverrideProviders { if context.Provider == id { - utils.Log.App.Info().Str("provider", id).Msg("OAuth groups not supported for this provider") + tlog.App.Info().Str("provider", id).Msg("OAuth groups not supported for this provider") return true } } for userGroup := range strings.SplitSeq(context.OAuthGroups, ",") { if utils.CheckFilter(requiredGroups, strings.TrimSpace(userGroup)) { - utils.Log.App.Trace().Str("group", userGroup).Str("required", requiredGroups).Msg("User group matched") + tlog.App.Trace().Str("group", userGroup).Str("required", requiredGroups).Msg("User group matched") return true } } - utils.Log.App.Debug().Msg("No groups matched") + tlog.App.Debug().Msg("No groups matched") return false } @@ -425,7 +426,7 @@ func (auth *AuthService) IsAuthEnabled(uri string, path config.AppPath) (bool, e func (auth *AuthService) GetBasicAuth(c *gin.Context) *config.User { username, password, ok := c.Request.BasicAuth() if !ok { - utils.Log.App.Debug().Msg("No basic auth provided") + tlog.App.Debug().Msg("No basic auth provided") return nil } return &config.User{ @@ -442,11 +443,11 @@ func (auth *AuthService) CheckIP(acls config.AppIP, ip string) bool { for _, blocked := range blockedIps { res, err := utils.FilterIP(blocked, ip) if err != nil { - utils.Log.App.Warn().Err(err).Str("item", blocked).Msg("Invalid IP/CIDR in block list") + tlog.App.Warn().Err(err).Str("item", blocked).Msg("Invalid IP/CIDR in block list") continue } if res { - utils.Log.App.Debug().Str("ip", ip).Str("item", blocked).Msg("IP is in blocked list, denying access") + tlog.App.Debug().Str("ip", ip).Str("item", blocked).Msg("IP is in blocked list, denying access") return false } } @@ -454,21 +455,21 @@ func (auth *AuthService) CheckIP(acls config.AppIP, ip string) bool { for _, allowed := range allowedIPs { res, err := utils.FilterIP(allowed, ip) if err != nil { - utils.Log.App.Warn().Err(err).Str("item", allowed).Msg("Invalid IP/CIDR in allow list") + tlog.App.Warn().Err(err).Str("item", allowed).Msg("Invalid IP/CIDR in allow list") continue } if res { - utils.Log.App.Debug().Str("ip", ip).Str("item", allowed).Msg("IP is in allowed list, allowing access") + tlog.App.Debug().Str("ip", ip).Str("item", allowed).Msg("IP is in allowed list, allowing access") return true } } if len(allowedIPs) > 0 { - utils.Log.App.Debug().Str("ip", ip).Msg("IP not in allow list, denying access") + tlog.App.Debug().Str("ip", ip).Msg("IP not in allow list, denying access") return false } - utils.Log.App.Debug().Str("ip", ip).Msg("IP not in allow or block list, allowing by default") + tlog.App.Debug().Str("ip", ip).Msg("IP not in allow or block list, allowing by default") return true } @@ -476,15 +477,15 @@ func (auth *AuthService) IsBypassedIP(acls config.AppIP, ip string) bool { for _, bypassed := range acls.Bypass { res, err := utils.FilterIP(bypassed, ip) if err != nil { - utils.Log.App.Warn().Err(err).Str("item", bypassed).Msg("Invalid IP/CIDR in bypass list") + tlog.App.Warn().Err(err).Str("item", bypassed).Msg("Invalid IP/CIDR in bypass list") continue } if res { - utils.Log.App.Debug().Str("ip", ip).Str("item", bypassed).Msg("IP is in bypass list, allowing access") + tlog.App.Debug().Str("ip", ip).Str("item", bypassed).Msg("IP is in bypass list, allowing access") return true } } - utils.Log.App.Debug().Str("ip", ip).Msg("IP not in bypass list, continuing with authentication") + tlog.App.Debug().Str("ip", ip).Msg("IP not in bypass list, continuing with authentication") return false } diff --git a/internal/service/docker_service.go b/internal/service/docker_service.go index 9063fa6a..fc96fb9d 100644 --- a/internal/service/docker_service.go +++ b/internal/service/docker_service.go @@ -5,8 +5,8 @@ import ( "strings" "github.com/steveiliop56/tinyauth/internal/config" - "github.com/steveiliop56/tinyauth/internal/utils" "github.com/steveiliop56/tinyauth/internal/utils/decoders" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" container "github.com/docker/docker/api/types/container" "github.com/docker/docker/client" @@ -37,7 +37,7 @@ func (docker *DockerService) Init() error { _, err = docker.client.Ping(docker.context) if err != nil { - utils.Log.App.Debug().Err(err).Msg("Docker not connected") + tlog.App.Debug().Err(err).Msg("Docker not connected") docker.isConnected = false docker.client = nil docker.context = nil @@ -45,7 +45,7 @@ func (docker *DockerService) Init() error { } docker.isConnected = true - utils.Log.App.Debug().Msg("Docker connected") + tlog.App.Debug().Msg("Docker connected") return nil } @@ -68,7 +68,7 @@ func (docker *DockerService) inspectContainer(containerId string) (container.Ins func (docker *DockerService) GetLabels(appDomain string) (config.App, error) { if !docker.isConnected { - utils.Log.App.Debug().Msg("Docker not connected, returning empty labels") + tlog.App.Debug().Msg("Docker not connected, returning empty labels") return config.App{}, nil } @@ -90,17 +90,17 @@ func (docker *DockerService) GetLabels(appDomain string) (config.App, error) { for appName, appLabels := range labels.Apps { if appLabels.Config.Domain == appDomain { - utils.Log.App.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by domain") + tlog.App.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by domain") return appLabels, nil } if strings.SplitN(appDomain, ".", 2)[0] == appName { - utils.Log.App.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by app name") + tlog.App.Debug().Str("id", inspect.ID).Str("name", inspect.Name).Msg("Found matching container by app name") return appLabels, nil } } } - utils.Log.App.Debug().Msg("No matching container found, returning empty labels") + tlog.App.Debug().Msg("No matching container found, returning empty labels") return config.App{}, nil } diff --git a/internal/service/generic_oauth_service.go b/internal/service/generic_oauth_service.go index 4c1f07f7..ef17b0eb 100644 --- a/internal/service/generic_oauth_service.go +++ b/internal/service/generic_oauth_service.go @@ -12,7 +12,7 @@ import ( "time" "github.com/steveiliop56/tinyauth/internal/config" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "golang.org/x/oauth2" ) @@ -117,7 +117,7 @@ func (generic *GenericOAuthService) Userinfo() (config.Claims, error) { return user, err } - utils.Log.App.Trace().Str("body", string(body)).Msg("Userinfo response body") + tlog.App.Trace().Str("body", string(body)).Msg("Userinfo response body") err = json.Unmarshal(body, &user) if err != nil { diff --git a/internal/service/ldap_service.go b/internal/service/ldap_service.go index 16eada1c..fb037786 100644 --- a/internal/service/ldap_service.go +++ b/internal/service/ldap_service.go @@ -9,7 +9,7 @@ import ( "github.com/cenkalti/backoff/v5" ldapgo "github.com/go-ldap/ldap/v3" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" ) type LdapServiceConfig struct { @@ -44,7 +44,7 @@ func (ldap *LdapService) Init() error { return fmt.Errorf("failed to initialize LDAP with mTLS authentication: %w", err) } ldap.cert = &cert - utils.Log.App.Info().Msg("Using LDAP with mTLS authentication") + tlog.App.Info().Msg("Using LDAP with mTLS authentication") // TODO: Add optional extra CA certificates, instead of `InsecureSkipVerify` /* @@ -66,12 +66,12 @@ func (ldap *LdapService) Init() error { for range time.Tick(time.Duration(5) * time.Minute) { err := ldap.heartbeat() if err != nil { - utils.Log.App.Error().Err(err).Msg("LDAP connection heartbeat failed") + tlog.App.Error().Err(err).Msg("LDAP connection heartbeat failed") if reconnectErr := ldap.reconnect(); reconnectErr != nil { - utils.Log.App.Error().Err(reconnectErr).Msg("Failed to reconnect to LDAP server") + tlog.App.Error().Err(reconnectErr).Msg("Failed to reconnect to LDAP server") continue } - utils.Log.App.Info().Msg("Successfully reconnected to LDAP server") + tlog.App.Info().Msg("Successfully reconnected to LDAP server") } } }() @@ -169,7 +169,7 @@ func (ldap *LdapService) Bind(userDN string, password string) error { } func (ldap *LdapService) heartbeat() error { - utils.Log.App.Debug().Msg("Performing LDAP connection heartbeat") + tlog.App.Debug().Msg("Performing LDAP connection heartbeat") searchRequest := ldapgo.NewSearchRequest( "", @@ -191,7 +191,7 @@ func (ldap *LdapService) heartbeat() error { } func (ldap *LdapService) reconnect() error { - utils.Log.App.Info().Msg("Reconnecting to LDAP server") + tlog.App.Info().Msg("Reconnecting to LDAP server") exp := backoff.NewExponentialBackOff() exp.InitialInterval = 500 * time.Millisecond diff --git a/internal/service/oauth_broker_service.go b/internal/service/oauth_broker_service.go index ac19c7b0..194c4315 100644 --- a/internal/service/oauth_broker_service.go +++ b/internal/service/oauth_broker_service.go @@ -4,7 +4,7 @@ import ( "errors" "github.com/steveiliop56/tinyauth/internal/config" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "golang.org/x/exp/slices" ) @@ -49,10 +49,10 @@ func (broker *OAuthBrokerService) Init() error { for name, service := range broker.services { err := service.Init() if err != nil { - utils.Log.App.Error().Err(err).Msgf("Failed to initialize OAuth service: %T", name) + tlog.App.Error().Err(err).Msgf("Failed to initialize OAuth service: %T", name) return err } - utils.Log.App.Info().Str("service", name).Msg("Initialized OAuth service") + tlog.App.Info().Str("service", name).Msg("Initialized OAuth service") } return nil diff --git a/internal/utils/tlog/log_audit.go b/internal/utils/tlog/log_audit.go new file mode 100644 index 00000000..d0c3fb02 --- /dev/null +++ b/internal/utils/tlog/log_audit.go @@ -0,0 +1,33 @@ +package tlog + +import "github.com/gin-gonic/gin" + +func AuditLoginSuccess(c *gin.Context, username, provider string) { + Audit.Info(). + Str("event", "login"). + Str("result", "success"). + Str("username", username). + Str("provider", provider). + Str("ip", c.ClientIP()). + Send() +} + +func AuditLoginFailure(c *gin.Context, username, provider string) { + Audit.Warn(). + Str("event", "login"). + Str("result", "failure"). + Str("username", username). + Str("provider", provider). + Str("ip", c.ClientIP()). + Send() +} + +func AuditLogout(c *gin.Context, username, provider string) { + Audit.Info(). + Str("event", "logout"). + Str("result", "success"). + Str("username", username). + Str("provider", provider). + Str("ip", c.ClientIP()). + Send() +} diff --git a/internal/utils/log_utils.go b/internal/utils/tlog/log_wrapper.go similarity index 85% rename from internal/utils/log_utils.go rename to internal/utils/tlog/log_wrapper.go index 1c651326..ef24bf77 100644 --- a/internal/utils/log_utils.go +++ b/internal/utils/tlog/log_wrapper.go @@ -1,4 +1,4 @@ -package utils +package tlog import ( "os" @@ -16,7 +16,11 @@ type Logger struct { App zerolog.Logger } -var Log *Logger +var ( + Audit zerolog.Logger + HTTP zerolog.Logger + App zerolog.Logger +) func NewLogger(cfg config.LogConfig) *Logger { baseLogger := log.With(). @@ -52,19 +56,21 @@ func NewSimpleLogger() *Logger { } func (l *Logger) Init() { - Log = l + Audit = l.Audit + HTTP = l.HTTP + App = l.App } func createLogger(component string, streamCfg config.LogStreamConfig, baseLogger zerolog.Logger) zerolog.Logger { if !streamCfg.Enabled { return zerolog.Nop() } - logger := baseLogger.With().Str("log_stream", component).Logger() + subLogger := baseLogger.With().Str("log_stream", component).Logger() // override level if specified, otherwise use base level if streamCfg.Level != "" { - logger = logger.Level(parseLogLevel(streamCfg.Level)) + subLogger = subLogger.Level(parseLogLevel(streamCfg.Level)) } - return logger + return subLogger } func parseLogLevel(level string) zerolog.Level { diff --git a/internal/utils/log_utils_test.go b/internal/utils/tlog/log_wrapper_test.go similarity index 85% rename from internal/utils/log_utils_test.go rename to internal/utils/tlog/log_wrapper_test.go index e98b1cfb..1ba521c0 100644 --- a/internal/utils/log_utils_test.go +++ b/internal/utils/tlog/log_wrapper_test.go @@ -1,4 +1,4 @@ -package utils_test +package tlog_test import ( "bytes" @@ -6,7 +6,7 @@ import ( "testing" "github.com/steveiliop56/tinyauth/internal/config" - "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/rs/zerolog" "gotest.tools/v3/assert" @@ -23,18 +23,16 @@ func TestNewLogger(t *testing.T) { }, } - logger := utils.NewLogger(cfg) + logger := tlog.NewLogger(cfg) assert.Assert(t, logger != nil) - assert.Assert(t, utils.Log == nil) assert.Assert(t, logger.HTTP.GetLevel() == zerolog.InfoLevel) assert.Assert(t, logger.App.GetLevel() == zerolog.DebugLevel) assert.Assert(t, logger.Audit.GetLevel() == zerolog.Disabled) } func TestNewSimpleLogger(t *testing.T) { - logger := utils.NewSimpleLogger() - + logger := tlog.NewSimpleLogger() assert.Assert(t, logger != nil) assert.Assert(t, logger.HTTP.GetLevel() == zerolog.InfoLevel) assert.Assert(t, logger.App.GetLevel() == zerolog.InfoLevel) @@ -42,11 +40,10 @@ func TestNewSimpleLogger(t *testing.T) { } func TestLoggerInit(t *testing.T) { - logger := utils.NewSimpleLogger() + logger := tlog.NewSimpleLogger() logger.Init() - assert.Assert(t, utils.Log != nil) - assert.Assert(t, utils.Log.App.GetLevel() != zerolog.Disabled) + assert.Assert(t, tlog.App.GetLevel() != zerolog.Disabled) } func TestLoggerWithDisabledStreams(t *testing.T) { @@ -60,7 +57,7 @@ func TestLoggerWithDisabledStreams(t *testing.T) { }, } - logger := utils.NewLogger(cfg) + logger := tlog.NewLogger(cfg) assert.Assert(t, logger.HTTP.GetLevel() == zerolog.Disabled) assert.Assert(t, logger.App.GetLevel() == zerolog.Disabled) @@ -80,7 +77,7 @@ func TestLogStreamField(t *testing.T) { }, } - logger := utils.NewLogger(cfg) + logger := tlog.NewLogger(cfg) // Override output for HTTP logger to capture output logger.HTTP = logger.HTTP.Output(&buf) From f07191459fe704b341dc3f5da369a51f5fa7d513 Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 20:08:32 -0500 Subject: [PATCH 4/7] refactor: update logging configuration in environment files --- .env.example | 16 +++++++++++++--- config.example.yaml | 17 +++++++++++++---- 2 files changed, 26 insertions(+), 7 deletions(-) diff --git a/.env.example b/.env.example index 607ce082..72eee61f 100644 --- a/.env.example +++ b/.env.example @@ -2,8 +2,6 @@ # The base URL where Tinyauth is accessible TINYAUTH_APPURL="https://auth.example.com" -# Log level: trace, debug, info, warn, error -TINYAUTH_LOGLEVEL="info" # Directory for static resources TINYAUTH_RESOURCESDIR="/data/resources" # Path to SQLite database file @@ -14,8 +12,20 @@ TINYAUTH_DISABLEANALYTICS="false" TINYAUTH_DISABLERESOURCES="false" # Disable UI warning messages TINYAUTH_DISABLEUIWARNINGS="false" + +# Logging Configuration + +# Log level: trace, debug, info, warn, error +TINYAUTH_LOG_LEVEL="info" # Enable JSON formatted logs -TINYAUTH_LOGJSON="false" +TINYAUTH_LOG_JSON="false" +# Specific Log stream configurations +# APP and HTTP log streams are enabled by default, and use the global log level unless overridden +TINYAUTH_LOG_STREAMS_APP_ENABLED="true" +TINYAUTH_LOG_STREAMS_APP_LEVEL="info" +TINYAUTH_LOG_STREAMS_HTTP_ENABLED="true" +TINYAUTH_LOG_STREAMS_HTTP_LEVEL="info" +TINYAUTH_LOG_STREAMS_AUDIT_ENABLED="false" # Server Configuration diff --git a/config.example.yaml b/config.example.yaml index 26e56d5e..0c5e74e1 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -2,8 +2,6 @@ # The base URL where Tinyauth is accessible appUrl: "https://auth.example.com" -# Log level: trace, debug, info, warn, error -logLevel: "info" # Directory for static resources resourcesDir: "./resources" # Path to SQLite database file @@ -14,8 +12,19 @@ disableAnalytics: false disableResources: false # Disable UI warning messages disableUIWarnings: false -# Enable JSON formatted logs -logJSON: false + +# Logging Configuration +log: + # Log level: trace, debug, info, warn, error + level: "info" + json: false + streams: + app: + level: "warn" + http: + level: "debug" + audit: + enabled: false # Server Configuration server: From 4ebdffa6b147cc414a5254eb5125f82be418cd1d Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 22:19:40 -0500 Subject: [PATCH 5/7] fix: adding coderabbit suggestions --- .env.example | 1 + config.example.yaml | 3 +++ internal/controller/oauth_controller.go | 1 + internal/controller/user_controller.go | 8 ++++---- internal/service/oauth_broker_service.go | 2 +- internal/utils/tlog/log_audit.go | 2 +- 6 files changed, 11 insertions(+), 6 deletions(-) diff --git a/.env.example b/.env.example index 72eee61f..ec753007 100644 --- a/.env.example +++ b/.env.example @@ -26,6 +26,7 @@ TINYAUTH_LOG_STREAMS_APP_LEVEL="info" TINYAUTH_LOG_STREAMS_HTTP_ENABLED="true" TINYAUTH_LOG_STREAMS_HTTP_LEVEL="info" TINYAUTH_LOG_STREAMS_AUDIT_ENABLED="false" +TINYAUTH_LOG_STREAMS_AUDIT_LEVEL="info" # Server Configuration diff --git a/config.example.yaml b/config.example.yaml index 0c5e74e1..fecc823d 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -20,11 +20,14 @@ log: json: false streams: app: + enabled: true level: "warn" http: + enabled: true level: "debug" audit: enabled: false + level: "info" # Server Configuration server: diff --git a/internal/controller/oauth_controller.go b/internal/controller/oauth_controller.go index 2eac77b8..8dfd7a2e 100644 --- a/internal/controller/oauth_controller.go +++ b/internal/controller/oauth_controller.go @@ -155,6 +155,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { if !controller.auth.IsEmailWhitelisted(user.Email) { tlog.App.Warn().Str("email", user.Email).Msg("Email not whitelisted") + tlog.AuditLoginFailure(c, user.Email, req.Provider, "email not whitelisted") queries, err := query.Values(config.UnauthorizedQuery{ Username: user.Email, diff --git a/internal/controller/user_controller.go b/internal/controller/user_controller.go index e35048b7..73478fa5 100644 --- a/internal/controller/user_controller.go +++ b/internal/controller/user_controller.go @@ -67,7 +67,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { if isLocked { tlog.App.Warn().Str("username", req.Username).Msg("Account is locked due to too many failed login attempts") - tlog.AuditLoginFailure(c, req.Username, "username") + tlog.AuditLoginFailure(c, req.Username, "username", "account locked") c.Writer.Header().Add("x-tinyauth-lock-locked", "true") c.Writer.Header().Add("x-tinyauth-lock-reset", time.Now().Add(time.Duration(remaining)*time.Second).Format(time.RFC3339)) c.JSON(429, gin.H{ @@ -82,7 +82,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { if userSearch.Type == "unknown" { tlog.App.Warn().Str("username", req.Username).Msg("User not found") controller.auth.RecordLoginAttempt(req.Username, false) - tlog.AuditLoginFailure(c, req.Username, "username") + tlog.AuditLoginFailure(c, req.Username, "username", "user not found") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -93,7 +93,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { if !controller.auth.VerifyUser(userSearch, req.Password) { tlog.App.Warn().Str("username", req.Username).Msg("Invalid password") controller.auth.RecordLoginAttempt(req.Username, false) - tlog.AuditLoginFailure(c, req.Username, "username") + tlog.AuditLoginFailure(c, req.Username, "username", "invalid password") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -235,7 +235,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { if !ok { tlog.App.Warn().Str("username", context.Username).Msg("Invalid TOTP code") controller.auth.RecordLoginAttempt(context.Username, false) - tlog.AuditLoginFailure(c, context.Username, "totp") + tlog.AuditLoginFailure(c, context.Username, "totp", "invalid totp code") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", diff --git a/internal/service/oauth_broker_service.go b/internal/service/oauth_broker_service.go index 194c4315..76c23e92 100644 --- a/internal/service/oauth_broker_service.go +++ b/internal/service/oauth_broker_service.go @@ -49,7 +49,7 @@ func (broker *OAuthBrokerService) Init() error { for name, service := range broker.services { err := service.Init() if err != nil { - tlog.App.Error().Err(err).Msgf("Failed to initialize OAuth service: %T", name) + tlog.App.Error().Err(err).Msgf("Failed to initialize OAuth service: %s", name) return err } tlog.App.Info().Str("service", name).Msg("Initialized OAuth service") diff --git a/internal/utils/tlog/log_audit.go b/internal/utils/tlog/log_audit.go index d0c3fb02..e9829609 100644 --- a/internal/utils/tlog/log_audit.go +++ b/internal/utils/tlog/log_audit.go @@ -12,7 +12,7 @@ func AuditLoginSuccess(c *gin.Context, username, provider string) { Send() } -func AuditLoginFailure(c *gin.Context, username, provider string) { +func AuditLoginFailure(c *gin.Context, username, provider string, reason string) { Audit.Warn(). Str("event", "login"). Str("result", "failure"). From 86616990f7855c2e9688d04845d695d5b6ffb667 Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 23:08:01 -0500 Subject: [PATCH 6/7] fix: ensure correct audit caller --- internal/utils/tlog/log_audit.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/internal/utils/tlog/log_audit.go b/internal/utils/tlog/log_audit.go index e9829609..d5ef215d 100644 --- a/internal/utils/tlog/log_audit.go +++ b/internal/utils/tlog/log_audit.go @@ -2,8 +2,11 @@ package tlog import "github.com/gin-gonic/gin" +// functions here use CallerSkipFrame to ensure correct caller info is logged + func AuditLoginSuccess(c *gin.Context, username, provider string) { Audit.Info(). + CallerSkipFrame(1). Str("event", "login"). Str("result", "success"). Str("username", username). @@ -14,6 +17,7 @@ func AuditLoginSuccess(c *gin.Context, username, provider string) { func AuditLoginFailure(c *gin.Context, username, provider string, reason string) { Audit.Warn(). + CallerSkipFrame(1). Str("event", "login"). Str("result", "failure"). Str("username", username). @@ -24,6 +28,7 @@ func AuditLoginFailure(c *gin.Context, username, provider string, reason string) func AuditLogout(c *gin.Context, username, provider string) { Audit.Info(). + CallerSkipFrame(1). Str("event", "logout"). Str("result", "success"). Str("username", username). From 87898c613e46be218b392ffcd528ed938ced1132 Mon Sep 17 00:00:00 2001 From: pushpinderbal Date: Sun, 11 Jan 2026 23:12:44 -0500 Subject: [PATCH 7/7] fix: include reason in audit login failure logs --- internal/utils/tlog/log_audit.go | 1 + 1 file changed, 1 insertion(+) diff --git a/internal/utils/tlog/log_audit.go b/internal/utils/tlog/log_audit.go index d5ef215d..115d41fe 100644 --- a/internal/utils/tlog/log_audit.go +++ b/internal/utils/tlog/log_audit.go @@ -23,6 +23,7 @@ func AuditLoginFailure(c *gin.Context, username, provider string, reason string) Str("username", username). Str("provider", provider). Str("ip", c.ClientIP()). + Str("reason", reason). Send() }