feat(logging): wire LOG_LEVEL into slog, add LOG_FORMAT=json, correlate requests

.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

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

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))

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
 }
 

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)
+	}
+}

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

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);
 `,
 	},
 }

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,