From d2ad7f14efe1d53dd7c3775666e2340d1e756dbb Mon Sep 17 00:00:00 2001 From: Ayla Croft Date: Sat, 26 Sep 2026 11:30:14 -0400 Subject: [PATCH 1/2] test(s125): red first, the redaction filter raises on chardata and is then removed Eleven failures, committed before any fix. The defect: redact_msg/1 calls 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. The first test feeds it the exact event from the live log, improper tail and all: msg: {:string, ["Exqlite.Connection", 32, 40, "#PID<0.810.0> (\"db_conn_2\")", ") failed to connect: " | "** (Exqlite.Error) database is locked"]} ** (FunctionClauseError) no function clause matching in Enum."-map/2-lists^map/1-1-"/2 A second defect the property found, which I had guessed at earlier and wrongly dismissed: an arbitrary binary raises too. redact/1 runs Regex.replace on it and a binary that is not valid UTF-8 is exactly what key material arrives as. property "filter/2 returns for an arbitrary term in msg or meta" ** (ArgumentError) argument error, after 92 successful runs The suite never saw either because it only ever fed the filter proper lists of valid UTF-8. StreamData's own chardata/0 builds proper lists, so a property over it would have gone on passing while the filter died in production; the generator here builds improper tails deliberately. AC5 is the half the original slice did not cover and is the more important one: a filter that cannot redact must not be silently dropped. Boot fails, or the handler is replaced. Never left unfiltered. Trinity.Application.verify_log_redaction!/0 does not exist yet, so that test fails undefined. Signed-off-by: Ayla Croft --- .../telemetry/redaction_chardata_test.exs | 234 ++++++++++++++++++ 1 file changed, 234 insertions(+) create mode 100644 test/trinity/telemetry/redaction_chardata_test.exs diff --git a/test/trinity/telemetry/redaction_chardata_test.exs b/test/trinity/telemetry/redaction_chardata_test.exs new file mode 100644 index 0000000..83b82df --- /dev/null +++ b/test/trinity/telemetry/redaction_chardata_test.exs @@ -0,0 +1,234 @@ +# 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 = %{ + msg: {:string, ["x", ["password=hunter2seventeen", "y"]]}, + 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 "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 From 6e563a9172185ac080b22c515e8e4c829dd91221 Mon Sep 17 00:00:00 2001 From: Ayla Croft Date: Sat, 26 Sep 2026 11:40:06 -0400 Subject: [PATCH 2/2] fix(s125): complete slice 125 (the redaction filter survives improper chardata) The credential-masking Logger filter could be killed by ordinary log events, and OTP's response to a raising primary filter is to remove it permanently and carry on. Everything logged afterwards was unredacted while the system believed it was not. Two input classes did it, not one. Improper chardata, which the slice was opened for. redact_msg({format, args}) when is_list(args) caught {:string, iolist}, because an iolist is a list, and Enum.map/2 raises FunctionClauseError on an improper list. OTP chardata is routinely improper: a db_connection disconnect produces one, and so does an Exqlite.Error at boot. Binaries that are not valid UTF-8, which the property found after 92 runs. redact/1 runs Regex.replace/3 on any binary and that raises. I had this hypothesis at the start of the session and threw it away on a bad test: I checked redact/1 against one 8-byte invalid binary, saw it return, and concluded UTF-8 was not the problem. Three hand-picked inputs are not a population. This is the more serious of the two, because raw bytes are the shape key material most often takes, so the filter raised on exactly the input class most likely to be a secret, and failed in the direction that disabled redaction entirely. The fix: - {:string, chardata} is flattened rather than walked. The clause sits before {format, args}, which would otherwise catch it. - redact_list/1 replaces Enum.map/2 wherever a list may be improper, keeping the shape and redacting the tail rather than walking off the end of it. - An invalid binary is replaced rather than matched, keeping its byte size so the line still says something. - filter/2 wraps its own work and degrades to an event whose content is withheld, keeping only metadata that cannot carry a credential. - Trinity.Application.verify_log_redaction!/0 reads the primary filters from the logger and refuses to boot without this one. install_log_redaction/0 previously swallowed every error including a failure to install, so an application that could not redact started anyway and said nothing. The assertion that matters is end to end, because calling filter/2 directly is not how it dies: OTP calls it, OTP catches the raise, OTP removes it. Against the pre-fix module that test reports "OTP removed the filter after logging improper chardata", and a companion test asserts the line OTP did log was masked, so "still installed" cannot be satisfied by a filter that no longer redacts. Confirmed on a running server, which is how both of this session's defects were found: zero removed_failing_filter across a full approval turn, against a pre-fix run where the filter was removed at boot. Note for the next property written here: StreamData's own chardata/0 generates proper lists only, so a property written the obvious way would have gone on passing while the filter died in production. The generator in this slice builds improper tails deliberately. Signed-off-by: Ayla Croft --- CHANGELOG.md | 28 ++++ lib/trinity/application.ex | 52 ++++++-- lib/trinity/telemetry/redaction.ex | 121 ++++++++++++++++-- .../telemetry/redaction_chardata_test.exs | 32 ++++- 4 files changed, 210 insertions(+), 23 deletions(-) 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 index 83b82df..91c0636 100644 --- a/test/trinity/telemetry/redaction_chardata_test.exs +++ b/test/trinity/telemetry/redaction_chardata_test.exs @@ -152,7 +152,10 @@ defmodule Trinity.Telemetry.RedactionChardataTest do test "a credential nested inside a proper list is masked" do ev = %{ - msg: {:string, ["x", ["password=hunter2seventeen", "y"]]}, + # 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 } @@ -183,7 +186,6 @@ defmodule Trinity.Telemetry.RedactionChardataTest do assert %{} = Redaction.filter(%{msg: {:report, t}, meta: %{}, level: :info}, nil) end end - end describe "AC5: the filter is never silently absent" do @@ -208,6 +210,32 @@ defmodule Trinity.Telemetry.RedactionChardataTest do "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)