diff --git a/docs/superpowers/specs/2026-08-21-katip-logging-design.md b/docs/superpowers/specs/2026-08-21-katip-logging-design.md new file mode 100644 index 0000000..4d1b972 --- /dev/null +++ b/docs/superpowers/specs/2026-08-21-katip-logging-design.md @@ -0,0 +1,278 @@ +# Replace manual printing with katip logging + +Date: 2026-08-21 +Status: Approved (pending spec review) + +## Goal + +Replace all `print`/`putStrLn` logging under `src/` with [katip], a +structured logging framework. The AFRP layer and controller definitions +stay logging-free; only the `HASSEff` interpreters and runtime workers +log. + +[katip]: https://hackage.haskell.org/package/katip + +## Current state + +Nine logging sites under `src/`, all unstructured stdout: + +| Site | Current code | +|------|-------------| +| `Runtime.hs:78` | `print (callId, x)` — dry-run `CallService` | +| `Runtime.hs:79` | `print x` — `Debug` | +| `Runtime.hs:80` | `print (req, x)` — `Trace` | +| `Bus.hs:45` | `print x` — `Debug` (channelHassEval) | +| `Bus.hs:46` | `print (req, x)` — `Trace` (channelHassEval) | +| `Supervisor.hs:76` | `putStrLn ... "crashed: ..."` | +| `Supervisor.hs:78` | `putStrLn ... "restarting in ..."` | +| `Connection.hs:41` | `putStrLn "[reader] connected"` | +| `Connection.hs:77` | `putStrLn "[reader] skipping undecodable message: ..."` | + +`app/Main.hs`'s `putStrLn "Hello, Haskell!"` is outside `src/` and left +alone. `AFRP.hs`, `Controller.hs`, and `Controller/Bedroom.hs` contain +no logging and remain untouched. + +## Approach + +Approach A: `LogEnv` stored in `Bus`, explicit `runKatipT` per site. + +- `Bus` gains `busLogEnv :: LogEnv`; `defaultMain` builds the env and + passes it to `newBus`. +- Every existing worker already takes `Bus`, so it reads `busLogEnv` + and logs with `runKatipT le $ logMsg ns sev msg` — no worker + signature changes. +- `dryRunHassEval` and `channelHassEval` gain the controller name + (`Text`) so debug/trace logs get a per-controller namespace. +- `supervised` is the one function without a `Bus`; it gains a leading + `LogEnv` param. +- Tests get a silent `LogEnv` (no scribes) via a helper so they don't + spew. + +Rejected alternatives: B (`KatipContextT IO` worker monad — large +churn, async context loss undermines the main benefit, fights the +existing `IO`+`Bus` design); C (a new `App` `ReaderT` monad — +over-scoped for a logging swap). + +## Scribe setup + +One scribe in `defaultMain`: + +```haskell +scribe <- mkHandleScribe ColorIfTerminal stdout (permitItem DebugS) V2 +``` + +- `ColorIfTerminal`: color codes only when stdout is a TTY. +- `permitItem DebugS`: lets all severities through. The dev run shows + everything; a production deployment can swap `DebugS` for `InfoS` (or + register a second, more restrictive scribe) without code changes + elsewhere. +- `V2` verbosity: renders structured payload fields (e.g. `traceId`) + inline in bracket format, e.g. `[traceId:] `. +- `bracket ... closeScribes`: the current `waitAny`+`absurd` exits + abruptly; wrapping the body in `bracket` ensures scribe queues flush + and finalizers run on exit. + +App namespace (set once): `initLogEnv "home-assistant-controller" +"production"`. Every log's full namespace is `home-assistant-controller +. `. + +## Severity & namespace mapping + +| Site | Namespace | Severity | +|------|-----------|----------| +| dryRun `CallService` | `` | DebugS | +| `Debug` (both interpreters) | `` | DebugS | +| `Trace req x` (both interpreters) | `` | DebugS | +| Supervisor crash | `runtime.supervisor.` | WarningS | +| Supervisor restart | `runtime.supervisor.` | InfoS | +| reader connected | `runtime.reader` | InfoS | +| reader undecodable | `runtime.reader` | WarningS | + +Rationale: crashes that get restarted are recoverable → WarningS; the +restart notice is normal operation → InfoS. "reader connected" is an +operational milestone → InfoS; skipping a bad message is +abnormal-but-handled → WarningS. All interpreter output +(CallService dry-run, Debug, Trace) is developer instrumentation → +DebugS, so a production scribe (`permitItem InfoS`) filters it out +while a dev scribe keeps it. + +## Structured traceId + +`Trace req x` carries `requestTraceId :: UUID`. Logged via `logF` with +a `SimpleLogPayload` so the traceId is a structured field rather than +text concatenated into the message. `Data.UUID.toText` renders the UUID +as a hyphenated `Text` (which is `ToJSON`, as `sl` requires): + +```haskell +Trace req x -> runKatipT le $ + logF (sl "traceId" (toText (requestTraceId req))) ns DebugS (showLS x) +``` + +Renders in bracket format as +`[home-assistant-controller.][Debug][...][traceId:] `. +The `toText` import comes from `Data.UUID` (already a dependency). + +## Signature changes + +### `Bus` (Bus.hs) + +```haskell +data Bus = Bus + { busInbound :: TChan Value + , busOutbound :: TChan Service + , busConn :: TVar (Maybe Connection) + , busGen :: CallIdGen + , busLogEnv :: LogEnv -- new + } + +newBus :: LogEnv -> Int -> IO Bus -- LogEnv first +``` + +`LogEnv` is the more "environmental" arg; `Int` is the call-id seed. + +### `HASSEff` interpreters (Runtime.hs, Bus.hs) + +Both gain the controller name as the 2nd arg and read `LogEnv` from +`Bus`/`busLogEnv`: + +```haskell +dryRunHassEval :: Bus -> Text -> HASSEff a -> IO a +channelHassEval :: Bus -> Text -> HASSEff a -> IO a +``` + +- `dryRunHassEval` changes from `CallIdGen -> ...` to `Bus -> Text -> + ...` (it needs both `busGen` for call ids and `busLogEnv` for + logging). Matches `channelHassEval`'s shape for symmetry. +- `Debug`: `print x` → `runKatipT (busLogEnv bus) $ logMsg ns DebugS + (showLS x)`. +- `Trace`: `print (req, x)` → the structured `logF` call in + [Structured traceId](#structured-traceid). +- `CallService`: + - `dryRunHassEval`: keeps `generateCallId (busGen bus)` (call id for + dry-run output) and replaces `print (callId, x)` with a DebugS log + of the `Service`: + `runKatipT (busLogEnv bus) $ logMsg ns DebugS (showLS svc)`. + - `channelHassEval`: unchanged — writes `Service` to `busOutbound` + and emits no log (the writer does the actual send; logging here + would be new behavior, not a replacement). + +### `supervised` (Supervisor.hs) + +```haskell +supervised :: LogEnv -> Text -> Backoff -> IO Void -> IO Void +``` + +Logs via `runKatipT le $ logMsg ("runtime.supervisor." <> name) sev +msg`. `defaultMain` passes `busLogEnv bus`. + +### `defaultMain` (Runtime.hs) + +Builds `LogEnv` at the top, passes to `newBus`, wraps body in +`bracket ... closeScribes`: + +```haskell +defaultMain = withSocketsDo $ do + scribe <- mkHandleScribe ColorIfTerminal stdout (permitItem DebugS) V2 + le <- registerScribe "stdout" scribe defaultScribeSettings + =<< initLogEnv "home-assistant-controller" "production" + bracket (pure le) closeScribes $ \le' -> do + token <- getEnv "HA_TOKEN" + bus <- newBus le' 0 + let workers = ... + as <- mapM (\(name, act) -> async (supervised le' name defaultBackoff act)) workers + (_, v) <- waitAny as + absurd v +``` + +### `runController` (Runtime.hs) + +`Controller _name` becomes `Controller name`; the name threads into the +interpreter: + +```haskell +runController :: Bus -> Controller -> IO Void +runController bus (Controller name machine) = do + inbound <- atomically (dupTChan (busInbound bus)) + go inbound machine + where + go inbound f = do + msg <- atomically (readTChan inbound) + uuid <- UUID.V4.nextRandom + (_, f') <- step (dryRunHassEval bus name) uuid f (Event msg) + go inbound f' +``` + +### `Connection.hs` workers + +`readerAction`/`writerAction` signatures unchanged — they already take +`Bus`. The two `putStrLn` sites read `busLogEnv bus` and log via +`runKatipT (busLogEnv bus) $ logMsg "runtime.reader" sev msg`. + +### No changes to + +`AFRP.hs`, `Controller.hs`, `Controller/Bedroom.hs`, +`Connection.hs`'s pure `encodeService`, or any controller definition — +they remain logging-free. + +## Tests + +A silent `LogEnv` helper (in `test/Main.hs` or a new `test/Support.hs`) +lets tests construct a `Bus`/call `supervised` without spewing: + +```haskell +silentLogEnv :: IO LogEnv +silentLogEnv = initLogEnv "home-assistant-controller" "test" +``` + +No scribe registered → all `logMsg` calls are no-ops (katip drops +silently). + +Mechanical call-site updates: + +- `BusSpec`: `newBus 0` → `silentLogEnv >>= \le -> newBus le 0`; + `channelHassEval bus (CallService svc)` → + `channelHassEval bus "test" (CallService svc)`. +- `RuntimeSpec`: `newBus 0` → with `silentLogEnv`; `runController bus + (Controller "test" lightController)` unchanged. +- `SupervisorSpec`: `supervised "test" tinyBackoff action` → + `silentLogEnv >>= \le -> supervised le "test" tinyBackoff action` + (3 call sites). +- `ConnectionSpec`/`BackoffProp`: no change (test pure code). + +No new tests required — the logging swap is behavior-preserving for +existing assertions. A capturing-scribe test asserting debug logs +*would* fire is out of scope (noted as a future option). + +## Cabal & nix + +- Add `katip` to library `build-depends` and to test-suite + `build-depends` (the test helper imports `Katip`). +- After editing the `.cabal`, regenerate the derivation per AGENTS.md: + + ``` + nix run nixpkgs#cabal2nix -- ./. > default.nix + ``` + +- `flake.nix`: no change. nixpkgs has `katip` 0.8.8.4 (verified), and + `callPackage ./.` picks up new deps from `default.nix` automatically. +- `default.nix`: regenerated by the cabal2nix command — never hand-edit. + +## Imports added + +| Module | Import | +|--------|--------| +| `Bus.hs` | `import Katip` | +| `Runtime.hs` | `import Katip` | +| `Supervisor.hs` | `import Katip` (+ `qualified Data.Text as T` if not present) | +| `Connection.hs` | `import Katip` | +| test helper | `import Katip` | + +## Non-goals + +- Logging inside the AFRP layer or controller definitions. +- A custom capturing-scribe test. +- Log-level configuration via env or CLI (the scribe `permitItem` is a + code constant for now). +- JSON output / file scribe / multiple scribes (deferred; the single + stdout text scribe is the drop-in replacement for current `print`). +- Changing `app/Main.hs` (outside `src/`).