From ba5516bfb26f6a352f02fe7c46e1c471f48e5b3f Mon Sep 17 00:00:00 2001 From: Edwin <18327273+thinkbig1979@users.noreply.github.com> Date: Fri, 31 Jul 2026 21:13:33 +0200 Subject: [PATCH] feat(logging): wire LOG_LEVEL into slog, add LOG_FORMAT=json, correlate requests LOG_LEVEL was dead configuration. config.Load declared it, defaulted it, read the env var and logged it back out at startup, and nothing consumed it: grepping the non-test backend for slog.SetDefault, NewTextHandler and NewJSONHandler returned zero hits. The process ran on slog's default handler at the default level for its entire life. Setting LOG_LEVEL=debug in production therefore did nothing at all, which is worse than not offering the knob: an operator turns it up during an incident, sees no change, and concludes the problem is elsewhere. What it suppressed was exactly the diagnostic layer -- the slog.Debug calls in the WebSocket, terminal and git paths, which are the entire evidence base when a user reports that their terminal dropped or the logs pane went blank. Three changes, cheapest to make together: internal/logging installs the process-wide handler. main() bootstraps it from the environment BEFORE config.Load, so config's own startup lines -- including the volume-path-identity warning -- go through the configured handler rather than slog's default, then re-installs it from the validated config, which stays authoritative. An unrecognised LOG_LEVEL or LOG_FORMAT stops the process at startup instead of silently becoming info. LOG_FORMAT selects text (default, so existing deployments are unchanged) or json. The codebase already logs structured key-value pairs throughout; only the encoder was missing. middleware.RequestID assigns each request a UUID, exposes it on the gin context, returns it in X-Request-ID and puts it in the HTTP log line. ActionLogger.LogWithRequest carries it onto the audit row (migration 10 adds a nullable action_log.request_id), so a 500 in the HTTP log can be joined to the action it produced. An inbound X-Request-ID is honoured only when it parses as a UUID -- the value lands in log lines and audit rows, where an arbitrary caller-supplied string could forge entries or bloat the database. Handler helpers now take the gin context rather than a pre-extracted userID, which also replaces eleven userID.(string) type assertions with userIDFrom's "anonymous" fallback. Verified against the running binary, not just in unit tests: LOG_LEVEL=bogus -> exits 1, 'unrecognised log level "bogus" (want one of debug, error, info, warn)' LOG_LEVEL=warn -> 0 INFO lines, WARN lines still present LOG_LEVEL=debug -> 'Pulling git changes (CLI)' appears, one of the lines the bead names as permanently invisible LOG_FORMAT=json -> 19 of 19 startup lines parse as JSON request id -> X-Request-Id: 6d4ac13a-... matched the HTTP log line's request_id and the action_log row for that same pull agent-os-7li --- .env.example | 7 ++ backend/.env.example | 8 ++ backend/cmd/server/main.go | 22 +++- backend/internal/config/config.go | 22 +++- backend/internal/config/config_test.go | 87 +++++++++++++ backend/internal/database/audit.go | 27 ++-- backend/internal/database/migrations.go | 13 ++ backend/internal/handlers/compose.go | 11 +- backend/internal/handlers/env.go | 11 +- backend/internal/handlers/git.go | 8 +- backend/internal/handlers/respond.go | 3 +- backend/internal/handlers/stack_crud.go | 8 +- backend/internal/handlers/stack_lifecycle.go | 12 +- backend/internal/handlers/stacks.go | 5 +- backend/internal/logging/logging.go | 118 ++++++++++++++++++ backend/internal/logging/logging_test.go | 117 +++++++++++++++++ backend/internal/middleware/logging.go | 1 + backend/internal/middleware/requestid.go | 57 +++++++++ backend/internal/middleware/requestid_test.go | 112 +++++++++++++++++ backend/internal/models/models.go | 1 + backend/internal/services/actionlog.go | 10 ++ backend/internal/services/actionlog_test.go | 53 ++++++++ 22 files changed, 667 insertions(+), 46 deletions(-) create mode 100644 backend/internal/config/config_test.go create mode 100644 backend/internal/logging/logging.go create mode 100644 backend/internal/logging/logging_test.go create mode 100644 backend/internal/middleware/requestid.go create mode 100644 backend/internal/middleware/requestid_test.go create mode 100644 backend/internal/services/actionlog_test.go diff --git a/.env.example b/.env.example index c0c82ce..932e8cf 100644 --- a/.env.example +++ b/.env.example @@ -31,7 +31,14 @@ PORT=5001 DATA_DIR=/app/data # Log level: debug, info, warn, error (default: info) +# Log format: text or json (default: text) +# An unrecognised value stops the server at startup rather than silently +# falling back, so a typo is visible immediately. Use json when shipping to an +# aggregator (Loki, Elasticsearch); text is easier to read at a terminal. +# Every log line carries a request_id, also returned in the X-Request-ID +# response header and recorded on the matching action_log row. LOG_LEVEL=info +LOG_FORMAT=text # Disable authentication - only safe on trusted networks! # When enabled, access is restricted to TRUSTED_NETWORKS diff --git a/backend/.env.example b/backend/.env.example index d6f473e..434fc76 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -9,7 +9,15 @@ STORAGE_KEY= # Server Configuration PORT=5001 + +# Logging. LOG_LEVEL is one of debug, info, warn, error; LOG_FORMAT is text or +# json. An unrecognised value stops the server at startup rather than silently +# falling back, so a typo is visible immediately. Use json when shipping to an +# aggregator (Loki, Elasticsearch); text is easier to read at a terminal. +# Every log line carries a request_id, also returned in the X-Request-ID +# response header and recorded on the matching action_log row. LOG_LEVEL=info +LOG_FORMAT=text # Stacks Directory (where Docker Compose files are stored) STACKS_DIR=/opt/stacks diff --git a/backend/cmd/server/main.go b/backend/cmd/server/main.go index a149214..2a3c99d 100644 --- a/backend/cmd/server/main.go +++ b/backend/cmd/server/main.go @@ -21,6 +21,7 @@ import ( "github.com/thinkbig1979/capstan/backend/internal/config" "github.com/thinkbig1979/capstan/backend/internal/database" "github.com/thinkbig1979/capstan/backend/internal/handlers" + "github.com/thinkbig1979/capstan/backend/internal/logging" "github.com/thinkbig1979/capstan/backend/internal/middleware" "github.com/thinkbig1979/capstan/backend/internal/services" ) @@ -86,13 +87,30 @@ func isLocalhost(c *gin.Context) bool { } func main() { - slog.Info("Starting Capstan backend") + // Bootstrap the logger from the environment before config.Load, so that + // config's own startup lines — including the volume-path-identity warning — + // go through the configured handler instead of slog's default. An + // unrecognised value stops the process here rather than silently becoming + // info (agent-os-7li). + if err := logging.ConfigureFromEnv(os.Stderr); err != nil { + log.Fatal("Failed to configure logging:", err) + } cfg, err := config.Load() if err != nil { log.Fatal("Failed to load config:", err) } + // Re-install from the validated config, which is the authoritative source. + if err := logging.Configure(os.Stderr, cfg.LogLevel, cfg.LogFormat); err != nil { + log.Fatal("Failed to configure logging:", err) + } + + slog.Info("Starting Capstan backend", + "log_level", cfg.LogLevel, + "log_format", cfg.LogFormat, + ) + db, err := database.NewWithMigrationsAndEncryptor(cfg.DataDir, services.NewTokenEncryptorOrDefault(cfg.StorageKey, cfg.JWTSecret)) if err != nil { log.Fatal("Failed to initialize database:", err) @@ -201,6 +219,8 @@ func main() { } r.Use(middleware.RecoveryMiddleware()) + // Before LoggingMiddleware: the HTTP log line carries the request ID. + r.Use(middleware.RequestID()) r.Use(middleware.LoggingMiddleware()) r.Use(middleware.BodySizeLimit()) r.Use(middleware.CORSMiddleware(cfg.CORSOrigins)) diff --git a/backend/internal/config/config.go b/backend/internal/config/config.go index 86c1e8f..a4915b2 100644 --- a/backend/internal/config/config.go +++ b/backend/internal/config/config.go @@ -5,6 +5,8 @@ import ( "os" "path/filepath" "strings" + + "github.com/thinkbig1979/capstan/backend/internal/logging" ) type StacksDirEntry struct { @@ -21,6 +23,7 @@ type Config struct { JWTSecret string StorageKey string LogLevel string + LogFormat string GitSSHKey string GitHTTPSToken string GitHTTPSUser string @@ -48,7 +51,8 @@ type Config struct { func Load() (*Config, error) { cfg := &Config{ Port: "5001", - LogLevel: "info", + LogLevel: logging.DefaultLevel, + LogFormat: logging.FormatText, GitSSHKey: filepath.Join(os.Getenv("HOME"), ".ssh", "id_rsa"), GitHTTPSUser: "git", AuthDisabled: os.Getenv("AUTH_DISABLED") == "true", @@ -84,6 +88,10 @@ func Load() (*Config, error) { cfg.LogLevel = logLevel } + if logFormat := os.Getenv("LOG_FORMAT"); logFormat != "" { + cfg.LogFormat = logFormat + } + if gitSSHKey := os.Getenv("GIT_SSH_KEY"); gitSSHKey != "" { cfg.GitSSHKey = gitSSHKey } @@ -140,6 +148,7 @@ func Load() (*Config, error) { "port", cfg.Port, "jwt_secret", "[REDACTED]", "log_level", cfg.LogLevel, + "log_format", cfg.LogFormat, "auth_disabled", cfg.AuthDisabled, ) @@ -167,6 +176,17 @@ func validate(cfg *Config) error { return &ConfigError{Field: "DATA_DIR", Message: "required"} } + // A typo here is caught at startup rather than silently defaulting to info. + // Silently falling back is how an operator turns logging up during an + // incident, sees no change, and concludes the problem is elsewhere. + if _, err := logging.ParseLevel(cfg.LogLevel); err != nil { + return &ConfigError{Field: "LOG_LEVEL", Message: err.Error()} + } + + if _, err := logging.ParseFormat(cfg.LogFormat); err != nil { + return &ConfigError{Field: "LOG_FORMAT", Message: err.Error()} + } + return nil } diff --git a/backend/internal/config/config_test.go b/backend/internal/config/config_test.go new file mode 100644 index 0000000..f618466 --- /dev/null +++ b/backend/internal/config/config_test.go @@ -0,0 +1,87 @@ +package config + +import ( + "strings" + "testing" +) + +// LOG_LEVEL used to be dead configuration — read, logged back out, never +// consumed and never validated. A typo silently produced info-level logging, +// which is how an operator turns logging up during an incident, sees no change, +// and concludes the problem is elsewhere (agent-os-7li). + +func newValidConfig() *Config { + return &Config{ + JWTSecret: strings.Repeat("k", 32), + StacksDir: "/opt/stacks", + DataDir: "/app/data", + LogLevel: "info", + LogFormat: "text", + } +} + +func TestValidate_RejectsUnknownLogLevel(t *testing.T) { + cfg := newValidConfig() + cfg.LogLevel = "verbose" + + err := validate(cfg) + if err == nil { + t.Fatal("expected LOG_LEVEL=verbose to be rejected, got nil") + } + if !strings.Contains(err.Error(), "LOG_LEVEL") { + t.Errorf("error should name the offending variable, got: %v", err) + } + if !strings.Contains(err.Error(), "verbose") { + t.Errorf("error should quote the offending value, got: %v", err) + } +} + +func TestValidate_RejectsUnknownLogFormat(t *testing.T) { + cfg := newValidConfig() + cfg.LogFormat = "logfmt" + + err := validate(cfg) + if err == nil { + t.Fatal("expected LOG_FORMAT=logfmt to be rejected, got nil") + } + if !strings.Contains(err.Error(), "LOG_FORMAT") { + t.Errorf("error should name the offending variable, got: %v", err) + } +} + +func TestValidate_AcceptsEveryDocumentedCombination(t *testing.T) { + for _, level := range []string{"debug", "info", "warn", "error"} { + for _, format := range []string{"text", "json"} { + cfg := newValidConfig() + cfg.LogLevel = level + cfg.LogFormat = format + if err := validate(cfg); err != nil { + t.Errorf("LOG_LEVEL=%s LOG_FORMAT=%s rejected: %v", level, format, err) + } + } + } +} + +// TestLoad_DefaultsAreValid guards against the defaults drifting away from the +// values validate accepts, which would make the server refuse to start with no +// logging env vars set at all. +func TestLoad_DefaultsAreValid(t *testing.T) { + cfg := newValidConfig() + cfg.LogLevel = "" + cfg.LogFormat = "" + + if err := validate(cfg); err == nil { + t.Fatal("empty values should not validate; Load fills them with defaults") + } + + defaults := &Config{ + JWTSecret: strings.Repeat("k", 32), + StacksDir: "/opt/stacks", + DataDir: "/app/data", + LogLevel: "info", // must match Load's default + LogFormat: "text", // must match Load's default + } + if err := validate(defaults); err != nil { + t.Errorf("Load's defaults do not pass validation: %v", err) + } +} diff --git a/backend/internal/database/audit.go b/backend/internal/database/audit.go index b56f494..a35a57c 100644 --- a/backend/internal/database/audit.go +++ b/backend/internal/database/audit.go @@ -19,14 +19,14 @@ func (d *DB) LogAction(log models.ActionLog) error { if log.StackID != "" { stackID = log.StackID } - query := `INSERT INTO action_log (id, user_id, stack_id, action, detail, created_at) - VALUES (?, ?, ?, ?, ?, ?)` - _, err := d.db.Exec(query, log.ID, log.UserID, stackID, log.Action, log.Detail, log.CreatedAt) + query := `INSERT INTO action_log (id, user_id, stack_id, action, detail, request_id, created_at) + VALUES (?, ?, ?, ?, ?, ?, ?)` + _, err := d.db.Exec(query, log.ID, log.UserID, stackID, log.Action, log.Detail, log.RequestID, log.CreatedAt) return err } func (d *DB) GetActionsByStack(stackID string, limit int) ([]models.ActionLog, error) { - query := `SELECT id, user_id, stack_id, action, detail, created_at + query := `SELECT id, user_id, stack_id, action, detail, request_id, created_at FROM action_log WHERE stack_id = ? ORDER BY created_at DESC LIMIT ?` rows, err := d.db.Query(query, stackID, limit) if err != nil { @@ -37,19 +37,20 @@ func (d *DB) GetActionsByStack(stackID string, limit int) ([]models.ActionLog, e actions := make([]models.ActionLog, 0) for rows.Next() { var action models.ActionLog - var stackID sql.NullString - err := rows.Scan(&action.ID, &action.UserID, &stackID, &action.Action, &action.Detail, &action.CreatedAt) + var stackID, requestID sql.NullString + err := rows.Scan(&action.ID, &action.UserID, &stackID, &action.Action, &action.Detail, &requestID, &action.CreatedAt) if err != nil { return nil, err } action.StackID = stackID.String + action.RequestID = requestID.String actions = append(actions, action) } return actions, nil } func (d *DB) GetRecentActions(limit int) ([]models.ActionLog, error) { - query := `SELECT id, user_id, stack_id, action, detail, created_at + query := `SELECT id, user_id, stack_id, action, detail, request_id, created_at FROM action_log ORDER BY created_at DESC LIMIT ?` rows, err := d.db.Query(query, limit) if err != nil { @@ -60,12 +61,13 @@ func (d *DB) GetRecentActions(limit int) ([]models.ActionLog, error) { actions := make([]models.ActionLog, 0) for rows.Next() { var action models.ActionLog - var stackID sql.NullString - err := rows.Scan(&action.ID, &action.UserID, &stackID, &action.Action, &action.Detail, &action.CreatedAt) + var stackID, requestID sql.NullString + err := rows.Scan(&action.ID, &action.UserID, &stackID, &action.Action, &action.Detail, &requestID, &action.CreatedAt) if err != nil { return nil, err } action.StackID = stackID.String + action.RequestID = requestID.String actions = append(actions, action) } return actions, nil @@ -123,7 +125,7 @@ func (d *DB) ListActionLogsFiltered(limit, offset int, f ActionLogFilter) ([]mod return nil, 0, err } - query := `SELECT id, user_id, stack_id, action, detail, created_at + query := `SELECT id, user_id, stack_id, action, detail, request_id, created_at FROM action_log` + whereClause + ` ORDER BY created_at DESC LIMIT ? OFFSET ?` queryArgs := append(append([]interface{}{}, args...), limit, offset) rows, err := d.db.Query(query, queryArgs...) @@ -135,12 +137,13 @@ func (d *DB) ListActionLogsFiltered(limit, offset int, f ActionLogFilter) ([]mod actions := make([]models.ActionLog, 0) for rows.Next() { var action models.ActionLog - var stackID sql.NullString - err := rows.Scan(&action.ID, &action.UserID, &stackID, &action.Action, &action.Detail, &action.CreatedAt) + var stackID, requestID sql.NullString + err := rows.Scan(&action.ID, &action.UserID, &stackID, &action.Action, &action.Detail, &requestID, &action.CreatedAt) if err != nil { return nil, 0, err } action.StackID = stackID.String + action.RequestID = requestID.String actions = append(actions, action) } return actions, total, nil diff --git a/backend/internal/database/migrations.go b/backend/internal/database/migrations.go index 3b3ab61..f87db75 100644 --- a/backend/internal/database/migrations.go +++ b/backend/internal/database/migrations.go @@ -266,6 +266,19 @@ DROP TABLE action_log_v8; CREATE INDEX IF NOT EXISTS idx_action_log_user_id ON action_log(user_id); CREATE INDEX IF NOT EXISTS idx_action_log_stack_id ON action_log(stack_id); CREATE INDEX IF NOT EXISTS idx_action_log_created_at ON action_log(created_at); +`, + }, + { + Version: 10, + Name: "action_log_request_id", + SQL: ` +-- Carries the per-request ID (see middleware.RequestID) onto the audit row, so +-- a 500 in the HTTP log can be joined to the action it produced. Nullable: rows +-- written before this migration, and by background jobs that serve no request, +-- legitimately have none. +ALTER TABLE action_log ADD COLUMN request_id TEXT; + +CREATE INDEX IF NOT EXISTS idx_action_log_request_id ON action_log(request_id); `, }, } diff --git a/backend/internal/handlers/compose.go b/backend/internal/handlers/compose.go index 41b468c..ab6c0f6 100644 --- a/backend/internal/handlers/compose.go +++ b/backend/internal/handlers/compose.go @@ -9,6 +9,7 @@ import ( "github.com/gin-gonic/gin" "github.com/thinkbig1979/capstan/backend/internal/config" "github.com/thinkbig1979/capstan/backend/internal/database" + "github.com/thinkbig1979/capstan/backend/internal/middleware" "github.com/thinkbig1979/capstan/backend/internal/models" "github.com/thinkbig1979/capstan/backend/internal/services" "github.com/thinkbig1979/capstan/backend/internal/truth" @@ -192,8 +193,7 @@ func (h *ComposeHandler) Put(c *gin.Context) { return } - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "update_compose", "Updated compose file: "+stack.ComposeFile) + h.logAction(c, id, "update_compose", "Updated compose file: "+stack.ComposeFile) c.JSON(http.StatusOK, ComposeSaveResponse{ Saved: true, @@ -245,8 +245,8 @@ func (h *ComposeHandler) Lint(c *gin.Context) { }) } -func (h *ComposeHandler) logAction(userID, stackID, action, detail string) { - h.actionLog.Log(userID, &stackID, action, detail) +func (h *ComposeHandler) logAction(c *gin.Context, stackID, action, detail string) { + h.actionLog.LogWithRequest(middleware.RequestIDFrom(c), userIDFrom(c), &stackID, action, detail) } // restoreEnv restores envPath to its pre-update state. If originalBytes is nil @@ -445,8 +445,7 @@ func (h *ComposeHandler) PutComposeAndEnv(c *gin.Context) { return } - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "update_compose_env", "Updated compose and env atomically") + h.logAction(c, id, "update_compose_env", "Updated compose and env atomically") details := map[string]any{ "compose": stack.ComposeFile, diff --git a/backend/internal/handlers/env.go b/backend/internal/handlers/env.go index 7db4a56..7d43d2c 100644 --- a/backend/internal/handlers/env.go +++ b/backend/internal/handlers/env.go @@ -12,6 +12,7 @@ import ( "github.com/gin-gonic/gin" "github.com/thinkbig1979/capstan/backend/internal/config" "github.com/thinkbig1979/capstan/backend/internal/database" + "github.com/thinkbig1979/capstan/backend/internal/middleware" "github.com/thinkbig1979/capstan/backend/internal/models" "github.com/thinkbig1979/capstan/backend/internal/services" "github.com/thinkbig1979/capstan/backend/internal/truth" @@ -196,8 +197,7 @@ func (h *EnvHandler) Put(c *gin.Context) { return } - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "update_env", "Updated env file: "+stack.EnvFile) + h.logAction(c, id, "update_env", "Updated env file: "+stack.EnvFile) renderResult(c, truth.Success("env file saved", truth.KV("filename", stack.EnvFile), @@ -284,8 +284,7 @@ func (h *EnvHandler) Create(c *gin.Context) { } } - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "create_env", "Created env file: "+envFileName) + h.logAction(c, id, "create_env", "Created env file: "+envFileName) c.JSON(http.StatusCreated, truth.Success("env file created", truth.KV("filename", envFileName), @@ -502,6 +501,6 @@ func (h *EnvHandler) isSensitiveKey(key string) bool { return false } -func (h *EnvHandler) logAction(userID, stackID, action, detail string) { - h.actionLog.Log(userID, &stackID, action, detail) +func (h *EnvHandler) logAction(c *gin.Context, stackID, action, detail string) { + h.actionLog.LogWithRequest(middleware.RequestIDFrom(c), userIDFrom(c), &stackID, action, detail) } diff --git a/backend/internal/handlers/git.go b/backend/internal/handlers/git.go index 7e049f3..64b4e67 100644 --- a/backend/internal/handlers/git.go +++ b/backend/internal/handlers/git.go @@ -11,6 +11,7 @@ import ( "github.com/gin-gonic/gin" "github.com/thinkbig1979/capstan/backend/internal/config" "github.com/thinkbig1979/capstan/backend/internal/database" + "github.com/thinkbig1979/capstan/backend/internal/middleware" "github.com/thinkbig1979/capstan/backend/internal/models" "github.com/thinkbig1979/capstan/backend/internal/pathutil" "github.com/thinkbig1979/capstan/backend/internal/services" @@ -145,9 +146,8 @@ func (h *GitHandler) Pull(c *gin.Context) { redeploy := c.Query("redeploy") == "true" ar, pullResult := h.git.PullVerified(absPath, redeploy, h.docker) - userID, _ := c.Get("userID") if pullResult != nil { - h.logGitAction(userID.(string), absPath, "pull", h.formatPullDetail(pullResult)) + h.logGitAction(c, absPath, "pull", h.formatPullDetail(pullResult)) } renderResult(c, ar) @@ -241,8 +241,8 @@ func (h *GitHandler) GetDiff(c *gin.Context) { }) } -func (h *GitHandler) logGitAction(userID, absPath, action, detail string) { - h.actionLog.Log(userID, nil, action, detail) +func (h *GitHandler) logGitAction(c *gin.Context, absPath, action, detail string) { + h.actionLog.LogWithRequest(middleware.RequestIDFrom(c), userIDFrom(c), nil, action, detail) } func parseQueryParamInt(value string, min, max int) (int, error) { diff --git a/backend/internal/handlers/respond.go b/backend/internal/handlers/respond.go index a7774ff..1b9ab30 100644 --- a/backend/internal/handlers/respond.go +++ b/backend/internal/handlers/respond.go @@ -4,6 +4,7 @@ import ( "net/http" "github.com/gin-gonic/gin" + "github.com/thinkbig1979/capstan/backend/internal/middleware" "github.com/thinkbig1979/capstan/backend/internal/models" "github.com/thinkbig1979/capstan/backend/internal/services" "github.com/thinkbig1979/capstan/backend/internal/truth" @@ -40,5 +41,5 @@ func userIDFrom(c *gin.Context) string { // logActionFromContext logs an action using the userID found on the gin // context, delegating to the given ActionLogger. func logActionFromContext(l *services.ActionLogger, c *gin.Context, stackID *string, action string, detail interface{}) { - l.Log(userIDFrom(c), stackID, action, detail) + l.LogWithRequest(middleware.RequestIDFrom(c), userIDFrom(c), stackID, action, detail) } diff --git a/backend/internal/handlers/stack_crud.go b/backend/internal/handlers/stack_crud.go index 6dc9c64..ad52959 100644 --- a/backend/internal/handlers/stack_crud.go +++ b/backend/internal/handlers/stack_crud.go @@ -203,8 +203,7 @@ func (h *StacksHandler) Create(c *gin.Context) { return } - userID, _ := c.Get("userID") - h.logAction(userID.(string), stackID, "create", fmt.Sprintf("Created new stack: %s", req.Name)) + h.logAction(c, stackID, "create", fmt.Sprintf("Created new stack: %s", req.Name)) // req.Deploy is false: stack created successfully, no deploy requested. if !req.Deploy || h.docker == nil { @@ -223,7 +222,7 @@ func (h *StacksHandler) Create(c *gin.Context) { // Attempt deployment using StartVerified so the outcome reflects the actual // running state, not just compose exit code (finding #14). deployAR, deployOutput := h.docker.StartVerified(stack) - h.logAction(userID.(string), stackID, "start", deployOutput) + h.logAction(c, stackID, "start", deployOutput) // Update DB with the verified status regardless of outcome. verifiedStatus := lifecycleStatus(deployAR) @@ -361,8 +360,7 @@ func (h *StacksHandler) Delete(c *gin.Context) { // Start/Stop/Restart's verified lifecycle). deleteAR, deleteOutput := h.docker.DeleteVerified(*stack) - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "delete", deleteOutput) + h.logAction(c, id, "delete", deleteOutput) if deleteAR.Outcome != truth.OutcomeSuccess && deleteAR.Outcome != truth.OutcomeNoChange { renderResult(c, truth.ActionResult{ diff --git a/backend/internal/handlers/stack_lifecycle.go b/backend/internal/handlers/stack_lifecycle.go index c6b0567..f879372 100644 --- a/backend/internal/handlers/stack_lifecycle.go +++ b/backend/internal/handlers/stack_lifecycle.go @@ -37,8 +37,7 @@ func (h *StacksHandler) Start(c *gin.Context) { ar, output := h.docker.StartVerified(*stack) duration := time.Since(startTime) - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "start", output) + h.logAction(c, id, "start", output) verifiedStatus := lifecycleStatus(ar) if statusErr := h.db.UpdateStackStatus(id, verifiedStatus); statusErr != nil { @@ -84,8 +83,7 @@ func (h *StacksHandler) Stop(c *gin.Context) { ar, output := h.docker.StopVerified(*stack) duration := time.Since(startTime) - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "stop", output) + h.logAction(c, id, "stop", output) verifiedStatus := lifecycleStatus(ar) if statusErr := h.db.UpdateStackStatus(id, verifiedStatus); statusErr != nil { @@ -131,8 +129,7 @@ func (h *StacksHandler) Restart(c *gin.Context) { ar, output := h.docker.RestartVerified(*stack) duration := time.Since(startTime) - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "restart", output) + h.logAction(c, id, "restart", output) verifiedStatus := lifecycleStatus(ar) if statusErr := h.db.UpdateStackStatus(id, verifiedStatus); statusErr != nil { @@ -178,8 +175,7 @@ func (h *StacksHandler) Pull(c *gin.Context) { pullAR, pullOutput := h.docker.PullVerified(*stack) duration := time.Since(startTime) - userID, _ := c.Get("userID") - h.logAction(userID.(string), id, "pull", pullOutput) + h.logAction(c, id, "pull", pullOutput) restartAfterPull := c.Query("restart") == "true" diff --git a/backend/internal/handlers/stacks.go b/backend/internal/handlers/stacks.go index bad8684..e26f3a1 100644 --- a/backend/internal/handlers/stacks.go +++ b/backend/internal/handlers/stacks.go @@ -9,6 +9,7 @@ import ( "github.com/gin-gonic/gin" "github.com/thinkbig1979/capstan/backend/internal/config" + "github.com/thinkbig1979/capstan/backend/internal/middleware" "github.com/thinkbig1979/capstan/backend/internal/models" "github.com/thinkbig1979/capstan/backend/internal/services" "github.com/thinkbig1979/capstan/backend/internal/truth" @@ -202,8 +203,8 @@ func (h *StacksHandler) Get(c *gin.Context) { c.JSON(http.StatusOK, stack) } -func (h *StacksHandler) logAction(userID, stackID, action, detail string) { - h.actionLog.Log(userID, &stackID, action, detail) +func (h *StacksHandler) logAction(c *gin.Context, stackID, action, detail string) { + h.actionLog.LogWithRequest(middleware.RequestIDFrom(c), userIDFrom(c), &stackID, action, detail) } func (h *StacksHandler) isValidStacksDir(dir string) bool { diff --git a/backend/internal/logging/logging.go b/backend/internal/logging/logging.go new file mode 100644 index 0000000..ed0cdac --- /dev/null +++ b/backend/internal/logging/logging.go @@ -0,0 +1,118 @@ +// Package logging installs the process-wide slog handler. +// +// Before this existed, LOG_LEVEL was dead configuration: config.Load read it, +// logged it back out at startup and nothing consumed it. The process ran on +// slog's default handler for its entire life, so every slog.Debug call in the +// WebSocket, terminal and git paths was permanently invisible — including the +// ones that are the whole evidence base when a user reports a dropped terminal +// (agent-os-7li). +package logging + +import ( + "fmt" + "io" + "log/slog" + "os" + "sort" + "strings" +) + +// Format names the encoder used for log output. +const ( + FormatText = "text" + FormatJSON = "json" +) + +var levels = map[string]slog.Level{ + "debug": slog.LevelDebug, + "info": slog.LevelInfo, + "warn": slog.LevelWarn, + "error": slog.LevelError, +} + +// ParseLevel maps a LOG_LEVEL value to a slog.Level. +// +// An unrecognised value is an error rather than a silent fallback to info: a +// typo in LOG_LEVEL should be visible at startup, not discovered at 3am when +// the debug lines someone is waiting for never arrive. +func ParseLevel(name string) (slog.Level, error) { + level, ok := levels[strings.ToLower(strings.TrimSpace(name))] + if !ok { + return 0, fmt.Errorf("unrecognised log level %q (want one of %s)", name, LevelNames()) + } + return level, nil +} + +// ParseFormat validates a LOG_FORMAT value. +func ParseFormat(name string) (string, error) { + switch strings.ToLower(strings.TrimSpace(name)) { + case FormatText: + return FormatText, nil + case FormatJSON: + return FormatJSON, nil + default: + return "", fmt.Errorf("unrecognised log format %q (want %s or %s)", name, FormatText, FormatJSON) + } +} + +// LevelNames returns the accepted LOG_LEVEL values, sorted, for error messages. +func LevelNames() string { + names := make([]string, 0, len(levels)) + for name := range levels { + names = append(names, name) + } + sort.Strings(names) + return strings.Join(names, ", ") +} + +// NewHandler builds a slog handler for the given level and format. +func NewHandler(w io.Writer, level slog.Level, format string) (slog.Handler, error) { + opts := &slog.HandlerOptions{Level: level} + switch format { + case FormatJSON: + return slog.NewJSONHandler(w, opts), nil + case FormatText: + return slog.NewTextHandler(w, opts), nil + default: + return nil, fmt.Errorf("unrecognised log format %q (want %s or %s)", format, FormatText, FormatJSON) + } +} + +// DefaultLevel is the LOG_LEVEL applied when the variable is unset. +const DefaultLevel = "info" + +// ConfigureFromEnv installs the logger straight from LOG_LEVEL / LOG_FORMAT. +// +// main() calls this before config.Load so that config's own startup lines — +// including the volume-path-identity warning — are emitted through the +// configured handler rather than slog's default. Load then re-installs the +// logger from the validated config, which stays the authoritative source. +func ConfigureFromEnv(w io.Writer) error { + level := os.Getenv("LOG_LEVEL") + if level == "" { + level = DefaultLevel + } + format := os.Getenv("LOG_FORMAT") + if format == "" { + format = FormatText + } + return Configure(w, level, format) +} + +// Configure installs the process-wide default logger. +func Configure(w io.Writer, levelName, formatName string) error { + level, err := ParseLevel(levelName) + if err != nil { + return err + } + format, err := ParseFormat(formatName) + if err != nil { + return err + } + handler, err := NewHandler(w, level, format) + if err != nil { + return err + } + slog.SetDefault(slog.New(handler)) + return nil +} diff --git a/backend/internal/logging/logging_test.go b/backend/internal/logging/logging_test.go new file mode 100644 index 0000000..b05e5e7 --- /dev/null +++ b/backend/internal/logging/logging_test.go @@ -0,0 +1,117 @@ +package logging + +import ( + "bytes" + "encoding/json" + "log/slog" + "strings" + "testing" +) + +// LOG_LEVEL was dead configuration: declared, defaulted, read from the +// environment and logged back out, with nothing consuming it. These tests pin +// down that it now actually gates output (agent-os-7li). + +func TestConfigure_LevelGatesOutput(t *testing.T) { + cases := []struct { + level string + wantDebug bool + wantInfo bool + wantWarn bool + }{ + {"debug", true, true, true}, + {"info", false, true, true}, + {"warn", false, false, true}, + {"error", false, false, false}, + } + + for _, tc := range cases { + t.Run(tc.level, func(t *testing.T) { + var buf bytes.Buffer + if err := Configure(&buf, tc.level, FormatText); err != nil { + t.Fatalf("Configure(%q): %v", tc.level, err) + } + + slog.Debug("debug-line") + slog.Info("info-line") + slog.Warn("warn-line") + + out := buf.String() + for _, want := range []struct { + marker string + present bool + }{ + {"debug-line", tc.wantDebug}, + {"info-line", tc.wantInfo}, + {"warn-line", tc.wantWarn}, + } { + if got := strings.Contains(out, want.marker); got != want.present { + t.Errorf("LOG_LEVEL=%s: %s present = %v, want %v\noutput: %s", + tc.level, want.marker, got, want.present, out) + } + } + }) + } +} + +func TestConfigure_JSONFormatParses(t *testing.T) { + var buf bytes.Buffer + if err := Configure(&buf, "info", FormatJSON); err != nil { + t.Fatalf("Configure: %v", err) + } + + slog.Info("HTTP request", "status", 200, "path", "/api/v1/stacks") + + var line map[string]any + if err := json.Unmarshal(bytes.TrimSpace(buf.Bytes()), &line); err != nil { + t.Fatalf("JSON output does not parse: %v\nline: %s", err, buf.String()) + } + if line["msg"] != "HTTP request" || line["path"] != "/api/v1/stacks" { + t.Errorf("structured fields lost: %v", line) + } +} + +func TestConfigure_TextIsTheDefaultShape(t *testing.T) { + var buf bytes.Buffer + if err := Configure(&buf, "info", FormatText); err != nil { + t.Fatalf("Configure: %v", err) + } + slog.Info("plain", "k", "v") + + if json.Valid(bytes.TrimSpace(buf.Bytes())) { + t.Errorf("text format emitted JSON: %s", buf.String()) + } + if !strings.Contains(buf.String(), "k=v") { + t.Errorf("expected key=value text output, got: %s", buf.String()) + } +} + +// TestConfigure_RejectsUnknownValues is the "fails loudly" requirement: a typo +// in LOG_LEVEL must surface at startup rather than silently becoming info. +func TestConfigure_RejectsUnknownValues(t *testing.T) { + var buf bytes.Buffer + + err := Configure(&buf, "bogus", FormatText) + if err == nil { + t.Fatal("expected an error for an unrecognised log level, got nil") + } + if !strings.Contains(err.Error(), "bogus") || !strings.Contains(err.Error(), "debug, error, info, warn") { + t.Errorf("error should name the bad value and the accepted set, got: %v", err) + } + + if err := Configure(&buf, "info", "yaml"); err == nil { + t.Fatal("expected an error for an unrecognised log format, got nil") + } +} + +func TestParseLevel_CaseAndSpaceTolerant(t *testing.T) { + for _, in := range []string{"DEBUG", " debug ", "Debug"} { + got, err := ParseLevel(in) + if err != nil { + t.Fatalf("ParseLevel(%q): %v", in, err) + } + if got != slog.LevelDebug { + t.Errorf("ParseLevel(%q) = %v, want debug", in, got) + } + } +} diff --git a/backend/internal/middleware/logging.go b/backend/internal/middleware/logging.go index 06a93fc..48f7f75 100644 --- a/backend/internal/middleware/logging.go +++ b/backend/internal/middleware/logging.go @@ -35,6 +35,7 @@ func LoggingMiddleware() gin.HandlerFunc { } slog.Log(c.Request.Context(), level, "HTTP request", + "request_id", RequestIDFrom(c), "method", c.Request.Method, "path", path, "status", c.Writer.Status(), diff --git a/backend/internal/middleware/requestid.go b/backend/internal/middleware/requestid.go new file mode 100644 index 0000000..79dde6c --- /dev/null +++ b/backend/internal/middleware/requestid.go @@ -0,0 +1,57 @@ +package middleware + +import ( + "github.com/gin-gonic/gin" + "github.com/google/uuid" +) + +// RequestIDKey is the gin context key holding the current request's ID. +const RequestIDKey = "requestID" + +// RequestIDHeader is the response header carrying it back to the caller, and +// the request header honoured when a reverse proxy has already assigned one. +const RequestIDHeader = "X-Request-ID" + +// RequestID assigns every request an ID, exposes it on the context, and returns +// it in a response header. +// +// Without it there is no way to join a 500 in the HTTP log to the row it +// produced in action_log, or to follow one user action across several log +// lines. The header also gives a user something concrete to quote in a bug +// report (agent-os-7li). +// +// An inbound header is honoured so a request keeps one identity across a +// reverse proxy — but only when it is a well-formed UUID. An arbitrary +// caller-supplied string would otherwise end up in log lines and audit rows, +// where a crafted value could forge log entries or bloat the database. +func RequestID() gin.HandlerFunc { + return func(c *gin.Context) { + id := "" + if inbound := c.GetHeader(RequestIDHeader); inbound != "" { + if parsed, err := uuid.Parse(inbound); err == nil { + id = parsed.String() + } + } + if id == "" { + id = uuid.New().String() + } + + c.Set(RequestIDKey, id) + c.Header(RequestIDHeader, id) + c.Next() + } +} + +// RequestIDFrom returns the request ID stored on the context, or "" when the +// middleware did not run (background jobs, tests). +func RequestIDFrom(c *gin.Context) string { + if c == nil { + return "" + } + if v, ok := c.Get(RequestIDKey); ok { + if id, ok := v.(string); ok { + return id + } + } + return "" +} diff --git a/backend/internal/middleware/requestid_test.go b/backend/internal/middleware/requestid_test.go new file mode 100644 index 0000000..22be875 --- /dev/null +++ b/backend/internal/middleware/requestid_test.go @@ -0,0 +1,112 @@ +package middleware + +import ( + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/gin-gonic/gin" + "github.com/google/uuid" +) + +func init() { gin.SetMode(gin.TestMode) } + +// newRequestIDRouter wires RequestID ahead of a handler that echoes whatever the +// middleware put on the context, so the test can compare the two. +func newRequestIDRouter() *gin.Engine { + r := gin.New() + r.Use(RequestID()) + r.GET("/probe", func(c *gin.Context) { + c.String(http.StatusOK, RequestIDFrom(c)) + }) + return r +} + +func TestRequestID_SetsHeaderAndContext(t *testing.T) { + w := httptest.NewRecorder() + newRequestIDRouter().ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/probe", nil)) + + header := w.Header().Get(RequestIDHeader) + if header == "" { + t.Fatalf("no %s response header", RequestIDHeader) + } + if _, err := uuid.Parse(header); err != nil { + t.Errorf("%s = %q, which is not a UUID: %v", RequestIDHeader, header, err) + } + if body := w.Body.String(); body != header { + t.Errorf("context ID %q does not match the response header %q", body, header) + } +} + +func TestRequestID_IsUniquePerRequest(t *testing.T) { + r := newRequestIDRouter() + seen := map[string]bool{} + for i := 0; i < 5; i++ { + w := httptest.NewRecorder() + r.ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/probe", nil)) + id := w.Body.String() + if seen[id] { + t.Fatalf("request ID %q reused across requests", id) + } + seen[id] = true + } +} + +// TestRequestID_HonoursInboundUUID keeps one identity across a reverse proxy +// that has already assigned an ID. +func TestRequestID_HonoursInboundUUID(t *testing.T) { + inbound := uuid.New().String() + req := httptest.NewRequest(http.MethodGet, "/probe", nil) + req.Header.Set(RequestIDHeader, inbound) + + w := httptest.NewRecorder() + newRequestIDRouter().ServeHTTP(w, req) + + if got := w.Body.String(); got != inbound { + t.Errorf("inbound request ID not honoured: got %q, want %q", got, inbound) + } + if got := w.Header().Get(RequestIDHeader); got != inbound { + t.Errorf("response header = %q, want the inbound %q", got, inbound) + } +} + +// TestRequestID_RejectsUntrustedInbound is the reason inbound IDs are parsed +// rather than trusted: the value lands in log lines and audit rows, where an +// arbitrary caller-supplied string could forge entries or bloat the database. +func TestRequestID_RejectsUntrustedInbound(t *testing.T) { + for name, hostile := range map[string]string{ + "forged log line": `abc" msg="user deleted everything`, + "newline": "aaa\nbbb", + "oversized": strings.Repeat("x", 4096), + "not a uuid": "12345", + } { + t.Run(name, func(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "/probe", nil) + req.Header.Set(RequestIDHeader, hostile) + + w := httptest.NewRecorder() + newRequestIDRouter().ServeHTTP(w, req) + + got := w.Body.String() + if got == hostile { + t.Fatalf("untrusted inbound ID was accepted verbatim: %q", got) + } + if _, err := uuid.Parse(got); err != nil { + t.Errorf("replacement ID %q is not a UUID: %v", got, err) + } + }) + } +} + +// TestRequestIDFrom_AbsentMiddleware covers background jobs and tests, which +// serve no request and must not panic. +func TestRequestIDFrom_AbsentMiddleware(t *testing.T) { + c, _ := gin.CreateTestContext(httptest.NewRecorder()) + if got := RequestIDFrom(c); got != "" { + t.Errorf("RequestIDFrom without the middleware = %q, want empty", got) + } + if got := RequestIDFrom(nil); got != "" { + t.Errorf("RequestIDFrom(nil) = %q, want empty", got) + } +} diff --git a/backend/internal/models/models.go b/backend/internal/models/models.go index a270103..a3b56d7 100644 --- a/backend/internal/models/models.go +++ b/backend/internal/models/models.go @@ -107,6 +107,7 @@ type ActionLog struct { StackID string `json:"stackId"` Action string `json:"action"` Detail string `json:"detail"` + RequestID string `json:"requestId,omitempty"` CreatedAt time.Time `json:"createdAt"` } diff --git a/backend/internal/services/actionlog.go b/backend/internal/services/actionlog.go index 2c073f1..b925edf 100644 --- a/backend/internal/services/actionlog.go +++ b/backend/internal/services/actionlog.go @@ -53,7 +53,16 @@ func NewActionLogger(db *database.DB) *ActionLogger { return &ActionLogger{db: db} } +// Log records an action with no request correlation. Background jobs and +// schedulers serve no HTTP request, so they legitimately have no ID. func (l *ActionLogger) Log(userID string, stackID *string, action string, detail interface{}) { + l.LogWithRequest("", userID, stackID, action, detail) +} + +// LogWithRequest records an action tagged with the ID of the request that +// caused it, so an HTTP log line and the audit row it produced can be joined +// (agent-os-7li). +func (l *ActionLogger) LogWithRequest(requestID, userID string, stackID *string, action string, detail interface{}) { detailJSON, err := json.Marshal(detail) if err != nil { slog.Error("failed to marshal action detail", "action", action, "error", err) @@ -71,6 +80,7 @@ func (l *ActionLogger) Log(userID string, stackID *string, action string, detail StackID: stackIDStr, Action: action, Detail: string(detailJSON), + RequestID: requestID, CreatedAt: time.Now(), } diff --git a/backend/internal/services/actionlog_test.go b/backend/internal/services/actionlog_test.go new file mode 100644 index 0000000..4e25550 --- /dev/null +++ b/backend/internal/services/actionlog_test.go @@ -0,0 +1,53 @@ +package services + +import ( + "testing" +) + +// Without a shared ID there is no way to join a 500 in the HTTP log to the row +// it produced in action_log, or to follow one user action across several log +// lines (agent-os-7li). + +func TestActionLogger_PersistsRequestID(t *testing.T) { + db := newTestDB(t) + logger := NewActionLogger(db) + stackID := "stacks~demo:default" + + logger.LogWithRequest("11111111-2222-4333-8444-555555555555", "user-1", &stackID, ActionGitPull, map[string]string{"detail": "pulled"}) + + actions, err := db.GetActionsByStack(stackID, 10) + if err != nil { + t.Fatalf("GetActionsByStack: %v", err) + } + if len(actions) != 1 { + t.Fatalf("expected 1 action row, got %d", len(actions)) + } + if got := actions[0].RequestID; got != "11111111-2222-4333-8444-555555555555" { + t.Errorf("action row request ID = %q, want the one supplied at log time", got) + } +} + +// TestActionLogger_LogWithoutRequestID covers background jobs and schedulers, +// which serve no HTTP request. The column is nullable for exactly this reason, +// and the row must still be written. +func TestActionLogger_LogWithoutRequestID(t *testing.T) { + db := newTestDB(t) + logger := NewActionLogger(db) + stackID := "stacks~demo:default" + + logger.Log("system", &stackID, ActionBackup, map[string]string{"kind": "scheduled"}) + + actions, err := db.GetActionsByStack(stackID, 10) + if err != nil { + t.Fatalf("GetActionsByStack: %v", err) + } + if len(actions) != 1 { + t.Fatalf("expected the row to be written anyway, got %d rows", len(actions)) + } + if actions[0].RequestID != "" { + t.Errorf("expected an empty request ID for a background action, got %q", actions[0].RequestID) + } + if actions[0].UserID != "system" { + t.Errorf("actor = %q, want system", actions[0].UserID) + } +}