ML-158: plan review

backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md

@@ -4,7 +4,7 @@ title: Force production logs to single-line format
 status: To Do
 assignee: []
 created_date: '2026-05-03 13:51'
-updated_date: '2026-05-03 14:26'
+updated_date: '2026-05-03 14:39'
 labels: []
 dependencies: []
 references:
@@ -54,58 +54,176 @@ The solution has three layers:
 
 ### Completeness and sequencing
 
+#### Step 0: Pre-implementation verification
+
+Before writing code, verify two assumptions:
+
+**0a. Enumerate Phoenix.Logger events that fire in production.**
+
+`Phoenix.Logger` auto-attaches to 8 telemetry events. With production log level `:info`, only these produce visible output:
+
+| Event | Level | Multi-line? | Covered by |
+|---|---|---|---|
+| `[:phoenix, :endpoint, :start]` | `:info` | No (one line) | Logster v2 |
+| `[:phoenix, :endpoint, :stop]` | `:info` | No (one line) | Logster v2 |
+| `[:phoenix, :socket_connected]` | `:info` | **Yes** (4+ lines) | Custom handler (Step 4) |
+| `[:phoenix, :error_rendered]` | `:error` | No (one line) | Silenced — acceptable (ErrorTracker already captures errors) |
+| `[:phoenix, :router_dispatch, :start]` | `:debug` | Yes | Already filtered at `:info` level — no action needed |
+| `[:phoenix, :socket_drain]` | `:debug` | No | Already filtered |
+| `[:phoenix, :channel_joined]` | `:debug` | Yes | Already filtered (LiveView uses `"lv:"` topics not `"phoenix"` internal topics, but default log_join level is `:debug`) |
+| `[:phoenix, :channel_handled_in]` | `:debug` | Yes | Already filtered |
+
+**Verdict**: The only events that produce visible output at `:info`+ are endpoint start/stop, socket_connected, and error_rendered. Disabling Phoenix.Logger is safe — the first two are replaced by Logster, socket_connected is replaced by the custom handler, and losing error_rendered is acceptable because ErrorTracker already captures all errors via its own telemetry listener.
+
+**Verify**: Confirm by starting the app with `MIX_ENV=prod mix phx.server` and inspecting stdout before any changes. Note which Phoenix.Logger events appear. If `router_dispatch_start` or `channel_*` events appear at `:info`, adjust the plan accordingly.
+
+**0b. Verify whether Logster v2 handles `[:phoenix, :socket_connected]`.**
+
+After adding the Logster dependency (Step 1), inspect `Logster`'s telemetry attachments to check if it already emits a handler for `[:phoenix, :socket_connected]`.
+
+**Verify**: In an IEx session: `Logster.__info__(:functions)` or check the Logster source to see which events it attaches to. If it covers `socket_connected`, **skip Step 4** — the custom telemetry handler is unnecessary.
+
 #### Step 1: Add Logster dependency
 - Add `{:logster, "~> 2.0.0-rc.5"}` to `mix.exs` deps
 - Run `mix deps.get`
 - **Verify**: `mix compile` succeeds, `Logster` module is available
 
-#### Step 2: Disable Phoenix.Logger and configure Logster in prod
+#### Step 2: Disable Phoenix.Logger in prod
-- `config/prod.exs`: add `config :phoenix, :logger, false`
-- `config/prod.exs`: add Logster configuration (filter parameters, optional settings)
-- **Verify**: After deployment, no `GET /path` or `Sent 200 in Xms` lines appear (they'll be replaced by Logster's output)
 
