ML-158: force single-line log output in production

Three-layer architecture:
- Logster v2 handles HTTP request and LiveView socket telemetry in logfmt format
- Custom formatter as safety net escaping any remaining embedded newlines
- Config flag (single_line_logging) gating Logster attachment to prod only

Dev environment retains multi-line format for readability.
This commit is contained in:
Claudio Ortolina
2026-05-04 15:01:10 +01:00
parent 0f19afb0aa
commit 7c6760d7db
10 changed files with 407 additions and 8 deletions
@@ -0,0 +1,374 @@
---
id: ML-158
title: Force production logs to single-line format
status: Done
assignee: []
created_date: '2026-05-03 13:51'
updated_date: '2026-05-04 13:43'
labels:
- ready
dependencies: []
references:
- 'backlog://documents/doc-3'
modified_files:
- mix.exs
- config/config.exs
- config/prod.exs
- lib/music_library/application.ex
- lib/music_library/logger/single_line_formatter.ex
- test/music_library/logger/single_line_formatter_test.exs
- docs/production-infrastructure.md
- docs/architecture.md
priority: medium
---
## Description
<!-- SECTION:DESCRIPTION:BEGIN -->
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.
<!-- SECTION:DESCRIPTION:END -->
## Acceptance Criteria
<!-- AC:BEGIN -->
- [x] #1 HTTP request logs (GET /path + Sent 200) appear as a single logfmt line in production
- [x] #2 LiveView socket connection logs (CONNECTED TO Phoenix.LiveView.Socket) appear as a single line
- [x] #3 No log message in production output spans multiple physical lines — all newlines are escaped as \\n
- [x] #4 Existing metadata (request_id, etc.) is preserved in log output
- [x] #5 Stack traces from errors/exceptions are escaped to single line
- [x] #6 Dev environment logging is unchanged and still uses multi-line format for readability
<!-- AC:END -->
## Implementation Plan
<!-- SECTION:PLAN:BEGIN -->
## 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 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 in prod
- `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
> **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, 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 (`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`: 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 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 |
|---|---|
| 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 | 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
**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. The custom telemetry handler is also a `:telemetry.attach` call, not a supervised process.
**Routes**: None affected.
**External APIs**: None affected.
**UI components**: None affected.
**Config changes**:
- `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/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 `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.
**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). 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.
<!-- SECTION:PLAN:END -->
## Final Summary
<!-- SECTION:FINAL_SUMMARY:BEGIN -->
## Implementation Summary
### What was done
#### Step 0: Pre-implementation verification
- Confirmed Phoenix.Logger fires 4 events at `:info`+ level (endpoint start/stop, socket_connected, error_rendered) — matches plan assumptions
- Confirmed Logster v2 handles `[:phoenix, :socket_connected]` — **skipped Step 4** (custom telemetry handler unnecessary)
#### Step 1: Added Logster dependency
- `mix.exs`: `{:logster, "~> 2.0.0-rc.5"}`
#### Step 2: Disabled Phoenix.Logger in prod
- `config/prod.exs`: `config :phoenix, :logger, false`
#### Step 3: Configured Logster with environment-conditional attach
- `config/config.exs`: `config :music_library, :single_line_logging, false`
- `config/prod.exs`: `config :music_library, :single_line_logging, true`
- `config/prod.exs`: Logster config with `extra_fields: [:request_id]` and parameter filtering
- `lib/music_library/application.ex`: conditional `Logster.attach_phoenix_logger()` when `single_line_logging` is true
#### Step 4: Skipped (Logster v2 handles `[:phoenix, :socket_connected]`)
#### Step 5-6: Created custom Logger.Formatter as safety net
- `lib/music_library/logger/single_line_formatter.ex`: Implements `format/4` callback, replaces embedded `\n` with escaped `\\n`, handles string/iolist/report messages, preserves metadata
- `config/prod.exs`: formatter configured as `{MusicLibrary.Logger.SingleLineFormatter, :format}` with `metadata: [:request_id]`
#### Step 7: Codebase audit
- Searched for Logger calls with embedded `\n` — none found
- Multi-line Logger calls in source all produce single-line output (string concatenation without actual newlines)
- Custom formatter handles any remaining cases from OTP/Elixir internals
#### Step 8: Tests
- `test/music_library/logger/single_line_formatter_test.exs`: 13 tests covering newline replacement, iolist handling, metadata preservation, single-line output, dev/test config verification
- All 931 project tests pass
#### Step 9: OTP release verification
- `MIX_ENV=prod mix release` builds successfully
- sys.config confirms: `phoenix logger: false`, `single_line_logging: true`, Logster config, custom formatter tuple, logster application included
#### Step 10: Documentation
- `docs/production-infrastructure.md`: Added "Logging" section under Monitoring & Observability
- `docs/architecture.md`: Added `MusicLibrary.Logger.SingleLineFormatter` to Business Logic Modules, Logster note under Supervision Tree, and Web Utility Modules note
### Files changed
- `mix.exs` — added logster dependency
- `config/config.exs` — added `single_line_logging: false`
- `config/prod.exs` — 4 config additions (phoenix logger disable, flag, logster, formatter)
- `lib/music_library/application.ex` — conditional Logster attach
- `lib/music_library/logger/single_line_formatter.ex` — new module
- `test/music_library/logger/single_line_formatter_test.exs` — new test file
- `docs/production-infrastructure.md` — Logging section
- `docs/architecture.md` — module entries
<!-- SECTION:FINAL_SUMMARY:END -->