home-assistant-controller/docs/superpowers/specs/2026-08-21-katip-logging-design.md

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.

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:

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:<uuid>] <message>.
• 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 . <component>.

Severity & namespace mapping

Site	Namespace	Severity
dryRun CallService	<controllerName>	DebugS
Debug (both interpreters)	<controllerName>	DebugS
Trace req x (both interpreters)	<controllerName>	DebugS
Supervisor crash	runtime.supervisor.<name>	WarningS
Supervisor restart	runtime.supervisor.<name>	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):

Trace req x -> runKatipT le $
  logF (sl "traceId" (toText (requestTraceId req))) ns DebugS (showLS x)

Renders in bracket format as [home-assistant-controller.<name>][Debug][...][traceId:<uuid>] <x>. The toText import comes from Data.UUID (already a dependency).

Signature changes

Bus (Bus.hs)

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:

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

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:

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:

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:

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