Slice 125: the credential filter cannot be switched off by a log line

CHANGELOG.md

@@ -24,6 +24,34 @@ evidence for each increment is retained by the maintainers and summarised here.
 
 ## 2026-09-26
 
+### `slice/125`: the credential filter cannot be switched off by a log line
+
+Trinity masks anything credential-shaped on its way into a log. That filter could be killed by
+ordinary events, and the way it failed was the worst available: the runtime removes a filter that
+raises, permanently, and carries on. Every line written after that point was unmasked, and nothing
+anywhere said so.
+
+Two kinds of input did it. The first was a log message built as a list whose tail is a piece of text
+rather than an end marker, which is a routine shape in this runtime and is what a dropped database
+connection produces. The second, found by a generated test rather than by hand, was any run of bytes
+that is not valid text. That one matters more: raw bytes are the form key material usually takes, so
+the filter failed on exactly the input most likely to be a secret, in the direction that switched
+masking off entirely.
+
+The filter now walks every shape of message content, replaces a run of bytes it cannot read as text
+rather than trying to match it, and, if anything unforeseen goes wrong, withholds the line's content
+instead of letting it through. Trinity also refuses to start if the filter is not installed, checked
+against the running logger rather than against configuration.
+
+The test that matters exercises the path that actually killed it, by logging through the runtime
+itself rather than calling the filter directly, and a companion test checks the line that came out
+was masked, so "still installed" cannot be satisfied by a filter that no longer does anything.
+Confirmed on a running server: no removals across a full approval turn, against a run before the fix
+where the filter was removed during start-up.
+
+Verified: gate green at exit 0; 844 tests passing; coverage 80.31%, level with the previous
+increment.
+
 ### `slice/126`: nothing about an approval is discarded in silence
 
 A decision the owner makes that arrives when there is no held call to apply it to used to be thrown

lib/trinity/application.ex

@@ -123,16 +123,50 @@ defmodule Trinity.Application do
   # The lock lives in the data directory the database defaults to. A deployment that points
   # DATABASE_PATH elsewhere still locks the data directory, which is the thing two instances
   # would otherwise share; the test environment points it at a temporary directory.
+  # Slice 125: installed, then *verified*. The previous version swallowed every error, including a
+  # failure to install, so an application that could not redact its logs started anyway and said
+  # nothing. Redaction is not optional and a missing filter is not a warning.
   defp install_log_redaction do
-    :logger.add_primary_filter(
-      :trinity_redaction,
-      {&Trinity.Telemetry.Redaction.filter/2, nil}
-    )
-  rescue
-    # Already installed (a release that restarts the application, or a test that starts it twice).
-    _ -> :ok
-  catch
-    _, _ -> :ok
+    case :logger.add_primary_filter(
+           :trinity_redaction,
+           {&Trinity.Telemetry.Redaction.filter/2, nil}
+         ) do
+      :ok ->
+        :ok
+
+      # Already installed: a release that restarts the application, or a test that starts it twice.
+      {:error, {:already_exist, _}} ->
+        :ok
+
+      {:error, reason} ->
+        raise "could not install the log redaction filter: #{inspect(reason)}"
+    end
+
+    verify_log_redaction!()
+  end
+
+  @doc """
+  Raises unless the log redaction filter is installed, read from the logger itself.
+
+  Called at boot, after installation, so the application cannot start unfiltered. Read from
+  `:logger.get_primary_config/0` rather than from configuration, because what matters is whether the
+  filter is in the handler, not whether something asked for it to be.
+
+  OTP removes a primary filter that raises, permanently, and continues without it, which is the
+  failure this exists to make impossible to reach silently. `Trinity.Telemetry.Redaction.filter/2`
+  is written so that it cannot raise; this is the check that the arrangement actually holds.
+  """
+  @spec verify_log_redaction!() :: :ok
+  def verify_log_redaction! do
+    names = for {name, _fun} <- :logger.get_primary_config().filters, do: name
+
+    if :trinity_redaction in names do
+      :ok
+    else
+      raise "the log redaction filter is not installed (primary filters: #{inspect(names)}). " <>
+              "Refusing to run: every log line written from here would be unredacted, and " <>
+              "nothing downstream would say so."
+    end
   end
 
   defp lock_dir do

