diff --git a/backlog/docs/doc-3 - Research-Force-production-logs-to-single-line-format.md b/backlog/docs/doc-3 - Research-Force-production-logs-to-single-line-format.md new file mode 100644 index 00000000..d6977848 --- /dev/null +++ b/backlog/docs/doc-3 - Research-Force-production-logs-to-single-line-format.md @@ -0,0 +1,78 @@ +--- +id: doc-3 +title: 'Research: Force production logs to single-line format' +type: other +created_date: '2026-05-03 13:53' +updated_date: '2026-05-03 14:23' +--- +# Research: Force production logs to single-line format + +## Current state + +**Config** (`config/config.exs`): +```elixir +config :logger, :default_formatter, + format: "$time $metadata[$level] $message\n", + metadata: [:request_id] +``` + +**Override** (`config/prod.exs`): +```elixir +config :logger, level: :info +``` + +**Log sources in prod**: + +| Source | Produces | Problem | +|---|---|---| +| `Phoenix.Logger` (telemetry) | `GET /health` + `Sent 200 in Xms` | Two separate lines for one request — can't reverse | +| `Phoenix.Logger` (telemetry) | `CONNECTED TO Phoenix.LiveView.Socket...` | One event with embedded `\n` — 4+ lines | +| Custom `Logger.info/error/...` | Varies | Some may be multi-line | +| OTP / stack traces | Crash reports | Multi-line | + +`Phoenix.Logger` is auto-attached by Phoenix.Endpoint and handles telemetry events including `[:phoenix, :endpoint, :start]`, `[:phoenix, :endpoint, :stop]`, and `[:phoenix, :socket_connected]`. + +## Chosen approach: Option 2 (comprehensive) + +1. **Disable Phoenix.Logger** — `config :phoenix, :logger, false` in prod +2. **Add Logster v2** — `Logster.attach_phoenix_logger()` for single-line HTTP request logging (logfmt format) +3. **Custom telemetry handler** — for `[:phoenix, :socket_connected]` LiveView handshakes (if not covered by Logster) +4. **Custom Logger.Formatter** — safety net replacing `\n` → `\\n` in all remaining messages +5. **Code audit** — fix multi-line Logger calls in project code + +### Why Logster v2 over v1 + +v2 (`~> 2.0.0-rc.5`) uses `Logster.attach_phoenix_logger()` in `application.ex` instead of replacing a plug in the endpoint. This is the modern approach that works with Phoenix's telemetry-based logging architecture. It outputs logfmt (`key=value`) format by default, merging the `GET /path` and `Sent 200` lines into one. + +### Architecture impact + +| Touchpoint | Change | +|---|---| +| `config/prod.exs` | Add `config :phoenix, :logger, false` + Logster config + formatter config | +| `lib/music_library/application.ex` | Add conditional `Logster.attach_phoenix_logger()` | +| `lib/music_library_web/telemetry_log_handler.ex` | **New module** — handles socket_connected telemetry | +| `lib/music_library/logger/single_line_formatter.ex` | **New module** — Logger.Formatter format function | +| `mix.exs` | Add `{:logster, "~> 2.0.0-rc.5"}` | +| Docs | Update `docs/production-infrastructure.md` with logging config | + +### Performance + +- Logster: one telemetry handler invocation per request, logfmt formatting is string interpolation — negligible overhead +- Custom formatter: one `String.replace/3` per log event, Logger already truncates messages — negligible +- No CPU or memory concerns at the log volume of a personal app + +### Dependencies + +- `logster ~> 2.0.0-rc.5` (1.9M downloads, MIT license, active maintenance) + +### Cost + +- None — no paid services involved + +--- + +## Questions resolved + +1. **Newline style**: Replace `\n` with `\\n` (escaped, traceable) +2. **Scope**: Prod-only; dev keeps current multi-line format for readability +3. **Module naming**: `MusicLibrary.Logger.SingleLineFormatter` and `MusicLibraryWeb.TelemetryLogHandler` 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 new file mode 100644 index 00000000..8da5a7c3 --- /dev/null +++ b/backlog/tasks/ml-158 - Force-production-logs-to-single-line-format.md @@ -0,0 +1,190 @@ +--- +id: ML-158 +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' +labels: [] +dependencies: [] +references: + - 'backlog://documents/doc-3' +priority: medium +--- + +## Description + + +When running in production, logs spanning multiple lines create issues — they cannot be easily filtered, and log output cannot be reversed reliably. We need to configure the `prod` environment to output logs on one line with appropriate metadata. + + +## Acceptance Criteria + +- [ ] #1 HTTP request logs (GET /path + Sent 200) appear as a single logfmt line in production +- [ ] #2 LiveView socket connection logs (CONNECTED TO Phoenix.LiveView.Socket) appear as a single line +- [ ] #3 No log message in production output spans multiple physical lines — all newlines are escaped as \\n +- [ ] #4 Existing metadata (request_id, etc.) is preserved in log output +- [ ] #5 Stack traces from errors/exceptions are escaped to single line +- [ ] #6 Dev environment logging is unchanged and still uses multi-line format for readability + + +## Implementation Plan + + +## Implementation Plan: Force production logs to single-line format + +### Objective alignment + +The problem: multi-line log output in production prevents reliable line-based filtering and makes log output impossible to reverse. Log sources include HTTP request logs (two separate `Logger.info` calls from `Phoenix.Logger`), LiveView handshake logs (single `Logger.info` with embedded newlines), and any custom `Logger` calls that pass multi-line strings. + +The solution has three layers: +1. **Logster** replaces `Phoenix.Logger` for HTTP request logging — merges `GET + Sent` into one logfmt line +2. **Custom telemetry handler** replaces `Phoenix.Logger`'s `[:phoenix, :socket_connected]` handler — flattens LiveView handshake into one line +3. **Custom Logger.Formatter** acts as a universal safety net — replaces any remaining embedded newlines with escaped `\n` in ALL log messages + +### Simplicity and alternatives considered + +**Chosen**: Logster v2 + custom telemetry handler + custom formatter. Handles all log sources explicitly, with a safety net for anything missed. + +**Rejected**: Custom formatter alone (Route A) — would flatten LiveView handshakes but HTTP requests remain two separate lines (they're separate log events, not one multi-line event). This fails to solve the reversibility problem for HTTP logs. + +**Rejected**: JSON structured logging (Route B) — adds a dependency and makes terminal `grep`/`tail` harder. Overkill for a personal app without log aggregation. + +**Deferred**: Migrating custom `Logger` calls to `Logster.info/1` key=value format — can be done incrementally after this task. + +### Completeness and sequencing + +#### 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 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` + +#### Step 4: Create custom telemetry handler for LiveView socket connections +- New module `lib/music_library_web/telemetry_log_handler.ex` +- 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+ +- **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")` + +#### 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 + +#### Step 8: Update documentation +- Update `docs/production-infrastructure.md` — add logging section describing the three-layer approach +- **Verify**: Docs reflect the new logging architecture + +### Verifiability + +| Step | Verification | +|---|---| +| 1 | `mix compile` passes | +| 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 | + +### Architecture impact analysis + +**Schemas**: None affected. + +**Contexts**: None affected. + +**PubSub**: None affected. + +**Supervision tree**: No new children. Logster is a telemetry handler attached in `application.ex` — not a supervised process. + +**Routes**: None affected. + +**External APIs**: None affected. + +**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) + +**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 + +**Migration/deprecation**: None needed. Old config is simply replaced. + +### 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) + +**Database queries**: None. This is purely output-side. + +**Memory**: Negligible. No accumulated state. + +**N+1 risks**: None. No database interaction. + +**Latency/throughput**: All operations happen synchronously in the logging process. String replacement on bounded-size strings is microseconds. At the log volume of a single-user personal app (~dozens of requests/minute), overhead is unmeasurable. + +### Benchmarking requirements + +None needed. The operations are: +- String replacement on logger-truncated messages (bounded by default 4KB or configurable) +- String interpolation from telemetry metadata (no IO, no computation) +These are trivially fast. If future log volume increases by orders of magnitude, the `Logger` overload protection (message dropping at >500/sec) will engage before our formatter becomes a bottleneck. + +### Cost profile + +No paid resources consumed. +- Logster: MIT license, free +- No API calls, no compute, no storage costs +- No third-party services + +### Production infrastructure steps + +No manual production changes required. All configuration is in `config/prod.exs` and `application.ex`, deployed via the standard CI/CD pipeline. + +**Environment variables**: None new. + +**Service provisioning**: None. + +**Database migrations**: None. + +**DNS/firewall**: None. + +**Rollout**: Standard deploy (push to main → GitHub Actions → Coolify). If issues arise, revert the commit and redeploy. + +**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 +