-#### Step 3: Attach Logster in application.ex
+- `config/prod.exs`: add `config :phoenix, :logger, false`
-- `lib/music_library/application.ex`: add conditional `Logster.attach_phoenix_logger()` for `:prod` env
+- **Note**: This silences all 8 Phoenix.Logger telemetry handlers. Only `endpoint_start`, `endpoint_stop`, `socket_connected`, and `error_rendered` fire at `:info`+ in production. The first two are replaced by Logster, `socket_connected` is replaced by the custom handler (Step 4), and `error_rendered` is redundant with ErrorTracker.
-- **Verify**: In prod, HTTP requests produce a single logfmt line like `method=GET path=/health ... status=200 duration=696`
+- **Verify**: After deployment, no `GET /path`, `Sent 200`, or `CONNECTED TO` lines appear from Phoenix.Logger (they'll be replaced by Logster and the custom handler).
+
+#### Step 3: Configure Logster and attach in application.ex
+
+**Environment-conditional mechanism**: Use a config flag rather than checking `Mix.env()` at runtime (follows the project's existing pattern, e.g., `config :error_tracker, enabled: true`).
+
+- `config/config.exs`: add `config :music_library, :single_line_logging, false`
+- `config/prod.exs`: override with `config :music_library, :single_line_logging, true`
+- `config/prod.exs`: add Logster configuration:
+  ```elixir
+  config :logster,
+    extra_fields: [:request_id],
+    filter_parameters: Application.get_env(:phoenix, :filter_parameters, ["password"])
+  ```
+  (Reuses Phoenix's existing parameter filter list; `request_id` is added to every log line as metadata.)
+- `lib/music_library/application.ex`: add after children list declaration:
+  ```elixir
+  if Application.fetch_env!(:music_library, :single_line_logging) do
+    Logster.attach_phoenix_logger()
+  end
+  ```
+- **Verify**: In prod (`MIX_ENV=prod mix phx.server`), HTTP requests produce a single logfmt line like `method=GET path=/health request_id=Fz... status=200 duration=696µs`. In dev, Logster is NOT attached and Phoenix.Logger continues to log normally.
 
 #### Step 4: Create custom telemetry handler for LiveView socket connections
-- New module `lib/music_library_web/telemetry_log_handler.ex`
+
+> **Prerequisite**: Complete Step 0b first. Skip this step if Logster already handles `[:phoenix, :socket_connected]`.
+
+- New module `lib/music_library_web/telemetry/log_handler.ex` (placed under `lib/music_library_web/telemetry/` to match existing convention — sibling to `Telemetry.Storage`)
 - Handles `[:phoenix, :socket_connected]` event
-- Outputs a single line with transport, serializer, duration, and filtered params
+- Outputs a single line with transport, serializer, duration, result, and filtered params
-- Attach handler in `application.ex` (prod-only) alongside Logster
+- Respects Phoenix's `:filter_parameters` config — reuse `Phoenix.Logger.filter_values/2` for parameter filtering
-- **Verify**: LiveView connection produces one line instead of 4+
+- Include `@moduledoc` explaining purpose (required by Credo strict mode)
+- Attach handler in `application.ex` inside the same `if single_line_logging` block as Logster:
+  ```elixir
+  :telemetry.attach(
+    "music-library-socket-connected",
+    [:phoenix, :socket_connected],
+    &MusicLibraryWeb.Telemetry.LogHandler.handle_event/4,
+    :ok
+  )
+  ```
+- **Verify**: LiveView connection produces one line instead of 4+. Trigger by visiting any LiveView page (e.g., `/collection`). Manual inspection of stdout.
+- **Unit test** (`test/music_library_web/telemetry/log_handler_test.exs`): Verify output format is a single line containing transport, serializer, and duration. Verify sensitive params are filtered.
 - **Dependency on**: Step 2 (Phoenix.Logger must be disabled first so we don't double-log)
 
 #### Step 5: Create custom Logger.Formatter (safety net)
+
 - New module `lib/music_library/logger/single_line_formatter.ex`
-- Implements `format/4` function for `{module, function}` Logger.Formatter API
+- Implements `format/4` function (`level, message, timestamp, metadata`) returning `IO.chardata()`
-- Replaces `\n` with `\n` in message before delegating to default formatter
+- Replaces literal `\n` (newline character) with escaped `\\n` (backslash + n) in the message
-- **Verify**: Any Logger call with embedded newlines (stack traces, OTP reports) produces one line. Test with `Logger.error("line1\nline2\nline3")`
+- Handles both string and iolist messages: convert to string via `IO.chardata_to_string/1` before replacement
+- Include `@moduledoc` explaining that this is a production-only safety net for any log messages containing embedded newlines
+- **Unit tests** (`test/music_library/logger/single_line_formatter_test.exs`):
+  - `Logger.error("line1\nline2\nline3")` → produces one line with `line1\\nline2\\nline3`
+  - Messages without newlines pass through unchanged
+  - Iolist input `['hello', ?\n, 'world']` → produces `hello\\nworld`
+  - Metadata (request_id etc.) is preserved in output
+  - Empty messages don't crash
+- **Verify**: In IEx, `Logger.error("line1\nline2\nline3")` produces one line. Run `mix test test/music_library/logger/single_line_formatter_test.exs`.
 
 #### Step 6: Configure custom formatter in prod
-- `config/prod.exs`: set `config :logger, :default_formatter, format: {MusicLibrary.Logger.SingleLineFormatter, :format}`
-- Keep `metadata: [:request_id]`
-- **Verify**: After deployment, no log line contains an unescaped newline
 
-#### Step 7: Audit codebase for multi-line Logger calls
+- `config/prod.exs`: override the default formatter:
-- Search for `Logger.` calls with string interpolation containing `\n`
+  ```elixir
-- Rewrite to single-line strings or use `Logster.info/1` style
+  config :logger, :default_formatter,
-- **Verify**: `rg 'Logger\.(info|error|warning|debug)\b.*\\n' lib/` returns empty
+    format: {MusicLibrary.Logger.SingleLineFormatter, :format},
+    metadata: [:request_id]
+  ```
+- **Verify**: After deployment (`MIX_ENV=prod mix phx.server`), no log line contains an unescaped newline. Trigger a LiveView crash to verify stack traces are escaped to single line.
 
-#### Step 8: Update documentation
+#### Step 7: Audit codebase for multi-line Logger calls (best-effort)
-- Update `docs/production-infrastructure.md` — add logging section describing the three-layer approach
+
-- **Verify**: Docs reflect the new logging architecture
+> **Note**: The custom formatter (Step 5) is the authoritative safety net. This audit is best-effort — it catches multi-line calls in project code that would benefit from being rewritten as structured single-line messages, but the formatter handles anything missed.
+
+- Search for Logger calls containing `\n` escape sequences:
+  ```bash
+  rg -n 'Logger\.(info|error|warning|debug)\b.*\\\\n' lib/ --no-heading
+  ```
+- Search for Logger calls spanning multiple lines (heredocs, built-up iolists):
+  ```bash
+  rg -U -n 'Logger\.(info|error|warning|debug)\b[^)]*\n' lib/ --no-heading
+  ```
+- Rewrite found instances to single-line strings or use structured key=value format
+- **Do NOT** attempt to rewrite OTP/Elixir internal Logger calls — the custom formatter handles those.
+- **Verify**: Both `rg` searches return empty for project code in `lib/`. The formatter's unit tests pass.
+
+#### Step 8: Integration tests for environment behavior
+
+- **Dev environment unchanged test** (`test/music_library/logger/single_line_formatter_test.exs` or a dedicated integration test): Verify that in dev/test config (where `single_line_logging` is `false`), Logster is NOT attached and the custom formatter is NOT configured. Multi-line logs still appear in dev.
+- **Production config test**: Verify that loading `config/prod.exs` sets `config :phoenix, :logger, false`, `config :music_library, :single_line_logging, true`, and the custom formatter tuple.
+- **Verify**: `mix test` passes with coverage ≥75%.
+
+#### Step 9: OTP release verification
+
+> The production deployment uses an OTP release (`rel/overlays/bin/server`), not `mix phx.server`. The release has a different logging pipeline (Erlang `:logger` under the hood) that must be verified.
+
+- Build the release: `MIX_ENV=prod mix release`
+- Start the release and hit endpoints: `_build/prod/rel/music_library/bin/music_library start` (or `eval` for quick smoke test)
+- **Verify**:
+  - HTTP requests produce single logfmt lines
+  - LiveView connections produce single lines
+  - No multi-line log output appears
+  - Release starts without errors related to the new modules
+
+#### Step 10: Update documentation
+
+- **`docs/production-infrastructure.md`**: Add "Logging" section under Monitoring & Observability, describing:
+  - Logster for HTTP request logging (logfmt format)
+  - Custom telemetry handler for LiveView socket connections
+  - Custom formatter as single-line safety net
+  - Configuration details (formatter module, Logster attach point, config flag)
+  - Note that dev environment keeps default multi-line format
+- **`docs/architecture.md`**: Add new modules to the architecture summary:
+  - `MusicLibrary.Logger.SingleLineFormatter` under Business Logic Modules
+  - `MusicLibraryWeb.Telemetry.LogHandler` under Web Utility Modules
+  - Note that Logster is an external telemetry handler attached in `application.ex` (not a supervised process)
+- **Verify**: Both docs accurately reflect the new logging architecture. Run `mix docs` if available.
 
 ### Verifiability
 
 | Step | Verification |
 |---|---|
-| 1 | `mix compile` passes |
+| 0a | Inspect stdout with `MIX_ENV=prod mix phx.server` before any changes — confirm only endpoint start/stop, socket_connected, and error_rendered appear at `:info`+ |
+| 0b | Inspect Logster source in `deps/logster/` — check if `socket_connected` is handled; if yes, skip Step 4 |
+| 1 | `mix compile` passes, `Logster` module is available in IEx |
 | 2-6 | Start app with `MIX_ENV=prod mix phx.server`, hit endpoints, inspect stdout — all logs on one line |
-| 4 | Trigger LiveView connection (visit a LiveView page), verify single-line output |
+| 4 | Visit a LiveView page (`/collection`) in prod mode, verify single-line output in stdout |
-| 5 | `mix test` for any new unit tests, manual inspection of crash logs |
+| 5 | `mix test test/music_library/logger/single_line_formatter_test.exs` — all tests pass |
-| 7 | `rg` search returns empty |
+| 7 | Both `rg` searches (escaped `\n` and multi-line Logger calls) return empty for `lib/` |
-| 8 | Read docs, confirm accuracy |
+| 8 | `mix test` passes with ≥75% coverage; dev env test confirms multi-line output unchanged |
+| 9 | `MIX_ENV=prod mix release` succeeds; release binary starts without errors; log output is single-line |
+| 10 | Read both docs, confirm accuracy against implemented config and modules |
 
 ### Architecture impact analysis
 
@@ -115,7 +233,7 @@ The solution has three layers:
 
 **PubSub**: None affected.
 
-**Supervision tree**: No new children. Logster is a telemetry handler attached in `application.ex` — not a supervised process.
+**Supervision tree**: No new children. Logster is a telemetry handler attached in `application.ex` — not a supervised process. The custom telemetry handler is also a `:telemetry.attach` call, not a supervised process.
 
 **Routes**: None affected.
 
@@ -124,22 +242,30 @@ The solution has three layers:
 **UI components**: None affected.
 
 **Config changes**:
-- `mix.exs`: new dependency
+- `config/config.exs`: add `config :music_library, :single_line_logging, false`
-- `config/prod.exs`: 3 additions (phoenix logger disable, logster config, formatter config)
+- `mix.exs`: new dependency `{:logster, "~> 2.0.0-rc.5"}`
-- `lib/music_library/application.ex`: 1 addition (Logster attach call + telemetry handler attach)
+- `config/prod.exs`: 4 additions (phoenix logger disable, single_line_logging flag, logster config, formatter config)
+- `lib/music_library/application.ex`: 1 conditional block (Logster attach + optional telemetry handler attach)
 
 **New modules**:
-- `lib/music_library/logger/single_line_formatter.ex` — Logger.Formatter format function
+- `lib/music_library/logger/single_line_formatter.ex` — Logger.Formatter format/4 function; requires `@moduledoc` (Credo strict mode)
-- `lib/music_library_web/telemetry_log_handler.ex` — Phoenix socket telemetry handler
+- `lib/music_library_web/telemetry/log_handler.ex` — Phoenix socket telemetry handler (conditional on Step 0b); requires `@moduledoc`
+
+**New tests**:
+- `test/music_library/logger/single_line_formatter_test.exs` — unit tests for the formatter (newline replacement, iolist handling, metadata preservation)
+- `test/music_library_web/telemetry/log_handler_test.exs` — unit tests for the telemetry handler (single-line output, param filtering)
+- Integration assertions in existing or new test files for dev config unchanged
 
 **Migration/deprecation**: None needed. Old config is simply replaced.
 
+**Docker image impact**: Adding `logster` as a new Mix dependency changes `mix.lock`. The first deploy after this change will take longer because the Docker image rebuilds Logster from source. Subsequent deploys use the cached layer.
+
 ### Performance profile
 
 **Runtime complexity**: O(1) per log event.
 - Logster: string interpolation from telemetry metadata per HTTP request
 - Custom telemetry: same — one function call per socket connection
-- Custom formatter: one `String.replace/3` per log event (message size bounded by Logger truncation)
+- Custom formatter: one `IO.chardata_to_string/1` + `String.replace/3` per log event (message size bounded by Logger truncation)
 
 **Database queries**: None. This is purely output-side.
 
@@ -175,16 +301,7 @@ No manual production changes required. All configuration is in `config/prod.exs`
 
 **DNS/firewall**: None.
 
-**Rollout**: Standard deploy (push to main → GitHub Actions → Coolify). If issues arise, revert the commit and redeploy.
+**Rollout**: Standard deploy (push to main → GitHub Actions → Coolify). First deploy will be slower due to new dependency compilation (Logster). Subsequent deploys use cached Docker layer.
 
 **Rollback**: Revert to previous commit. No data migration needed.
-
-### Documentation updates
-
-- `docs/production-infrastructure.md`: Add "Logging" section under Monitoring & Observability, describing:
-  - Logster for HTTP request logging (logfmt format)
-  - Custom telemetry handler for LiveView socket connections
-  - Custom formatter as single-line safety net
-  - Configuration details (formatter module, Logster attach point)
-  - Note that dev environment keeps default multi-line format
 <!-- SECTION:PLAN:END -->