From 5f86faf489100e4a2a7f16bb1f02eb5806e256d0 Mon Sep 17 00:00:00 2001 From: martosaur Date: Sun, 1 Jun 2025 18:02:24 -0700 Subject: [PATCH 1/2] Add Act.metadata_serialization/1 set of cases --- lib/logger_handler_kit/act.ex | 83 ++++++++++++++- test/default_logger_test.exs | 194 +++++++++++++++++++++++++++++++++- 2 files changed, 275 insertions(+), 2 deletions(-) diff --git a/lib/logger_handler_kit/act.ex b/lib/logger_handler_kit/act.ex index 912a035..5403f52 100644 --- a/lib/logger_handler_kit/act.ex +++ b/lib/logger_handler_kit/act.ex @@ -11,7 +11,7 @@ defmodule LoggerHandlerKit.Act do Each function represents a case of interest, potentially with different flavors to highlight various cases. - The functions are divided into three groups: Basic, OTP, and SASL. + The functions are divided into four groups: Basic, OTP, SASL and Metadata. ## Basic @@ -45,6 +45,10 @@ defmodule LoggerHandlerKit.Act do In real life, SASL logs look like reports from supervisors about things that you would expect: child process restarts and such. They are skipped by Elixir by default, but a thorough handler might have an interest in them. + + ## Metadata + + These cases focus on challenges that arise from metadata. """ import ExUnit.Assertions @@ -1662,4 +1666,81 @@ defmodule LoggerHandlerKit.Act do assert_receive({:EXIT, ^pid, _}) :ok end + + @doc """ + Sets the `extra` key in Logger metadata to a sample value of some interesting type. + + Metadata can contain arbitrary Elixir terms, and the primary challenge that + loggers face when exporting it is serialization. There is no universally good + way to represent an Elixir term as text, so handlers or formatters must make + hard choices. Some examples: + + * Binary strings can contain non-printable characters. + * Structs by default don't implement the `String.Chars` protocol. When they do, the implementation might be designed for a different purpose than logging. + * Tuples can be inspected as text but lose their structure (in JSON), or serialized as lists which preserves structure but misleads about the original type. + * Charlists are indistinguishable from lists in JSON serialization. + + The default text formatter [skips](`Logger.Formatter#module-metadata`) many of these complex cases. + """ + @doc group: "Metadata" + @dialyzer :no_improper_lists + @metadata_types %{ + boolean: true, + string: "hello world", + binary: <<1, 2, 3>>, + atom: :foo, + integer: 42, + datetime: ~U[2025-06-01T12:34:56.000Z], + struct: %LoggerHandlerKit.FakeStruct{hello: "world"}, + tuple: {:ok, "hello"}, + keyword: [hello: "world"], + improper_keyword: [{:a, 1} | {:b, 2}], + fake_keyword: [{:a, 1}, {:b, 2, :c}], + list: [1, 2, 3], + improper_list: [1, 2 | 3], + map: %{:hello => "world", "foo" => "bar"}, + function: &__MODULE__.metadata_serialization/1 + } + @spec metadata_serialization( + :boolean + | :string + | :binary + | :atom + | :integer + | :datetime + | :struct + | :tuple + | :keyword + | :improper_keyword + | :fake_keyword + | :list + | :improper_list + | :map + | :function + | :anonymous_function + | :pid + | :ref + | :port + ) :: :ok + def metadata_serialization(:pid), do: Logger.metadata(extra: self()) + + def metadata_serialization(:anonymous_function), + do: Logger.metadata(extra: fn -> "hello world" end) + + def metadata_serialization(:ref), do: Logger.metadata(extra: make_ref()) + def metadata_serialization(:port), do: Logger.metadata(extra: Port.list() |> hd()) + + def metadata_serialization(:all) do + all = + Map.merge(@metadata_types, %{ + pid: self(), + anonymous_function: fn -> "hello world" end, + ref: make_ref(), + port: Port.list() |> hd() + }) + + Logger.metadata(extra: all) + end + + def metadata_serialization(case), do: Logger.metadata(extra: Map.fetch!(@metadata_types, case)) end diff --git a/test/default_logger_test.exs b/test/default_logger_test.exs index ea017c9..d6024b2 100644 --- a/test/default_logger_test.exs +++ b/test/default_logger_test.exs @@ -19,7 +19,7 @@ defmodule LoggerHandlerKit.DefaultLoggerTest do %{ type: {:device, io_device} }, - Map.merge(%{formatter: Logger.default_formatter()}, big_config_override) + Map.merge(%{formatter: Logger.default_formatter(metadata: [:extra])}, big_config_override) ) on_exit(on_exit) @@ -367,4 +367,196 @@ defmodule LoggerHandlerKit.DefaultLoggerTest do assert msg =~ "** (exit) :reached_max_restart_intensity" end end + + describe "Metadata" do + test "nil", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:boolean) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ "extra=true" + end + + test "string", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:string) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ "extra=hello" + end + + test "binary", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:binary) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ "extra=\x01\x02\x03" + end + + test "atom", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:atom) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ "extra=foo" + end + + test "integer", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:integer) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ "extra=42" + end + + test "datetime", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:datetime) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ "extra=2025-06-01 12:34:56.000Z" + end + + test "struct", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:struct) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips structs that do not implement String.Chars protocol + refute msg =~ "extra" + end + + test "tuple", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:tuple) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips tuples + refute msg =~ "extra" + end + + test "keyword", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:keyword) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips keyword lists + refute msg =~ "extra" + end + + test "improper keyword", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:improper_keyword) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips keyword lists + refute msg =~ "extra" + end + + test "fake keyword", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:fake_keyword) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips keyword lists + refute msg =~ "extra" + end + + test "list", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:list) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips all lists in fact + refute msg =~ "extra" + end + + test "improper list", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:improper_list) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips all lists in fact + refute msg =~ "extra" + end + + test "map", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:map) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips maps + refute msg =~ "extra" + end + + test "function", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:function) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips functions + refute msg =~ "extra" + end + + test "anonymous function", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:anonymous_function) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + # default formatter skips functions + refute msg =~ "extra" + end + + test "pid", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:pid) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ ~r"extra=<\d+\.\d+\.\d+>" + end + + test "ref", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:ref) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ ~r"extra=<\d+.\d+\.\d+\.\d+>" + end + + test "port", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:port) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + assert msg =~ ~r"extra=<\d+.\d+>" + end + + test "all", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.metadata_serialization(:all) + LoggerHandlerKit.Act.string_message() + LoggerHandlerKit.Assert.assert_logged(ref) + + assert_receive {^io_ref, msg} + refute msg =~ "extra" + end + end end From 737350ff3b8518da7d59bcc455e009fac256e819 Mon Sep 17 00:00:00 2001 From: martosaur Date: Mon, 2 Jun 2025 15:51:19 -0700 Subject: [PATCH 2/2] Add Metadata guide --- guides/metadata.md | 97 ++++++++++++++++++++++++++++++++++++++++++++++ mix.exs | 3 +- 2 files changed, 99 insertions(+), 1 deletion(-) create mode 100644 guides/metadata.md diff --git a/guides/metadata.md b/guides/metadata.md new file mode 100644 index 0000000..192c5f6 --- /dev/null +++ b/guides/metadata.md @@ -0,0 +1,97 @@ +# Metadata + +[Logger metadata](`Logger#module-metadata`) is structured data attached to log +messages. Metadata can be passed to `Logger` with the message: + +```elixir +Logger.info("Hello", user_id: 123) +``` + +or set beforehand with `Logger.metadata/1`: + +```elixir +Logger.metadata(user_id: 123) +``` + +> #### Not Just Keyword List {: .tip} +> +> Big Logger don't want you to know, but maps totally work as metadata too: +> +> ```elixir +> iex> Logger.metadata(%{hello: "world"}) +> :ok +> iex> Logger.metadata() +> [hello: "world"] +> ``` + +Metadata is tricky to use correctly because it behaves very differently in +development versus production environments. In development, the default console +logger outputs minimal metadata, and even when configured to show more, console +space is limited, so developers are pushed to embed important data directly in +log messages. Production logging solutions, however, very much prefer structured +metadata for filtering and searching, paired with static log messages that +enable effective fingerprinting and grouping of similar events. + +This guide focuses on the latter approach: using static log messages paired with +rich metadata: + +```elixir +Logger.error("Unexpected API response", status_code: 422, user_id: 123) +``` + +When working with metadata, logging libraries typically grapple with two key +challenges: serialization and scrubbing. + +## Serialization + +Metadata can hold Elixir terms of any type, but to send them somewhere and +display them to users, they must be serialized. Unfortunately, there's no +universally good way to handle this! Elixir's default +`Logger.Formatter#module-metadata` supports only a handful of types. The +de-facto expectation, however, is that specialized logging libraries can handle +any term and display it reasonably well. Consequently, every logging library +implements a step where it makes the hard decisions about what to do with +tuples, structs, and other complex data types. This process is sometimes called +encoding or sanitization. + +One solution that works well and can be easily integrated into your project is +the +[`LoggerJSON.Formatters.RedactorEncoder.encode/2`](https://hexdocs.pm/logger_json/LoggerJSON.Formatter.RedactorEncoder.html#encode/2) +function. It accepts any Elixir term and makes it JSON-serializable: + +```elixir +iex> LoggerJSON.Formatter.RedactorEncoder.encode(%{tuple: {:ok, "foo"}, pid: self()}, []) +%{pid: "#PID<0.219.0>", tuple: [:ok, "foo"]} +``` + +## Scrubbing + +Scrubbing is the process of removing sensitive fields from metadata. Data like +passwords, API keys, or credit card numbers should never be sent to your logging +service unnecessarily. While many logging services implement scrubbing on the +receiving end, some libraries handle this on the client side as well. + +The challenge with scrubbing is that it must be configurable. Applications store +diverse types of secrets, and no set of default rules can catch them all. +Fortunately, the same solution used for serialization works here too. +[`LoggerJSON.Formatters.RedactorEncoder.encode/2`](https://hexdocs.pm/logger_json/LoggerJSON.Formatter.RedactorEncoder.html#encode/2) +accepts a list of "redactors" that will be called to scrub potentially sensitive +data. It includes a powerful +[`LoggerJSON.Redactors.RedactKeys`](https://hexdocs.pm/logger_json/LoggerJSON.Redactors.RedactKeys.html) +redactor that redacts all values stored under specified keys: + +```elixir +iex> LoggerJSON.Formatter.RedactorEncoder.encode( + %{user: "Marion", password: "SCP-3125"}, + [{LoggerJSON.Redactors.RedactKeys, ["password"]}] +) +%{user: "Marion", password: "[REDACTED]"} +``` + +## Conclusion + +While [`LoggerJSON`](https://hex.pm/packages/logger_json)'s primary goal isn't to solve our metadata struggles, it +comes with a set of tools that can be very handy. Even if you don't want to +depend on it directly, it can provide you with a good starting point for your +own solution. And `LoggerHandlerKit.Act.metadata_serialization/1` can help you +with test cases! \ No newline at end of file diff --git a/mix.exs b/mix.exs index ceb594b..9454527 100644 --- a/mix.exs +++ b/mix.exs @@ -46,7 +46,8 @@ defmodule LoggerHandlerKit.MixProject do extras: [ "README.md", "guides/translation.md", - "guides/unhandled.md" + "guides/unhandled.md", + "guides/metadata.md" ], groups_for_modules: [ Helpers: [