diff --git a/backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md b/backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md index 8da5a7c3..f7286747 100644 --- a/backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md +++ b/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 -- `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 2: Disable Phoenix.Logger in prod -#### Step 3: Attach Logster in application.ex -- `lib/music_library/application.ex`: add conditional `Logster.attach_phoenix_logger()` for `:prod` env -- **Verify**: In prod, HTTP requests produce a single logfmt line like `method=GET path=/health ... status=200 duration=696` +- `config/prod.exs`: add `config :phoenix, :logger, false` +- **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**: 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 -- Attach handler in `application.ex` (prod-only) alongside Logster -- **Verify**: LiveView connection produces one line instead of 4+ +- Outputs a single line with transport, serializer, duration, result, and filtered params +- Respects Phoenix's `:filter_parameters` config — reuse `Phoenix.Logger.filter_values/2` for parameter filtering +- 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 -- Replaces `\n` with `\n` in message before delegating to default formatter -- **Verify**: Any Logger call with embedded newlines (stack traces, OTP reports) produces one line. Test with `Logger.error("line1\nline2\nline3")` +- Implements `format/4` function (`level, message, timestamp, metadata`) returning `IO.chardata()` +- Replaces literal `\n` (newline character) with escaped `\\n` (backslash + n) in the message +- 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 -- Search for `Logger.` calls with string interpolation containing `\n` -- Rewrite to single-line strings or use `Logster.info/1` style -- **Verify**: `rg 'Logger\.(info|error|warning|debug)\b.*\\n' lib/` returns empty +- `config/prod.exs`: override the default formatter: + ```elixir + config :logger, :default_formatter, + 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 -- Update `docs/production-infrastructure.md` — add logging section describing the three-layer approach -- **Verify**: Docs reflect the new logging architecture +#### Step 7: Audit codebase for multi-line Logger calls (best-effort) + +> **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 | -| 5 | `mix test` for any new unit tests, manual inspection of crash logs | -| 7 | `rg` search returns empty | -| 8 | Read docs, confirm accuracy | +| 4 | Visit a LiveView page (`/collection`) in prod mode, verify single-line output in stdout | +| 5 | `mix test test/music_library/logger/single_line_formatter_test.exs` — all tests pass | +| 7 | Both `rg` searches (escaped `\n` and multi-line Logger calls) return empty for `lib/` | +| 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/prod.exs`: 3 additions (phoenix logger disable, logster config, formatter config) -- `lib/music_library/application.ex`: 1 addition (Logster attach call + telemetry handler attach) +- `config/config.exs`: add `config :music_library, :single_line_logging, false` +- `mix.exs`: new dependency `{:logster, "~> 2.0.0-rc.5"}` +- `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_web/telemetry_log_handler.ex` — Phoenix socket telemetry handler +- `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 (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