diff --git a/CHANGELOG.md b/CHANGELOG.md index 190d063..d50216b 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/lib/trinity/application.ex b/lib/trinity/application.ex index 2643fe8..f5de26d 100644 --- a/lib/trinity/application.ex +++ b/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 diff --git a/lib/trinity/telemetry/redaction.ex b/lib/trinity/telemetry/redaction.ex index 520dad7..db468a6 100644 --- a/lib/trinity/telemetry/redaction.ex +++ b/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,25 +58,58 @@ 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 @@ -59,7 +117,7 @@ defmodule Trinity.Telemetry.Redaction do @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,11 +128,13 @@ 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), @@ -82,10 +142,47 @@ defmodule Trinity.Telemetry.Redaction do 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 diff --git a/test/trinity/telemetry/redaction_chardata_test.exs b/test/trinity/telemetry/redaction_chardata_test.exs new file mode 100644 index 0000000..91c0636 --- /dev/null +++ b/test/trinity/telemetry/redaction_chardata_test.exs @@ -0,0 +1,262 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry.RedactionChardataTest do + @moduledoc """ + Slice 125: the redaction filter walks chardata, never raises, and can never be left out. + + The defect: `filter/2` called `Enum.map/2` on the message body, OTP chardata is routinely an + **improper** list whose tail is a binary rather than `[]`, `Enum.map/2` raises + `FunctionClauseError` on one, and OTP responds to a raising primary filter by removing it from the + handler permanently. Everything logged afterwards is unredacted and nothing says so. + + Observed twice on a running server, including at boot from an `Exqlite.Error`, so it needs no + exotic conditions. The suite never saw it because the suite only ever fed the filter proper lists. + """ + use ExUnit.Case, async: true + use ExUnitProperties + + alias Trinity.Telemetry.Redaction + + # The exact event from the live log, tail and all. The `|` before the last element is the defect: + # this is an improper list. + defp live_event do + %{ + level: :error, + meta: %{ + line: 124, + pid: self(), + file: ~c"lib/db_connection/connection.ex", + domain: [:elixir], + application: :db_connection, + mfa: {DBConnection.Connection, :handle_event, 4} + }, + msg: + {:string, + [ + "Exqlite.Connection", + 32, + 40, + "#PID<0.810.0> (\"db_conn_2\")", + ") failed to connect: " | "** (Exqlite.Error) database is locked" + ]} + } + end + + defp text(%{msg: msg}), do: msg |> flatten_msg() |> IO.iodata_to_binary() + + defp flatten_msg({:string, cd}), do: cd + defp flatten_msg({:report, r}), do: inspect(r) + defp flatten_msg({fmt, args}) when is_list(args), do: :io_lib.format(fmt, args) + + # Chardata that includes the shape the suite never generated: a list whose tail is a binary + # rather than `[]`. StreamData's own `chardata/0` builds proper lists only, which is exactly why + # a property over it would have gone on passing while the filter died in production. + defp mixed_chardata do + leaf = + one_of([ + string(:printable), + integer(32..126), + list_of(integer(32..126), max_length: 4) + ]) + + tree(leaf, fn child -> + one_of([ + list_of(child, max_length: 4), + bind({list_of(child, max_length: 3), string(:printable)}, fn {items, tail} -> + constant(improper(items, tail)) + end) + ]) + end) + end + + defp improper([], tail), do: tail + defp improper([h | t], tail), do: [h | improper(t, tail)] + + describe "AC1: the event that killed it" do + test "filter/2 does not raise on the improper chardata from the live log" do + assert %{msg: _, meta: _} = Redaction.filter(live_event(), nil) + end + + test "and the message survives it: the tail is still in the output" do + out = Redaction.filter(live_event(), nil) + assert text(out) =~ "database is locked" + assert text(out) =~ "Exqlite.Connection" + end + end + + describe "AC2: total over OTP's message shapes" do + test "a binary" do + out = Redaction.filter(%{msg: {:string, "plain"}, meta: %{}, level: :info}, nil) + assert text(out) == "plain" + end + + test "a proper iolist" do + ev = %{msg: {:string, ["a", 32, ["b", "c"]]}, meta: %{}, level: :info} + assert text(Redaction.filter(ev, nil)) == "a bc" + end + + test "an improper iolist with a binary tail" do + ev = %{msg: {:string, ["a", 32 | "tail"]}, meta: %{}, level: :info} + assert text(Redaction.filter(ev, nil)) == "a tail" + end + + test "a deeply nested improper iolist" do + ev = %{msg: {:string, ["a", ["b", ["c" | "d"] | "e"] | "f"]}, meta: %{}, level: :info} + assert text(Redaction.filter(ev, nil)) == "abcdef" + end + + test "a charlist" do + ev = %{msg: {:string, ~c"hello"}, meta: %{}, level: :info} + assert text(Redaction.filter(ev, nil)) == "hello" + end + + test "a format string with args" do + ev = %{msg: {~c"~ts and ~ts", ["a", "b"]}, meta: %{}, level: :info} + out = Redaction.filter(ev, nil) + assert {_fmt, args} = out.msg + assert is_list(args) + end + + test "a report as a map" do + ev = %{msg: {:report, %{a: 1}}, meta: %{}, level: :info} + assert %{msg: {:report, %{a: 1}}} = Redaction.filter(ev, nil) + end + + test "a report as a keyword list" do + ev = %{msg: {:report, [a: 1, b: "x"]}, meta: %{}, level: :info} + assert %{msg: {:report, _}} = Redaction.filter(ev, nil) + end + + test "metadata carrying an improper iolist does not raise either" do + ev = %{msg: {:string, "x"}, meta: %{weird: ["a" | "b"]}, level: :info} + assert %{meta: %{weird: _}} = Redaction.filter(ev, nil) + end + end + + describe "AC4: it redacts what it walks, including the tail" do + test "a credential in an improper list's binary tail is masked" do + ev = %{ + msg: {:string, ["auth: " | "Bearer abcdefghijklmnopqrstuvwxyz0123456789"]}, + meta: %{}, + level: :info + } + + out = text(Redaction.filter(ev, nil)) + + assert out =~ "[REDACTED]", + "the credential in the improper tail was not masked. The old code could not reach " <> + "it at all: Enum.map/2 raised before it got there. Output: #{out}" + + refute out =~ "abcdefghijklmnopqrstuvwxyz0123456789" + end + + test "a credential nested inside a proper list is masked" do + ev = %{ + # The separators matter and are not padding: flattened, `["x", ["password=..."]]` is + # "xpassword=...", where `\b` correctly finds no word boundary. The fixture has to be a + # line someone could actually log. + msg: {:string, ["connecting ", ["password=hunter2seventeen", " ok"]]}, + meta: %{}, + level: :info + } + + assert text(Redaction.filter(ev, nil)) =~ "[REDACTED]" + end + end + + describe "AC3/AC5: it cannot raise, on anything" do + property "filter/2 returns for any generated chardata, proper or improper" do + check all(cd <- mixed_chardata()) do + ev = %{msg: {:string, cd}, meta: %{}, level: :info} + assert %{msg: {:string, _}} = Redaction.filter(ev, nil) + end + end + + property "and its output is always valid chardata" do + check all(cd <- mixed_chardata()) do + ev = %{msg: {:string, cd}, meta: %{}, level: :info} + %{msg: {:string, out}} = Redaction.filter(ev, nil) + assert is_binary(IO.iodata_to_binary(out)) + end + end + + property "filter/2 returns for an arbitrary term in msg or meta" do + check all(t <- term()) do + assert %{} = Redaction.filter(%{msg: {:string, t}, meta: %{k: t}, level: :info}, nil) + assert %{} = Redaction.filter(%{msg: {:report, t}, meta: %{}, level: :info}, nil) + end + end + end + + describe "AC5: the filter is never silently absent" do + test "it is installed, read from the logger rather than from configuration" do + names = for {name, _} <- :logger.get_primary_config().filters, do: name + assert :trinity_redaction in names + end + + test "it is still installed after being driven with every shape above" do + for ev <- [ + live_event(), + %{msg: {:string, ["a" | "b"]}, meta: %{}, level: :info}, + %{msg: {:report, [a: 1]}, meta: %{}, level: :info} + ] do + Redaction.filter(ev, nil) + end + + names = for {name, _} <- :logger.get_primary_config().filters, do: name + + assert :trinity_redaction in names, + "the filter was removed. OTP removes a primary filter that raises, permanently, and " <> + "everything logged afterwards is unredacted while the system believes it is not." + end + + test "logging improper chardata through OTP itself leaves the filter installed" do + # The end-to-end one. Everything above calls filter/2 directly, which is not how it dies: + # OTP calls it, OTP catches the raise, and OTP removes it. This goes through the real logger. + ExUnit.CaptureLog.capture_log(fn -> + :logger.log(:error, ["Exqlite.Connection", 32, ") failed: " | "** (Exqlite.Error) locked"]) + + :logger.log(:error, ["auth " | "Bearer abcdefghijklmnopqrstuvwxyz0123"]) + end) + + names = for {name, _} <- :logger.get_primary_config().filters, do: name + + assert :trinity_redaction in names, + "OTP removed the filter after logging improper chardata. This is the exact failure " <> + "seen on the running server: {removed_failing_filter, trinity_redaction}." + end + + test "and what it logged was redacted, not passed through" do + log = + ExUnit.CaptureLog.capture_log(fn -> + :logger.log(:error, ["auth " | "Bearer abcdefghijklmnopqrstuvwxyz0123"]) + end) + + assert log =~ "[REDACTED]" + refute log =~ "abcdefghijklmnopqrstuvwxyz0123" + end + + test "verify_log_redaction!/0 raises when the filter is absent, so boot cannot continue unfiltered" do + :ok = :logger.remove_primary_filter(:trinity_redaction) + + on_exit(fn -> + :logger.add_primary_filter( + :trinity_redaction, + {&Trinity.Telemetry.Redaction.filter/2, nil} + ) + end) + + assert_raise RuntimeError, ~r/redaction/i, fn -> + Trinity.Application.verify_log_redaction!() + end + + :ok = + :logger.add_primary_filter( + :trinity_redaction, + {&Trinity.Telemetry.Redaction.filter/2, nil} + ) + + assert Trinity.Application.verify_log_redaction!() == :ok + end + end +end