From 53bd413046d31b808b214200add1a49818a57874 Mon Sep 17 00:00:00 2001 From: Pushpinder Singh <53684951+pushpinderbal@users.noreply.github.com> Date: Thu, 15 Jan 2026 08:57:19 -0500 Subject: [PATCH] feat: configurable component-level logging (#575) * 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. * refactor: update logging implementation to use new logger structure * 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. * refactor: update logging configuration in environment files * fix: adding coderabbit suggestions * fix: ensure correct audit caller * fix: include reason in audit login failure logs --- .env.example | 17 +++- cmd/tinyauth/create.go | 11 +-- cmd/tinyauth/generate.go | 12 +-- cmd/tinyauth/healthcheck.go | 9 +- cmd/tinyauth/tinyauth.go | 43 +++++---- cmd/tinyauth/verify.go | 13 +-- config.example.yaml | 20 +++- internal/bootstrap/app_bootstrap.go | 47 +++++----- internal/bootstrap/service_bootstrap.go | 5 +- internal/config/config.go | 20 +++- internal/controller/context_controller.go | 8 +- .../controller/context_controller_test.go | 3 + internal/controller/oauth_controller.go | 45 ++++----- internal/controller/proxy_controller.go | 42 ++++----- internal/controller/proxy_controller_test.go | 3 + internal/controller/user_controller.go | 53 ++++++----- internal/controller/user_controller_test.go | 3 + internal/middleware/context_middleware.go | 22 ++--- internal/middleware/zerolog_middleware.go | 4 +- internal/service/access_controls_service.go | 10 +- internal/service/auth_service.go | 54 +++++------ 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 | 39 ++++++++ internal/utils/tlog/log_wrapper.go | 86 +++++++++++++++++ internal/utils/tlog/log_wrapper_test.go | 93 +++++++++++++++++++ 28 files changed, 486 insertions(+), 214 deletions(-) create mode 100644 internal/utils/tlog/log_audit.go create mode 100644 internal/utils/tlog/log_wrapper.go create mode 100644 internal/utils/tlog/log_wrapper_test.go diff --git a/.env.example b/.env.example index 607ce08..ec75300 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,21 @@ 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" +TINYAUTH_LOG_STREAMS_AUDIT_LEVEL="info" # Server Configuration diff --git a/cmd/tinyauth/create.go b/cmd/tinyauth/create.go index 6179f1d..8e7139b 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/tlog" "github.com/traefik/paerser/cli" "golang.org/x/crypto/bcrypt" ) @@ -43,7 +40,7 @@ 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) + tlog.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( @@ -77,7 +74,7 @@ func createUserCmd() *cli.Command { return errors.New("username and password cannot be empty") } - log.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 { @@ -90,7 +87,7 @@ func createUserCmd() *cli.Command { passwdStr = strings.ReplaceAll(passwdStr, "$", "$$") } - log.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 63eb671..0a63261 100644 --- a/cmd/tinyauth/generate.go +++ b/cmd/tinyauth/generate.go @@ -5,15 +5,13 @@ import ( "fmt" "os" "strings" - "time" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "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 +40,7 @@ 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) + tlog.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( @@ -91,9 +89,9 @@ func generateTotpCmd() *cli.Command { secret := key.Secret() - log.Info().Str("secret", secret).Msg("Generated TOTP secret") + tlog.App.Info().Str("secret", secret).Msg("Generated TOTP secret") - log.Info().Msg("Generated QR code") + tlog.App.Info().Msg("Generated QR code") config := qrterminal.Config{ Level: qrterminal.L, @@ -112,7 +110,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.") + 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 7b2fdcb..ca224e3 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/tlog" "github.com/traefik/paerser/cli" ) @@ -27,7 +26,7 @@ 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) + tlog.NewSimpleLogger().Init() appUrl := os.Getenv("TINYAUTH_APPURL") @@ -39,7 +38,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") + tlog.App.Info().Str("app_url", appUrl).Msg("Performing health check") client := http.Client{ Timeout: 30 * time.Second, @@ -77,7 +76,7 @@ func healthcheckCmd() *cli.Command { return fmt.Errorf("failed to decode response: %w", err) } - log.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 7d0dbf7..c1e652d 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/loaders" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" - "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,24 @@ func NewTinyauthCmdConfiguration() *config.Config { Insecure: false, SearchFilter: "(uid=%s)", }, + 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,25 +116,14 @@ func main() { } func runCmd(cfg config.Config) error { - logLevel, err := zerolog.ParseLevel(strings.ToLower(cfg.LogLevel)) + logger := tlog.NewLogger(cfg.Log) + logger.Init() - if err != nil { - log.Error().Err(err).Msg("Invalid or missing log level, defaulting to info") - } else { - zerolog.SetGlobalLevel(logLevel) - } - - log.Logger = log.With().Caller().Logger() - - if !cfg.LogJSON { - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}) - } - - log.Info().Str("version", config.Version).Msg("Starting tinyauth") + tlog.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 9634808..aa98cbd 100644 --- a/cmd/tinyauth/verify.go +++ b/cmd/tinyauth/verify.go @@ -3,15 +3,12 @@ package main import ( "errors" "fmt" - "os" - "time" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "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 +44,7 @@ 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) + tlog.NewSimpleLogger().Init() if tCfg.Interactive { form := huh.NewForm( @@ -101,9 +98,9 @@ func verifyUserCmd() *cli.Command { if user.TotpSecret == "" { if tCfg.Totp != "" { - log.Warn().Msg("User does not have TOTP secret") + tlog.App.Warn().Msg("User does not have TOTP secret") } - log.Info().Msg("User verified") + tlog.App.Info().Msg("User verified") return nil } @@ -113,7 +110,7 @@ func verifyUserCmd() *cli.Command { return fmt.Errorf("TOTP code incorrect") } - log.Info().Msg("User verified") + tlog.App.Info().Msg("User verified") return nil }, diff --git a/config.example.yaml b/config.example.yaml index 26e56d5..fecc823 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,22 @@ 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: + enabled: true + level: "warn" + http: + enabled: true + level: "debug" + audit: + enabled: false + level: "info" # Server Configuration server: diff --git a/internal/bootstrap/app_bootstrap.go b/internal/bootstrap/app_bootstrap.go index 414beea..20355fc 100644 --- a/internal/bootstrap/app_bootstrap.go +++ b/internal/bootstrap/app_bootstrap.go @@ -16,8 +16,7 @@ import ( "github.com/steveiliop56/tinyauth/internal/controller" "github.com/steveiliop56/tinyauth/internal/repository" "github.com/steveiliop56/tinyauth/internal/utils" - - "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" ) type BootstrapApp struct { @@ -103,13 +102,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") + 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) @@ -153,7 +152,7 @@ func (app *BootstrapApp) Setup() error { }) } - log.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") @@ -169,28 +168,28 @@ func (app *BootstrapApp) Setup() error { } // Start db cleanup routine - log.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 { - log.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 { - log.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) } } - log.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 { - log.Fatal().Err(err).Msg("Failed to start server") + tlog.App.Fatal().Err(err).Msg("Failed to start server") } return nil @@ -198,9 +197,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) + tlog.App.Info().Msgf("Starting server on %s", address) if err := router.Run(address); err != nil { - log.Fatal().Err(err).Msg("Failed to start server") + tlog.App.Fatal().Err(err).Msg("Failed to start server") } return nil @@ -223,7 +222,7 @@ func (app *BootstrapApp) heartbeat() { bodyJson, err := json.Marshal(body) if err != nil { - log.Error().Err(err).Msg("Failed to marshal heartbeat body") + tlog.App.Error().Err(err).Msg("Failed to marshal heartbeat body") return } @@ -234,12 +233,12 @@ func (app *BootstrapApp) heartbeat() { heartbeatURL := config.ApiServer + "/v1/instances/heartbeat" for ; true; <-ticker.C { - log.Debug().Msg("Sending heartbeat") + tlog.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") + tlog.App.Error().Err(err).Msg("Failed to create heartbeat request") continue } @@ -248,14 +247,14 @@ func (app *BootstrapApp) heartbeat() { res, err := client.Do(req) if err != nil { - log.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 { - log.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") } } } @@ -266,10 +265,10 @@ func (app *BootstrapApp) dbCleanup(queries *repository.Queries) { ctx := context.Background() for ; true; <-ticker.C { - log.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 { - log.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 02dd453..e68c2f2 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/tlog" ) 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") + tlog.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 920288d..62e06c9 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,23 @@ 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"` + Streams LogStreams `description:"Configuration for specific log streams." yaml:"streams"` +} + +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 { ConfigFile string `description:"Path to config file." yaml:"-"` } diff --git a/internal/controller/context_controller.go b/internal/controller/context_controller.go index 181c2f6..3c6f008 100644 --- a/internal/controller/context_controller.go +++ b/internal/controller/context_controller.go @@ -5,9 +5,9 @@ import ( "net/url" "github.com/steveiliop56/tinyauth/internal/utils" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" "github.com/gin-gonic/gin" - "github.com/rs/zerolog/log" ) type UserContextResponse struct { @@ -61,7 +61,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.") + tlog.App.Warn().Msg("UI warnings are disabled. This may expose users to security risks. Proceed with caution.") } return &ContextController{ @@ -94,7 +94,7 @@ func (controller *ContextController) userContextHandler(c *gin.Context) { } if err != nil { - log.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 @@ -108,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 { - log.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 7dee2c8..1a28e54 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/tlog" "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) { + tlog.NewSimpleLogger().Init() + // Setup gin.SetMode(gin.TestMode) router := gin.Default() diff --git a/internal/controller/oauth_controller.go b/internal/controller/oauth_controller.go index 3635e85..8dfd7a2 100644 --- a/internal/controller/oauth_controller.go +++ b/internal/controller/oauth_controller.go @@ -9,10 +9,10 @@ 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" - "github.com/rs/zerolog/log" ) type OAuthRequest struct { @@ -54,7 +54,7 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - log.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", @@ -65,7 +65,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) + tlog.App.Warn().Msgf("OAuth provider not found: %s", req.Provider) c.JSON(404, gin.H{ "status": 404, "message": "Not Found", @@ -82,12 +82,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") + tlog.App.Warn().Str("redirect_uri", redirectURI).Msg("Unsafe redirect URI detected, ignoring") redirectURI = "" } if redirectURI != "" && isRedirectSafe { - log.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) } @@ -103,7 +103,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - log.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", @@ -115,7 +115,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") + 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 @@ -127,14 +127,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) + 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 { - log.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 } @@ -142,26 +142,27 @@ 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") + 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 == "" { - log.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) { - log.Warn().Str("email", user.Email).Msg("Email not whitelisted") + 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, }) if err != nil { - log.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 } @@ -173,20 +174,20 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { var name string if strings.TrimSpace(user.Name) != "" { - log.Debug().Msg("Using name from OAuth provider") + tlog.App.Debug().Msg("Using name from OAuth provider") name = user.Name } else { - log.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) != "" { - log.Debug().Msg("Using preferred username from OAuth provider") + tlog.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") + tlog.App.Debug().Msg("No preferred username from OAuth provider, using pseudo username") username = strings.Replace(user.Email, "@", "_", -1) } @@ -200,20 +201,22 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { OAuthSub: user.Sub, } - log.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 { - log.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) { - log.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 } @@ -223,7 +226,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) { }) if err != nil { - log.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 2520bfb..bb62712 100644 --- a/internal/controller/proxy_controller.go +++ b/internal/controller/proxy_controller.go @@ -9,10 +9,10 @@ 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" - "github.com/rs/zerolog/log" ) var SupportedProxies = []string{"nginx", "traefik", "caddy", "envoy"} @@ -52,7 +52,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { err := c.BindUri(&req) if err != nil { - log.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", @@ -61,7 +61,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { } if !slices.Contains(SupportedProxies, req.Proxy) { - log.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", @@ -73,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 { - log.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, @@ -85,9 +85,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") + tlog.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") + tlog.App.Debug().Msg("Request identified as (most likely) coming from a non-browser client") } uri := c.Request.Header.Get("X-Forwarded-Uri") @@ -98,12 +98,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") + tlog.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") + tlog.App.Trace().Interface("acls", acls).Msg("ACLs for resource") clientIP := c.ClientIP() @@ -119,13 +119,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") + tlog.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") + tlog.App.Debug().Msg("Authentication disabled for resource, allowing access") controller.setHeaders(c, acls) c.JSON(200, gin.H{ "status": 200, @@ -149,7 +149,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.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 } @@ -163,7 +163,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") + tlog.App.Debug().Msg("No user context found in request, treating as not logged in") userContext = config.UserContext{ IsLoggedIn: false, } @@ -171,10 +171,10 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { userContext = context } - log.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 { - log.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 } @@ -182,7 +182,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") + 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{ @@ -197,7 +197,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.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 } @@ -216,7 +216,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") + 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{ @@ -232,7 +232,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.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 } @@ -276,7 +276,7 @@ func (controller *ProxyController) proxyHandler(c *gin.Context) { }) if err != nil { - log.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 } @@ -290,14 +290,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") + 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 != "" { - log.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 57711fc..cc6a3e4 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/tlog" "github.com/gin-gonic/gin" "gotest.tools/v3/assert" ) func setupProxyController(t *testing.T, middlewares *[]gin.HandlerFunc) (*gin.Engine, *httptest.ResponseRecorder, *service.AuthService) { + tlog.NewSimpleLogger().Init() + // Setup gin.SetMode(gin.TestMode) router := gin.Default() diff --git a/internal/controller/user_controller.go b/internal/controller/user_controller.go index 5670dd2..73478fa 100644 --- a/internal/controller/user_controller.go +++ b/internal/controller/user_controller.go @@ -8,10 +8,10 @@ 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" - "github.com/rs/zerolog/log" ) type LoginRequest struct { @@ -53,7 +53,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { err := c.ShouldBindJSON(&req) if err != nil { - log.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", @@ -61,12 +61,13 @@ func (controller *UserController) loginHandler(c *gin.Context) { return } - log.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 { - log.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", "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{ @@ -79,8 +80,9 @@ 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") + tlog.App.Warn().Str("username", req.Username).Msg("User not found") controller.auth.RecordLoginAttempt(req.Username, false) + tlog.AuditLoginFailure(c, req.Username, "username", "user not found") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -89,8 +91,9 @@ func (controller *UserController) loginHandler(c *gin.Context) { } if !controller.auth.VerifyUser(userSearch, req.Password) { - log.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", "invalid password") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -98,7 +101,8 @@ func (controller *UserController) loginHandler(c *gin.Context) { return } - log.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) @@ -106,7 +110,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") + 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, @@ -117,7 +121,7 @@ func (controller *UserController) loginHandler(c *gin.Context) { }) if err != nil { - log.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", @@ -141,12 +145,12 @@ func (controller *UserController) loginHandler(c *gin.Context) { Provider: "username", } - log.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 { - log.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", @@ -161,10 +165,15 @@ func (controller *UserController) loginHandler(c *gin.Context) { } func (controller *UserController) logoutHandler(c *gin.Context) { - log.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", @@ -176,7 +185,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { err := c.ShouldBindJSON(&req) if err != nil { - log.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", @@ -187,7 +196,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") + tlog.App.Error().Err(err).Msg("Failed to get user context") c.JSON(500, gin.H{ "status": 500, "message": "Internal Server Error", @@ -196,7 +205,7 @@ func (controller *UserController) totpHandler(c *gin.Context) { } if !context.TotpPending { - log.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", @@ -204,12 +213,12 @@ func (controller *UserController) totpHandler(c *gin.Context) { return } - log.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 { - log.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{ @@ -224,8 +233,9 @@ 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") + tlog.App.Warn().Str("username", context.Username).Msg("Invalid TOTP code") controller.auth.RecordLoginAttempt(context.Username, false) + tlog.AuditLoginFailure(c, context.Username, "totp", "invalid totp code") c.JSON(401, gin.H{ "status": 401, "message": "Unauthorized", @@ -233,7 +243,8 @@ func (controller *UserController) totpHandler(c *gin.Context) { return } - log.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) @@ -244,12 +255,12 @@ func (controller *UserController) totpHandler(c *gin.Context) { Provider: "username", } - log.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 { - log.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 99768c7..ef10487 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/tlog" "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) { + tlog.NewSimpleLogger().Init() + // Setup gin.SetMode(gin.TestMode) router := gin.Default() diff --git a/internal/middleware/context_middleware.go b/internal/middleware/context_middleware.go index a6bddc9..22749a7 100644 --- a/internal/middleware/context_middleware.go +++ b/internal/middleware/context_middleware.go @@ -8,9 +8,9 @@ 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/rs/zerolog/log" ) type ContextMiddlewareConfig struct { @@ -40,7 +40,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") + tlog.App.Debug().Err(err).Msg("No valid session cookie found") goto basic } @@ -62,7 +62,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") + tlog.App.Debug().Msg("User from session cookie not found") m.auth.DeleteSessionCookie(c) goto basic } @@ -81,13 +81,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") + tlog.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") + tlog.App.Debug().Msg("Email from session cookie not whitelisted") m.auth.DeleteSessionCookie(c) goto basic } @@ -112,7 +112,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { basic := m.auth.GetBasicAuth(c) if basic == nil { - log.Debug().Msg("No basic auth provided") + tlog.App.Debug().Msg("No basic auth provided") c.Next() return } @@ -120,7 +120,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) + 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() @@ -131,14 +131,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") + 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) - log.Debug().Msg("Invalid password for basic auth user") + tlog.App.Debug().Msg("Invalid password for basic auth user") c.Next() return } @@ -147,7 +147,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { switch userSearch.Type { case "local": - log.Debug().Msg("Basic auth user is local") + tlog.App.Debug().Msg("Basic auth user is local") user := m.auth.GetLocalUser(basic.Username) @@ -162,7 +162,7 @@ func (m *ContextMiddleware) Middleware() gin.HandlerFunc { c.Next() return case "ldap": - log.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 f3ca485..b88556b 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/tlog" ) var ( @@ -49,7 +49,7 @@ func (m *ZerologMiddleware) Middleware() gin.HandlerFunc { latency := time.Since(tStart).String() - subLogger := log.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 74117ea..087ce88 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/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 { - log.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 { - log.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 { - log.Debug().Msg("Using ACls from static configuration") + tlog.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") + 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 6d829c6..cddb613 100644 --- a/internal/service/auth_service.go +++ b/internal/service/auth_service.go @@ -12,10 +12,10 @@ 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" - "github.com/rs/zerolog/log" "golang.org/x/crypto/bcrypt" ) @@ -73,7 +73,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") + tlog.App.Warn().Err(err).Str("username", username).Msg("Failed to search for user in LDAP") return config.UserSearch{ Type: "error", } @@ -99,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 { - log.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 { - log.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: - log.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 } - log.Warn().Str("username", search.Username).Msg("User authentication failed") + tlog.App.Warn().Str("username", search.Username).Msg("User authentication failed") return false } @@ -127,7 +127,7 @@ func (auth *AuthService) GetLocalUser(username string) config.User { } } - log.Warn().Str("username", username).Msg("Local user not found") + tlog.App.Warn().Str("username", username).Msg("Local user not found") return config.User{} } @@ -182,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) - log.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") } } @@ -277,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) - log.Trace().Str("username", session.Username).Msg("Session cookie refreshed") + tlog.App.Trace().Str("username", session.Username).Msg("Session cookie refreshed") return nil } @@ -322,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 { - log.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") } @@ -331,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 { - log.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") } @@ -355,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 { - log.Debug().Msg("Checking OAuth whitelist") + tlog.App.Debug().Msg("Checking OAuth whitelist") return utils.CheckFilter(acls.OAuth.Whitelist, context.Email) } if acls.Users.Block != "" { - log.Debug().Msg("Checking blocked users") + tlog.App.Debug().Msg("Checking blocked users") if utils.CheckFilter(acls.Users.Block, context.Username) { return false } } - log.Debug().Msg("Checking users") + tlog.App.Debug().Msg("Checking users") return utils.CheckFilter(acls.Users.Allow, context.Username) } @@ -377,19 +377,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") + 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)) { - log.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 } } - log.Debug().Msg("No groups matched") + tlog.App.Debug().Msg("No groups matched") return false } @@ -426,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 { - log.Debug().Msg("No basic auth provided") + tlog.App.Debug().Msg("No basic auth provided") return nil } return &config.User{ @@ -443,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 { - log.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 { - log.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 } } @@ -455,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 { - log.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 { - log.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 { - log.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 } - log.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 } @@ -477,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 { - log.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 { - log.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 } } - log.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 a0693b2..fc96fb9 100644 --- a/internal/service/docker_service.go +++ b/internal/service/docker_service.go @@ -6,10 +6,10 @@ import ( "github.com/steveiliop56/tinyauth/internal/config" "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" - "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") + 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 - log.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 { - log.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 { - log.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 { - log.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 } } } - log.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 ac3252c..ef17b0e 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/tlog" - "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") + 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 b64c1df..fb03778 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/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 - log.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 { - log.Error().Err(err).Msg("LDAP connection heartbeat failed") + tlog.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") + tlog.App.Error().Err(reconnectErr).Msg("Failed to reconnect to LDAP server") continue } - log.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 { - log.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 { - log.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 2c7d4cf..76c23e9 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/tlog" - "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) + tlog.App.Error().Err(err).Msgf("Failed to initialize OAuth service: %s", name) return err } - log.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 0000000..115d41f --- /dev/null +++ b/internal/utils/tlog/log_audit.go @@ -0,0 +1,39 @@ +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). + Str("provider", provider). + Str("ip", c.ClientIP()). + Send() +} + +func AuditLoginFailure(c *gin.Context, username, provider string, reason string) { + Audit.Warn(). + CallerSkipFrame(1). + Str("event", "login"). + Str("result", "failure"). + Str("username", username). + Str("provider", provider). + Str("ip", c.ClientIP()). + Str("reason", reason). + Send() +} + +func AuditLogout(c *gin.Context, username, provider string) { + Audit.Info(). + CallerSkipFrame(1). + Str("event", "logout"). + Str("result", "success"). + Str("username", username). + Str("provider", provider). + Str("ip", c.ClientIP()). + Send() +} diff --git a/internal/utils/tlog/log_wrapper.go b/internal/utils/tlog/log_wrapper.go new file mode 100644 index 0000000..ef24bf7 --- /dev/null +++ b/internal/utils/tlog/log_wrapper.go @@ -0,0 +1,86 @@ +package tlog + +import ( + "os" + "strings" + "time" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" + "github.com/steveiliop56/tinyauth/internal/config" +) + +type Logger struct { + Audit zerolog.Logger + HTTP zerolog.Logger + App zerolog.Logger +} + +var ( + Audit zerolog.Logger + HTTP zerolog.Logger + App zerolog.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{ + Out: os.Stderr, + TimeFormat: time.RFC3339, + }) + } + + return &Logger{ + Audit: createLogger("audit", cfg.Streams.Audit, baseLogger), + HTTP: createLogger("http", cfg.Streams.HTTP, baseLogger), + App: createLogger("app", cfg.Streams.App, baseLogger), + } +} + +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 (l *Logger) Init() { + 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() + } + subLogger := baseLogger.With().Str("log_stream", component).Logger() + // override level if specified, otherwise use base level + if streamCfg.Level != "" { + subLogger = subLogger.Level(parseLogLevel(streamCfg.Level)) + } + return subLogger +} + +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 +} diff --git a/internal/utils/tlog/log_wrapper_test.go b/internal/utils/tlog/log_wrapper_test.go new file mode 100644 index 0000000..1ba521c --- /dev/null +++ b/internal/utils/tlog/log_wrapper_test.go @@ -0,0 +1,93 @@ +package tlog_test + +import ( + "bytes" + "encoding/json" + "testing" + + "github.com/steveiliop56/tinyauth/internal/config" + "github.com/steveiliop56/tinyauth/internal/utils/tlog" + + "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 := tlog.NewLogger(cfg) + + assert.Assert(t, logger != 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 := tlog.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 := tlog.NewSimpleLogger() + logger.Init() + + assert.Assert(t, tlog.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 := tlog.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 := tlog.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"]) +}