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

[thinkbig1979]

Closes agent-os-7li. First of the four main.go beads (7li → 0jp → r7e → 69a), which are sequential because they land in overlapping regions of the same file.

The bug

LOG_LEVEL was dead configuration:

$ grep -rn "slog.SetDefault\|NewTextHandler\|NewJSONHandler" --include=*.go backend/ | grep -v _test
(no output)

config.go declared the field, defaulted it to info, read the env var and logged it back out at startup. Nothing consumed it. The process ran on slog's default handler at the default level for its entire life.

Setting LOG_LEVEL=debug in production did nothing at all — worse than not offering the knob, because an operator turns it up during an incident, sees no change, and concludes the problem is elsewhere. What it suppressed is exactly the diagnostic layer: the slog.Debug calls in handlers/terminal.go, handlers/ws.go, services/terminal.go and services/git.go. When a user reports a dropped terminal or a blank logs pane, those lines are the whole evidence base.

What changed

internal/logging installs the process-wide handler.

main() bootstraps it from the environment before config.Load, then re-installs it from the validated config. The acceptance criterion says "immediately after config.Load()"; installing it before as well is what makes the rest of that sentence — "and before any other logging" — actually true. config.Load emits two lines of its own, one of them the volume-path-identity warning, and with the naive ordering those would still bypass the handler. With the bootstrap, all 19 startup lines are JSON in JSON mode. cfg remains the authoritative source.

LOG_FORMAT selects text (default, so existing deployments see no change) 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). There was previously no way to join a 500 in the HTTP log to the row it produced in action_log.

An inbound X-Request-ID is honoured only when it parses as a UUID. The value ends up in log lines and audit rows, so an arbitrary caller-supplied string could forge log entries or bloat the database — there is a test for abc" msg="user deleted everything.

Handler helpers now take the gin context instead of a pre-extracted userID, which also replaces eleven userID.(string) type assertions with userIDFrom's "anonymous" fallback.

Verified against the running binary

Unit tests prove the level gating in isolation; these are the same claims made against the real process, which is where the bug lived.

check	result
LOG_LEVEL=bogus	exits 1: unrecognised log level "bogus" (want one of debug, error, info, warn)
LOG_LEVEL=warn	0 level=INFO lines, WARN lines still present
LOG_LEVEL=debug	level=DEBUG msg="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 correlation	X-Request-Id: 6d4ac13a-2baa-454f-b61f-e26eb0b7d767 matched request_id=6d4ac13a-… in the HTTP log line and the action_log row for that same pull

The last one, end to end:

X-Request-Id: 6d4ac13a-2baa-454f-b61f-e26eb0b7d767

level=INFO msg="HTTP request" request_id=6d4ac13a-2baa-454f-b61f-e26eb0b7d767
  method=POST path=/api/v1/git/pull status=200 duration_ms=13

sqlite> select action, request_id from action_log order by rowid desc limit 1;
('pull', '6d4ac13a-2baa-454f-b61f-e26eb0b7d767')

Gates

go build ./... && go vet ./... && go test ./... -count=1   → exit 0
705 tests across 9 packages   (674 at session start, +7 from agent-os-qqw, +24 here)
go vet -tags=integration ./internal/integrationtest/       → exit 0

Frontend untouched.

Deliberately not done

The bead's step 5 ("consider promoting a few WebSocket slog.Debug calls to Warn") is not in the acceptance criteria and is a judgement call about each individual call site. Left out to keep this reviewable; the debug lines are now reachable via LOG_LEVEL=debug, which was the actual blocker.

PORT turns out to have the same shape of problem as LOG_LEVEL did — .env.example documents it, config.Load defaults it to 5001, and nothing reads os.Getenv("PORT"), so the server ignores it. Out of scope here; noticed while testing and worth its own issue.