diff --git a/lib/logger_json.ex b/lib/logger_json.ex index 066e5c6..e24edc4 100644 --- a/lib/logger_json.ex +++ b/lib/logger_json.ex @@ -56,6 +56,9 @@ defmodule LoggerJSON do If `:all`is given, all metadata is included. If `{:all_except, keys}` is given, all metadata except the specified keys is included. + * `:redactors` - a list of tuples, where first element is the module that implements the `LoggerJSON.Redactor` behaviour, + and the second element is the options to pass to the redactor module. By default, no redactors are used. + ## Metadata You can set some well-known metadata keys to be included in the log entry. The following keys are supported diff --git a/lib/logger_json/formatter.ex b/lib/logger_json/formatter.ex index 5257670..cdf1048 100644 --- a/lib/logger_json/formatter.ex +++ b/lib/logger_json/formatter.ex @@ -1,3 +1,9 @@ defmodule LoggerJSON.Formatter do - @callback format(event :: :logger.log_event(), opts :: term()) :: iodata() + @type opts :: [ + {:metadata, :all | {:all_except, [atom()]} | [atom()]} + | {:redactors, [{module(), term()}]} + | {atom(), term()} + ] + + @callback format(event :: :logger.log_event(), opts :: opts()) :: iodata() end diff --git a/lib/logger_json/formatter/encoder.ex b/lib/logger_json/formatter/encoder.ex index 7b75c7a..d327180 100644 --- a/lib/logger_json/formatter/encoder.ex +++ b/lib/logger_json/formatter/encoder.ex @@ -1,56 +1,68 @@ defmodule LoggerJSON.Formatter.Encoder do - @moduledoc """ - Utilities for converting metadata into data structures that can be safely passed to `Jason.encode!/1`. - """ - @doc """ - Produces metadata that is "safe" for calling Jason.encode!/1 on without errors. - This means that unexpected Logger metadata won't cause logging crashes. + Takes a term and makes sure that it can be encoded by Jason.encode!/1 without errors + and without leaking sensitive information. + + ## Encoding rules - Current formatting is... - * Maps: as is - * Printable binaries: as is - * Numbers: as is - * Structs that don't implement Jason.Encoder: converted to maps - * Tuples: converted to lists - * Keyword lists: converted to Maps - * everything else: inspected + Type | Encoding | Redaction + --------------------|-----------------------------------------------------|--------------- + `boolean()` | unchanged | unchanged + `map()` | unchanged | values are redacted + `list()` | unchanged | unchanged + `tuple()` | converted to list | unchanged + `binary()` | unchanged if printable, otherwise using `inspect/2` | unchanged + `number()` | unchanged | unchanged + `atom()` | unchanged | unchanged + `struct()` | converted to map | values are redacted + `keyword()` | converted to map | values are redacted + `%Jason.Fragment{}` | unchanged | unchanged + everything else | using `inspect/2` | unchanged """ - @spec encode(any()) :: any() - def encode(nil), do: nil - def encode(true), do: true - def encode(false), do: false - def encode(atom) when is_atom(atom), do: atom - def encode(tuple) when is_tuple(tuple), do: tuple |> Tuple.to_list() |> encode() - def encode(number) when is_number(number), do: number - def encode(binary) when is_binary(binary), do: encode_binary(binary) - def encode(%Jason.Fragment{} = fragment), do: fragment - def encode(%_struct{} = struct) do - if protocol_implemented?(struct) do - struct - else - struct - |> Map.from_struct() - |> encode() - end + @type redactor :: {redactor :: module(), redactor_opts :: term()} + + @spec encode(term(), redactors :: [redactor()]) :: term() + def encode(nil, _redactors), do: nil + def encode(true, _redactors), do: true + def encode(false, _redactors), do: false + def encode(atom, _redactors) when is_atom(atom), do: atom + def encode(tuple, redactors) when is_tuple(tuple), do: tuple |> Tuple.to_list() |> encode(redactors) + def encode(number, _redactors) when is_number(number), do: number + def encode("[REDACTED]", _redactors), do: "[REDACTED]" + def encode(binary, _redactors) when is_binary(binary), do: encode_binary(binary) + def encode(%Jason.Fragment{} = fragment, _redactors), do: fragment + + def encode(%_struct{} = struct, redactors) do + struct + |> Map.from_struct() + |> encode(redactors) end - def encode(%{} = map) do - for {key, value} <- map, into: %{}, do: {encode_map_key(key), encode(value)} + def encode(%{} = map, redactors) do + for {key, value} <- map, into: %{} do + key = encode_map_key(key) + {key, encode(redact(key, value, redactors), redactors)} + end end - def encode([{key, _} | _] = keyword) when is_atom(key) do - Enum.into(keyword, %{}, fn - {key, value} -> {encode_map_key(key), encode(value)} + def encode([{key, _} | _] = keyword, redactors) when is_atom(key) do + Enum.into(keyword, %{}, fn {key, value} -> + key = encode_map_key(key) + {key, encode(redact(key, value, redactors), redactors)} end) rescue - _ -> for(el <- keyword, do: encode(el)) + _ -> for(el <- keyword, do: encode(el, redactors)) + end + + def encode(list, redactors) when is_list(list), do: for(el <- list, do: encode(el, redactors)) + + def encode({key, value}, redactors) when is_binary(key) or is_atom(key) do + key = encode_map_key(key) + %{key => encode(redact(key, value, redactors), redactors)} end - def encode(list) when is_list(list), do: for(el <- list, do: encode(el)) - def encode({key, data}) when is_binary(key) or is_atom(key), do: %{encode_map_key(key) => encode(data)} - def encode(data), do: inspect(data, pretty: true, width: 80) + def encode(data, _redactors), do: inspect(data, pretty: true, width: 80) defp encode_map_key(key) when is_binary(key), do: encode_binary(key) defp encode_map_key(key) when is_atom(key) or is_number(key), do: key @@ -64,8 +76,9 @@ defmodule LoggerJSON.Formatter.Encoder do end end - def protocol_implemented?(data) do - impl = Jason.Encoder.impl_for(data) - impl && impl != Jason.Encoder.Any + defp redact(key, value, redactors) do + Enum.reduce(redactors, value, fn {redactor, opts}, acc -> + redactor.redact(key, acc, opts) + end) end end diff --git a/lib/logger_json/formatters/basic.ex b/lib/logger_json/formatters/basic.ex index f2127f6..97da452 100644 --- a/lib/logger_json/formatters/basic.ex +++ b/lib/logger_json/formatters/basic.ex @@ -28,6 +28,7 @@ defmodule LoggerJSON.Formatters.Basic do def format(%{level: level, meta: meta, msg: msg}, opts) do metadata_keys_or_selector = Keyword.get(opts, :metadata, []) metadata_selector = update_metadata_selector(metadata_keys_or_selector, @processed_metadata_keys) + redactors = Keyword.get(opts, :redactors, []) message = format_message(msg, meta, %{ @@ -40,8 +41,8 @@ defmodule LoggerJSON.Formatters.Basic do %{ time: utc_time(meta), severity: Atom.to_string(level), - message: encode(message), - metadata: encode(take_metadata(meta, metadata_selector)) + message: encode(message, redactors), + metadata: encode(take_metadata(meta, metadata_selector), redactors) } |> maybe_put(:request, format_http_request(meta)) |> maybe_put(:span, format_span(meta)) diff --git a/lib/logger_json/formatters/datadog.ex b/lib/logger_json/formatters/datadog.ex index 06edc84..3f409ab 100644 --- a/lib/logger_json/formatters/datadog.ex +++ b/lib/logger_json/formatters/datadog.ex @@ -50,6 +50,7 @@ defmodule LoggerJSON.Formatters.Datadog do @spec format(any(), any()) :: none() def format(%{level: level, meta: meta, msg: msg}, opts) do + redactors = Keyword.get(opts, :redactors, []) hostname = Keyword.get(opts, :hostname, :system) metadata_keys_or_selector = Keyword.get(opts, :metadata, []) @@ -73,8 +74,8 @@ defmodule LoggerJSON.Formatters.Datadog do %{syslog: syslog(level, meta, hostname)} |> maybe_put(:logger, format_logger(meta)) |> maybe_merge(format_http_request(meta)) - |> maybe_merge(encode(metadata)) - |> maybe_merge(encode(message)) + |> maybe_merge(encode(metadata, redactors)) + |> maybe_merge(encode(message, redactors)) |> Jason.encode_to_iodata!() [line, "\n"] @@ -137,7 +138,7 @@ defmodule LoggerJSON.Formatters.Datadog do defp format_logger(%{file: file, line: line, mfa: {m, f, a}} = meta) do %{ - thread_name: encode(meta[:pid]), + thread_name: inspect(meta[:pid]), method_name: format_function(m, f, a), file_name: IO.chardata_to_string(file), line: line diff --git a/lib/logger_json/formatters/google_cloud.ex b/lib/logger_json/formatters/google_cloud.ex index 3201003..2cbce5d 100644 --- a/lib/logger_json/formatters/google_cloud.ex +++ b/lib/logger_json/formatters/google_cloud.ex @@ -100,6 +100,7 @@ defmodule LoggerJSON.Formatters.GoogleCloud do @spec format(any(), any()) :: none() def format(%{level: level, meta: meta, msg: msg}, opts) do + redactors = Keyword.get(opts, :redactors, []) service_context = Keyword.get_lazy(opts, :service_context, fn -> %{service: to_string(node())} end) project_id = Keyword.get(opts, :project_id) metadata_keys_or_selector = Keyword.get(opts, :metadata, []) @@ -125,8 +126,8 @@ defmodule LoggerJSON.Formatters.GoogleCloud do |> maybe_put(:"logging.googleapis.com/spanId", format_span(meta, project_id)) |> maybe_put(:"logging.googleapis.com/trace", format_trace(meta, project_id)) |> maybe_put(:httpRequest, format_http_request(meta)) - |> maybe_merge(encode(message)) - |> maybe_merge(encode(metadata)) + |> maybe_merge(encode(message, redactors)) + |> maybe_merge(encode(metadata, redactors)) |> Jason.encode_to_iodata!() [line, "\n"] diff --git a/lib/logger_json/redactor.ex b/lib/logger_json/redactor.ex new file mode 100644 index 0000000..dbc6fc3 --- /dev/null +++ b/lib/logger_json/redactor.ex @@ -0,0 +1,14 @@ +defmodule LoggerJSON.Redactor do + @moduledoc """ + This module provides a behaviour which allows to redact sensitive information from logs. + + Note: redactor will not be applied on `Jason.Fragment` structs. + """ + + @doc """ + Takes a key and a value and returns a redacted value. + + This callback will be applied on key-value pairs, like elements of structs, maps or keyword lists. + """ + @callback redact(key :: term(), value :: term(), opts :: term()) :: term() +end diff --git a/lib/logger_json/redactors/redact_keys.ex b/lib/logger_json/redactors/redact_keys.ex new file mode 100644 index 0000000..6a8c2f4 --- /dev/null +++ b/lib/logger_json/redactors/redact_keys.ex @@ -0,0 +1,26 @@ +defmodule LoggerJSON.Redactors.RedactKeys do + @moduledoc """ + A simple redactor which replace the value of the keys with `"[REDACTED]"`. + + It takes list of keys to redact as an argument, eg.: + ```elixir + config :logger, :default_handler, + formatter: {LoggerJSON.Formatters.Basic, redactors: [ + {LoggerJSON.Redactors.RedactKeys, ["password"]} + ]} + ``` + + Keep in mind that LoggerJSON will convert key type to string before comparing it + with the list of keys to redact. + """ + + @behaviour LoggerJSON.Redactor + + def redact(key, value, keys) do + if key in keys do + "[REDACTED]" + else + value + end + end +end diff --git a/test/formatter/encoder_test.exs b/test/formatter/encoder_test.exs index 04fa91e..b8e1e31 100644 --- a/test/formatter/encoder_test.exs +++ b/test/formatter/encoder_test.exs @@ -5,70 +5,89 @@ defmodule LoggerJSON.Formatter.EncoderTest do defmodule IDStruct, do: defstruct(id: nil) - describe "encode/1" do + defmodule PasswordStruct, do: defstruct(password: "foo") + + @redactors [{LoggerJSON.Redactors.RedactKeys, [:password]}] + + describe "encode/2" do test "allows nils" do - assert encode(nil) == nil + assert encode(nil, @redactors) == nil end test "allows booleans" do - assert encode(true) == true - assert encode(false) == false + assert encode(true, @redactors) == true + assert encode(false, @redactors) == false end test "allows printable strings" do - assert encode("hello") == "hello" + assert encode("hello", @redactors) == "hello" end test "inspects non-printable binaries" do - assert encode("hello" <> <<0>>) == "<<104, 101, 108, 108, 111, 0>>" + assert encode("hello" <> <<0>>, @redactors) == "<<104, 101, 108, 108, 111, 0>>" end test "allows atoms" do - assert encode(:hello) == :hello + assert encode(:hello, @redactors) == :hello end test "allows numbers" do - assert encode(123) == 123 + assert encode(123, @redactors) == 123 end test "strips Structs" do - assert %{id: "hello"} == encode(%IDStruct{id: "hello"}) + assert encode(%IDStruct{id: "hello"}, @redactors) == %{id: "hello"} + end + + test "redacts values in structs" do + assert encode(%PasswordStruct{password: "hello"}, @redactors) == %{password: "[REDACTED]"} end - test "does not strip structs for which Jason.Encoder is derived" do - assert %NameStruct{name: "B"} == encode(%NameStruct{name: "B"}) + # Jason.Encoder protocol can be used in many other scenarios, + # like DB/API response serliazation, so it's better not to + # assume that it's what the users expects to see in logs. + test "strips structs when Jason.Encoder is derived for them" do + assert encode(%NameStruct{name: "B"}, @redactors) == %{name: "B"} end test "converts tuples to lists" do - assert encode({1, 2, 3}) == [1, 2, 3] + assert encode({1, 2, 3}, @redactors) == [1, 2, 3] end test "converts nested tuples to nested lists" do - assert encode({{2000, 1, 1}, {13, 30, 15}}) == [[2000, 1, 1], [13, 30, 15]] + assert encode({{2000, 1, 1}, {13, 30, 15}}, @redactors) == [[2000, 1, 1], [13, 30, 15]] end - test "converts Keyword lists to maps" do - assert encode(a: 1, b: 2) == %{a: 1, b: 2} + test "converts keyword lists to maps" do + assert encode([a: 1, b: 2], @redactors) == %{a: 1, b: 2} + end + + test "redacts values in keyword lists" do + assert encode([password: "foo"], @redactors) == %{password: "[REDACTED]"} end test "converts non-string map keys" do - assert encode(%{1 => 2}) == %{1 => 2} - assert encode(%{:a => 1}) == %{:a => 1} - assert encode(%{{"a", "b"} => 1}) == %{"{\"a\", \"b\"}" => 1} - assert encode(%{%{a: 1, b: 2} => 3}) == %{"%{a: 1, b: 2}" => 3} - assert encode(%{[{:a, :b}] => 3}) == %{"[a: :b]" => 3} + assert encode(%{1 => 2}, []) == %{1 => 2} + assert encode(%{:a => 1}, []) == %{:a => 1} + assert encode(%{{"a", "b"} => 1}, []) == %{"{\"a\", \"b\"}" => 1} + assert encode(%{%{a: 1, b: 2} => 3}, []) == %{"%{a: 1, b: 2}" => 3} + assert encode(%{[{:a, :b}] => 3}, []) == %{"[a: :b]" => 3} + end + + test "redacts values in maps" do + assert encode(%{password: "foo"}, @redactors) == %{password: "[REDACTED]"} end test "inspects functions" do - assert encode(&encode/1) == "&LoggerJSON.Formatter.Encoder.encode/1" + assert encode(&encode/2, []) == "&LoggerJSON.Formatter.Encoder.encode/2" end test "inspects pids" do - assert encode(self()) == inspect(self()) + assert encode(self(), []) == inspect(self()) end test "doesn't choke on things that look like keyword lists but aren't" do - assert encode([{:a, 1}, {:b, 2, :c}]) == [[:a, 1], [:b, 2, :c]] + assert encode([{:a, 1}, {:b, 2, :c}], []) == [[:a, 1], [:b, 2, :c]] end test "formats nested structures" do @@ -80,7 +99,7 @@ defmodule LoggerJSON.Formatter.EncoderTest do self: self() } - assert encode(input) == %{ + assert encode(input, []) == %{ foo: %{ foo_a: %{"x" => 1, "y" => %{id: 1}}, foo_b: %{foo_b_1: 1, foo_b_2: ["2a", "2b"]} @@ -89,10 +108,29 @@ defmodule LoggerJSON.Formatter.EncoderTest do } end + test "redacts nested structures" do + assert encode(%{password: "foo", other_key: %{password: ["foo"]}}, @redactors) == %{ + password: "[REDACTED]", + other_key: %{password: "[REDACTED]"} + } + + assert encode([password: "foo", other_key: [password: "bar"]], @redactors) == %{ + password: "[REDACTED]", + other_key: %{password: "[REDACTED]"} + } + + assert encode([password: "foo", other_key: %{password: "bar"}], @redactors) == %{ + password: "[REDACTED]", + other_key: %{password: "[REDACTED]"} + } + + assert encode([foo: ["foo", %{password: "bar"}]], @redactors) == %{foo: ["foo", %{password: "[REDACTED]"}]} + end + property "converts any term so that it can be encoded with Jason" do check all value <- term() do value - |> encode() + |> encode([]) |> Jason.encode!() end end