lib/trinity/telemetry/redaction.ex

@@ -14,6 +14,30 @@ defmodule Trinity.Telemetry.Redaction do
   known to be one, and it truncates long messages. Over-masking a log line costs a reader some
   context; under-masking one puts a key on disk.
 
+  ## It cannot raise, and that is a security property (slice 125)
+
+  OTP removes a primary filter that raises, **permanently**, and carries on. Everything logged
+  after that point is unredacted while the system believes it is not. So the interesting question
+  about this module is not what it masks but whether it can be made to fail, and the answer has to
+  be no for every input rather than for the inputs someone thought of.
+
+  Two ways it used to fail, both found on a running server rather than by a test:
+
+  - `Enum.map/2` was called on the message body. OTP chardata is routinely an **improper** list
+    whose tail is a binary rather than `[]`, and `Enum.map/2` raises `FunctionClauseError` on one.
+    A `db_connection` disconnect is enough to produce it. Lists are now walked by a function that
+    handles an improper tail, and `{:string, chardata}` is flattened rather than mapped.
+  - `Regex.replace/3` was called on any binary. A binary that is not valid UTF-8 raises, and raw
+    key material is exactly the kind of thing that arrives as bytes rather than text. An invalid
+    binary is now replaced outright rather than matched: it is not text a reader was meant to see,
+    and it is the shape a secret is most likely to take.
+
+  Beyond both, `filter/2` wraps its own work and degrades to an event that says the content was
+  withheld. Losing a log line's detail is recoverable; running unfiltered is not.
+
+  `Trinity.Application.verify_log_redaction!/0` refuses to let the application boot without this
+  filter installed, so "it was quietly missing" is not a state the system can be in.
+
   ## What it cannot do
 
   It sees the message and its metadata, not the intent. A key embedded in a sentence with no
@@ -22,6 +46,7 @@ defmodule Trinity.Telemetry.Redaction do
   """
 
   @max_chars 2_000
+  @max_reason_chars 200
 
   # Shapes rather than names. Each is anchored on a prefix that exists to be recognised, which is
   # the property that makes a credential's own format give it away.
@@ -33,33 +58,66 @@ defmodule Trinity.Telemetry.Redaction do
      "\\1\\2[REDACTED]"}
   ]
 
+  # Metadata worth keeping when an event has to be degraded: where a line came from, never what it
+  # said. None of these can carry a credential.
+  @safe_meta_keys [
+    :time,
+    :pid,
+    :gl,
+    :line,
+    :file,
+    :mfa,
+    :module,
+    :function,
+    :application,
+    :domain
+  ]
+
   @doc """
-  The filter. Returns the event with its message and metadata masked, never `:stop`.
+  The filter. Returns the event with its message and metadata masked, never `:stop`, never raising.
 
   Never `:stop`, on purpose: a filter that drops a line to avoid printing a secret also drops the
   evidence that something happened. Masking keeps the event and removes the value.
