How :logger and report_cb actually work

This document explains, precisely and with evidence, what happens today when code calls Logger.info/2 (or :logger.info/2 directly) with a structured report (a map or keyword list) instead of a string — with and without a report_cb — and exactly where the "structure gets destroyed" failure mode described in the Elixir Forum thread "What do we do with logging in libraries?" (based on martosaur's post) actually occurs in the pipeline.

Every claim below was checked against a real :logger/Logger runtime (Erlang/OTP 29, Elixir 1.20) with a throwaway script, not just read off documentation. The scripts are reproduced (trimmed) inline so the behavior can be re-verified independently.

1. The shape of a log event

Internally, :logger represents every log call as a "log event" — a map with (at minimum) :level, :msg, and :meta keys. The :msg field is one of exactly two shapes:

• {:string, chardata} — an already-rendered message. There is no structure here; it's text.
• {:report, report} — a report, where report is a map or a keyword list of arbitrary application data. This is what "structured logging" means at the OTP level.

Which shape you get is determined entirely by what you pass as the first argument to Logger.info/2 (or :logger.info/2, :logger.log/3, etc.) — not by anything a handler or formatter does later.

report_cb — a function that knows how to render a specific report shape into text — does not live in :msg. It lives in :meta, as meta.report_cb, alongside the rest of the event's metadata (pid, timestamp, group leader, application-specific metadata, etc.).

This separation is the whole story: the report and its renderer are two independent pieces of data traveling on the same event, and nothing about :logger's core dispatch mechanism ever collapses one into the other.

2. Verified: :logger dispatches the identical raw event to every handler

:logger handlers are independent; each one is invoked with the log event by the same core dispatch code, and formatting is something a handler (or its configured formatter) does to its own copy of the event when producing output — it is not a step that happens before dispatch and is not shared across handlers.

Verified with two handlers attached simultaneously, one report with a report_cb:

:logger.add_handler(:capture_a, CaptureHandler, %{config: %{owner: self(), tag: :handler_a}, filter_default: :log})
:logger.add_handler(:capture_b, CaptureHandler, %{config: %{owner: self(), tag: :handler_b}, filter_default: :log})

report_cb = fn %{event: event, attempt: attempt} -> {"retrying ~s (attempt ~p)", [event, attempt]} end
:logger.info(%{event: :http_retry, attempt: 3}, %{report_cb: report_cb})

Both handlers received the exact same event:

msg: {:report, %{event: :http_retry, attempt: 3}}
meta: %{..., report_cb: #Function<...>}

Meanwhile Elixir's own default console handler, attached in the same VM, independently called the report_cb to print retrying http_retry (attempt 3) to the console. That rendering had zero effect on what capture_a and capture_b received — they still got the untouched map. Calling report_cb is something a formatter does for its own output; it cannot reach across and mutate what other handlers see.

Conclusion: if the only thing touching your log events is ordinary :logger handler dispatch, a report_cb can never destroy structure for another consumer. The destruction described in the forum thread has to be happening somewhere else.

3. Verified: what Elixir's Logger does with a map, with no report_cb

Logger.info(%{event: :cache_miss, key: "user:42"})

captured event: msg: {:report, %{key: "user:42", event: :cache_miss}}, and critically meta has no report_cb key at all.

Console output: [key: "user:42", event: :cache_miss] — Elixir's default formatter falls back to a generic keyword/map rendering when no report_cb is supplied. It does not crash, and it does not need a report_cb to produce some text — but that fallback rendering is generic and not particularly readable, which is the practical reason to supply your own report_cb.

A keyword list behaves identically: msg: {:report, [event: ..., key: ...]}.

Structure is intact by default. Omitting report_cb costs you readability in the console, not structure.

4. Verified: the real destruction happens at the call site, before :logger ever sees the data

Logger.info("cache miss for user:42")
# => msg: {:string, "cache miss for user:42"}

report = %{event: :cache_miss, key: "user:42"}
Logger.info("cache event: #{inspect(report)}")
# => msg: {:string, "cache event: %{key: \"user:42\", event: :cache_miss}"}

Both produce {:string, ...}. The second case is the one that actually matters for the forum complaint: the library author had a structured map, and threw it away themselves by interpolating it into a string before Logger.info/2 was ever called. By the time :logger sees this call, there is no map anywhere in the system — not in :msg, not in :meta — to hand to a JSON handler. No formatter, no report_cb, no clever handler configuration downstream can recover data that was already flattened to text before the log call happened.

This is complaint #1 from the thread ("libraries log unstructured interpolated strings") and it is a call-site problem, full stop. It is also the failure mode Clarion's API is designed to make structurally impossible: Clarion.report/3 requires a map/keyword report as the primary argument, so there is no code path that lets a caller hand it a pre-rendered string instead.

5. Verified: the one place inside :logger that can destroy structure for everyone

:logger supports primary filters (:logger.add_primary_filter/2) — functions that run once per log event, before any handler is invoked, and whose return value (a possibly-modified event) is what gets passed to every handler and to any remaining primary filters. This is documented OTP behavior, not a bug, and it exists for legitimate purposes (domain-based routing, event translation — Elixir itself has historically used primary filters to turn certain OTP/SASL reports into friendlier reports).

But a primary filter is a single, global, shared processing step, and a badly written one can do exactly what the forum thread describes:

overeager_filter = fn log_event, _extra ->
  case log_event do
    %{msg: {:report, report}, meta: %{report_cb: cb}} when is_function(cb, 1) ->
      {format, args} = cb.(report)
      rendered = :io_lib.format(format, args) |> IO.iodata_to_binary()
      %{log_event | msg: {:string, rendered}}   # <-- discards `report` for EVERYONE

    _ -> log_event
  end
end

:logger.add_primary_filter(:overeager_renderer, {overeager_filter, []})

With this filter installed, the same call that previously produced msg: {:report, %{event: :http_retry, attempt: 2}} for a raw-event consumer now produces msg: {:string, "retry http_retry (2)"} for every handler in the system — including a JSON/structured handler that never asked for rendering and has no idea the map ever existed.

This is complaint #3, precisely located: it is not a :logger design flaw and it does not require a malicious actor — it just requires one piece of code, anywhere in the dependency tree, with primary-filter access, that treats "render for humans" and "the canonical representation of this event" as the same thing, and eagerly does the former in place of preserving the latter. Primary filters run before handler selection even happens, so there is no way for a downstream handler to opt out or recover the discarded data.

The practical takeaway for library authors: never call your own report_cb and pass the result onward as if it were the log data — a report_cb is a rendering hint for something else to call, at the point it actually needs text, not a preprocessing step for the report itself. Never install a primary filter that replaces {:report, _} with {:string, _}. (Clarion's report_cb is only ever attached to metadata for a consumer to call — Clarion itself never invokes it and never rewrites :msg.)

6. The report_cb contract has two arities

Per OTP's :logger types, a report_cb may be either:

• fun(report) -> {format_string, args} — rendered later via :io_lib.format/2 semantics (what all the experiments above used), or
• fun(report, report_cb_config) -> chardata — a two-argument form that additionally receives the calling handler's formatter config (e.g. chars_limit, depth, single_line), so a report_cb can honor a specific handler's formatting preferences.

Clarion's default_report_cb/1 implements the 1-arity form; the 2-arity form is worth supporting as a future enhancement for callers who want their custom report_cb to respect a handler's single_line/depth settings, but is out of scope for v1 (see design_decisions.md).

7. A closed historical door: legacy Logger backends

Before Elixir 1.15, third-party "Logger backends" were :gen_event handlers added via config :logger, backends: [...], implemented through a compatibility module (Logger.Backends). That shim worked by having Elixir's Logger application pre-render the message to text before handing it to each backend — so under that legacy API, every backend genuinely only ever saw already-flattened text, never the raw report.

Verified on this install: Code.ensure_loaded?(Logger.Backends) and Code.ensure_loaded?(:logger_backends) are both false — the module no longer ships. On modern Elixir, native :logger handlers (as used in all the experiments above) are the only supported mechanism, and they behave as described in sections 2–5. This legacy detail is included only because it partially explains complaint #4 ("Logger configuration quirks") — some still-circulating advice and older library integration guides were written against a backend API that worked fundamentally differently from today's handlers, and porting that advice forward without re-checking it is a real source of confusion.

8. Complaint #4 in concrete terms: default handler vs. added handlers

Elixir's default console handler is set up specially by the :logger application at boot, using Elixir-specific config keys (config :logger, :console, config :logger, :default_formatter, config :logger, :default_handler) that apply Elixir conveniences (colors, metadata formatting, level-based filtering shortcuts) automatically. A handler you add yourself — via config :logger, :handlers (a list of {module, id, config} tuples merged into :logger's handler set at boot — Elixir's own mechanism for declaring handlers ahead of application start) or by calling :logger.add_handler/3 directly at runtime — gets none of that for free. It is a plain OTP handler: you must specify its own :formatter (:logger_formatter or a custom module), its own :level, and its own metadata keys to include. This is a real, frequently-hit surprise, but it is orthogonal to Clarion's contract — Clarion produces a correctly-shaped event at the call site; how any given handler is configured to consume it is the operator's/application's concern, not the library author's.

Summary: where the failure actually lives

Clarion's correctness property (verified by test, not assumed) is narrower and more honest than "fixes logging in the Elixir ecosystem": it guarantees that what Clarion hands to :logger keeps the raw report in :msg and any renderer strictly in :meta.report_cb, for every call made through Clarion.report/3. It cannot stop a badly written primary filter installed by some other dependency from destroying structure downstream — no library sitting at the call site can, since that damage happens after the call returns. What it can do is remove the two most common ways library authors sabotage themselves before that point: logging a plain string, or interpolating a report into one.