+
+  Never raising, also on purpose, and for a stronger reason: OTP removes a raising filter from the
+  handler permanently, so one unexpected shape would disable redaction for the life of the node.
+  Anything the walk cannot handle degrades to an event whose content is withheld.
   """
   @spec filter(map(), term()) :: map()
   def filter(%{msg: msg, meta: meta} = event, _opts) do
     %{event | msg: redact_msg(msg), meta: redact_meta(meta)}
+  rescue
+    e -> withheld(event, e)
+  catch
+    kind, reason -> withheld(event, {kind, reason})
   end
 
   def filter(event, _opts), do: event
 
-  @doc "Masks credential-shaped substrings in a binary."
+  @doc """
+  Masks credential-shaped substrings in a binary.
+
+  A binary that is not valid UTF-8 is replaced rather than matched. The patterns cannot be applied
+  to it (`Regex.replace/3` raises), it is not text a reader was meant to read, and bytes are the
+  shape key material most often takes.
+  """
   @spec redact(term()) :: term()
   def redact(text) when is_binary(text) do
-    Enum.reduce(@patterns, text, fn {re, replacement}, acc ->
-      Regex.replace(re, acc, replacement)
-    end)
+    if String.valid?(text) do
+      Enum.reduce(@patterns, text, fn {re, replacement}, acc ->
+        Regex.replace(re, acc, replacement)
+      end)
+    else
+      "[REDACTED-BINARY #{byte_size(text)} bytes]"
+    end
   end
 
   def redact(other), do: other
 
   @doc "Truncates to the logging limit, saying how much was dropped rather than trailing off."
   @spec truncate(binary(), pos_integer()) :: binary()
   def truncate(text, max \\ @max_chars) when is_binary(text) do
-    if String.length(text) > max do
+    if String.valid?(text) and String.length(text) > max do
       String.slice(text, 0, max) <> "… [#{String.length(text) - max} more characters]"
     else
       text
@@ -70,22 +128,61 @@ defmodule Trinity.Telemetry.Redaction do
   @spec max_chars() :: pos_integer()
   def max_chars, do: @max_chars
 
-  defp redact_msg({:string, text}) when is_binary(text),
-    do: {:string, text |> redact() |> truncate()}
-
-  defp redact_msg({format, args}) when is_list(args), do: {format, Enum.map(args, &redact_term/1)}
+  # `{:string, chardata}` is flattened to a binary rather than walked element by element. A binary
+  # is itself valid chardata, so nothing downstream can tell the difference, and it removes every
+  # question about improper tails, nested lists and codepoints in one step. It must be matched
+  # before the `{format, args}` clause below, which would otherwise catch it: an iolist is a list.
+  defp redact_msg({:string, chardata}), do: {:string, chardata |> to_text() |> redact_text()}
   defp redact_msg({:report, report}), do: {:report, redact_term(report)}
+  defp redact_msg({format, args}) when is_list(args), do: {format, redact_list(args)}
   defp redact_msg(other), do: other
 
   defp redact_meta(meta) when is_map(meta),
     do: Map.new(meta, fn {k, v} -> {k, redact_term(v)} end)
 
   defp redact_meta(meta), do: meta
 
-  defp redact_term(v) when is_binary(v), do: v |> redact() |> truncate()
-  defp redact_term(v) when is_list(v), do: Enum.map(v, &redact_term/1)
+  defp redact_term(v) when is_binary(v), do: redact_text(v)
+  defp redact_term(v) when is_list(v), do: redact_list(v)
   defp redact_term(%{__struct__: _} = v), do: v
   defp redact_term(v) when is_map(v), do: Map.new(v, fn {k, val} -> {k, redact_term(val)} end)
   defp redact_term({a, b}), do: {redact_term(a), redact_term(b)}
   defp redact_term(v), do: v
+
+  # The defect slice 125 exists for. `Enum.map/2` raises `FunctionClauseError` on an improper list,
+  # and OTP chardata is routinely improper. This keeps the shape, tail and all, and redacts the
+  # tail rather than walking off the end of it.
+  defp redact_list([]), do: []
+  defp redact_list([head | tail]), do: [redact_term(head) | redact_list(tail)]
+  defp redact_list(tail), do: redact_term(tail)
+
+  defp redact_text(text) when is_binary(text), do: text |> redact() |> truncate()
+
+  # Chardata that `IO.chardata_to_string/1` refuses is still an event that has to be logged, so it
+  # is inspected rather than dropped. `inspect/1` is total where the conversion is not.
+  defp to_text(chardata) do
+    IO.chardata_to_string(chardata)
+  rescue
+    _ -> inspect(chardata)
+  catch
+    _, _ -> inspect(chardata)
+  end
+
+  # The last line of the last line. Reached only if the walk above raised on something no test
+  # anticipated, which is precisely when passing the event through unmasked would be worst.
+  defp withheld(event, why) do
+    reason = why |> inspect() |> binary_slice(0, @max_reason_chars)
+
+    %{
+      event
+      | msg:
+          {:string,
+           "[REDACTED: this log event could not be filtered and its content is withheld. " <>
+             "Reason: #{reason}]"},
+        meta: safe_meta(event)
+    }
+  end
+
+  defp safe_meta(%{meta: meta}) when is_map(meta), do: Map.take(meta, @safe_meta_keys)
+  defp safe_meta(_), do: %{}
 end