support more metadata types

bench/format.exs

@@ -5,6 +5,18 @@ Benchee.run(
       {_level = :debug, _msg = "this is a message", _ts = {{2023, 11, 22}, {16, 19, 5, 729}}, _meta = [user_id: 11]},
     "info" =>
       {_level = :info, _msg = "this is a message", _ts = {{2023, 11, 22}, {16, 19, 5, 737}},
-       _meta = [pid: self(), ref: :erlang.make_ref()]}
+       _meta = [pid: self(), ref: :erlang.make_ref()]},
+    "metadata: :all" =>
+      {_level = :debug, _msg = "this is a message", _ts = {{2023, 11, 22}, {16, 19, 5, 737}},
+       _meta = [
+         line: 95,
+         pid: self(),
+         time: 1_703_215_516_705_225,
+         file: ~c"/Users/x/Developer/ex_json_logger/test/ex_json_logger_test.exs",
+         gl: self(),
+         domain: [:elixir],
+         mfa: {ExJsonLoggerTest, :"test format/4 structured", 1},
+         report_cb: &:logger.format_otp_report/1
+       ]}
   }
 )

lib/ex_json_logger.ex

@@ -22,51 +22,108 @@ defmodule ExJsonLogger do
   """
   import Logger.Formatter, only: [format_date: 1, format_time: 1]
 
-  @pid_str "#PID"
+  defmodule LogEvent do
+    @moduledoc false
+    defstruct fields: []
+    @type t :: %__MODULE__{fields: [{atom, term}]}
+
+    defimpl Jason.Encoder do
+      @spec encode(ExJsonLogger.LogEvent.t(), Jason.Encode.opts()) :: iodata
+      def encode(%{fields: fields}, opts) do
+        Jason.Encode.keyword(fields, opts)
+      end
+    end
+  end
 
   @doc """
   Function referenced in the `:format` config.
   """
   @spec format(Logger.level(), Logger.message(), Logger.Formatter.time(), Keyword.t()) :: iodata()
   def format(level, msg, timestamp, metadata) do
-    logger_info = %{
-      level: level,
-      time: format_timestamp(timestamp),
-      msg: IO.iodata_to_binary(msg)
-    }
-
-    metadata
-    |> Map.new(fn {k, v} -> {k, format_metadata(v)} end)
-    |> Map.merge(logger_info)
-    |> encode()
+    encode([
+      {"level", level},
+      {"time", format_timestamp(timestamp)},
+      {"msg", IO.iodata_to_binary(msg)}
+      | metadata(metadata)
+    ])
   rescue
-    _ ->
-      encode(%{
-        level: :error,
-        time: format_timestamp(timestamp),
-        msg: "ExJsonLogger could not format: #{inspect({level, msg, metadata})}"
-      })
+    _e ->
+      encode([
+        {"level", "error"},
+        {"time", format_timestamp(timestamp)},
+        {"msg", "ExJsonLogger could not format: #{inspect({level, msg, metadata})}"}
+      ])
+  end
+
+  @compile inline: [encode: 1]
+  defp encode(fields) do
+    [Jason.encode_to_iodata!(%LogEvent{fields: fields}), ?\n]
+  end
+
+  defp metadata([kv | rest]) do
+    if kv = format_metadata(kv) do
+      [kv | metadata(rest)]
+    else
+      metadata(rest)
+    end
   end
 
-  defp encode(log_event) do
-    [Jason.encode_to_iodata!(log_event), ?\n]
+  defp metadata([] = empty), do: empty
+
+  defmacrop unsafe_fragment(data) do
+    quote do
+      Jason.Fragment.new([?", unquote_splicing(data), ?"])
+    end
   end
 
   defp format_timestamp({date, time}) do
     unsafe_fragment([format_date(date), ?\s, format_time(time)])
   end
 
-  defp format_metadata(pid) when is_pid(pid) do
-    unsafe_fragment([@pid_str | :erlang.pid_to_list(pid)])
+  defp format_metadata({drop, _}) when drop in [:msg, :time, :level, :report_cb, :gl], do: nil
+
+  defp format_metadata({_, nil} = kv), do: kv
+  defp format_metadata({_, string} = kv) when is_binary(string), do: kv
+  defp format_metadata({_, number} = kv) when is_number(number), do: kv
+
+  defp format_metadata({key, pid}) when is_pid(pid) do
+    {key, unsafe_fragment(["#PID", :erlang.pid_to_list(pid)])}
   end
 
-  defp format_metadata(ref) when is_reference(ref) do
-    unsafe_fragment(:erlang.ref_to_list(ref))
+  defp format_metadata({key, ref}) when is_reference(ref) do
+    {key, unsafe_fragment([:erlang.ref_to_list(ref)])}
   end
 
-  defp format_metadata(other), do: other
+  defp format_metadata({key, port}) when is_port(port) do
+    {key, unsafe_fragment([:erlang.port_to_list(port)])}
+  end
+
+  defp format_metadata({key, atom}) when is_atom(atom) do
+    value =
+      case Atom.to_string(atom) do
+        "Elixir." <> rest -> rest
+        other -> other
+      end
+
+    {key, value}
+  end
+
+  defp format_metadata({mfa_key, {mod, fun, arity}})
+       when mfa_key in [:mfa, :initial_call] and is_atom(mod) and is_atom(fun) and is_integer(arity) do
+    {mfa_key, Exception.format_mfa(mod, fun, arity)}
+  end
+
+  defp format_metadata({list_key, list}) when list_key in [:file, :function] and is_list(list) do
+    {list_key, List.to_string(list)}
+  end
 
-  defp unsafe_fragment(data) do
-    Jason.Fragment.new([?", data, ?"])
+  defp format_metadata({k, %_struct{} = v} = kv) do
+    cond do
+      impl = String.Chars.impl_for(v) -> {k, impl.to_string(v)}
+      Jason.Encoder.impl_for(v) != Jason.Encoder.Any -> kv
+      true -> {k, inspect(v)}
+    end
   end
+
+  defp format_metadata(other), do: other
 end

mix.exs

@@ -10,6 +10,7 @@ defmodule ExJsonLogger.Mixfile do
       name: "ex_json_logger",
       version: @version,
       elixir: ">= 1.14.0",
+      elixirc_paths: elixirc_paths(Mix.env()),
       elixirc_options: [warnings_as_errors: true],
       build_embedded: Mix.env() == :prod,
       start_permanent: Mix.env() == :prod,
@@ -34,6 +35,9 @@ defmodule ExJsonLogger.Mixfile do
     [extra_applications: [:logger]]
   end
 
+  defp elixirc_paths(:test), do: ["lib", "test/support"]
+  defp elixirc_paths(_env), do: ["lib"]
+
   defp deps do
     [
       {:ex_doc, ">= 0.0.0", only: :dev, runtime: false},

test/ex_json_logger_test.exs

@@ -34,31 +34,133 @@ defmodule ExJsonLoggerTest do
                "user_id" => 11
              } = decoded_log
     end
+
+    test "pids and refs are encoded" do
+      Logger.configure_backend(:console, metadata: [:pid, :ref])
+      ref = make_ref()
+      pid = self()
+      Logger.metadata(pid: pid, ref: ref)
+
+      "#Reference" <> encoded_ref = inspect(ref)
+      expected_ref = "#Ref" <> encoded_ref
+      expected_pid = inspect(pid)
+
+      message =
+        capture_log(fn ->
+          Logger.info("this is a message")
+        end)
+
+      {:ok, decoded_log} = Jason.decode(message)
+
+      assert %{
+               "msg" => "this is a message",
+               "level" => "info",
+               "pid" => ^expected_pid,
+               "ref" => ^expected_ref
+             } = decoded_log
+    end
+
+    test "metadata: :all" do
+      Logger.configure_backend(:console, metadata: :all)
+
+      message =
+        capture_log(fn ->
+          Logger.debug("this is a message")
+        end)
+
+      assert %{
+               "domain" => ["elixir"],
+               "file" => file,
+               "level" => "debug",
+               "line" => line,
+               "mfa" => "ExJsonLoggerTest.\"test format/4 metadata: :all\"/1",
+               "msg" => "this is a message",
+               "pid" => "#PID<0." <> _self_pid,
+               "time" => _time
+             } = Jason.decode!(message)
+
+      assert String.ends_with?(file, "/ex_json_logger/test/ex_json_logger_test.exs")
+      assert is_integer(line)
+    end
+
+    test "structured" do
+      Logger.configure_backend(:console, metadata: :all)
+
+      message =
+        capture_log(fn ->
+          Logger.debug(msg: "this is a message", where: "somewhere", ok: :ok)
+        end)
+
+      assert %{
+               "domain" => ["elixir"],
+               "file" => file,
+               "level" => "debug",
+               "line" => line,
+               "mfa" => "ExJsonLoggerTest.\"test format/4 structured\"/1",
+               "msg" => "[msg: \"this is a message\", where: \"somewhere\", ok: :ok]",
+               "pid" => "#PID<0." <> _self_pid,
+               "time" => _time
+             } = Jason.decode!(message)
+
+      assert String.ends_with?(file, "/ex_json_logger/test/ex_json_logger_test.exs")
+      assert is_integer(line)
+    end
+
+    test "metadata cannot override :msg and :level" do
+      Logger.configure_backend(:console, metadata: :all)
+
+      message =
+        capture_log(fn ->
+          Logger.debug("this is a message", level: :error, msg: "this is metadata")
+        end)
+
+      assert %{"level" => "debug", "msg" => "this is a message"} = Jason.decode!(message)
+    end
+
+    test "metadata can override :time" do
+      Logger.configure_backend(:console, metadata: :all)
+
+      message =
+        capture_log(fn ->
+          Logger.debug("this is a message", time: 0)
+        end)
+
+      assert %{"time" => "1970" <> _} = Jason.decode!(message)
+    end
   end
 
-  test "pids and refs are encoded" do
-    Logger.configure_backend(:console, metadata: [:pid, :ref])
-    ref = make_ref()
-    pid = self()
+  describe "protocols" do
+    test "String.Chars" do
+      Logger.configure_backend(:console, metadata: :all)
+
+      message =
+        capture_log(fn ->
+          Logger.debug("this is a message", some_key: %StringCharsValue{message: "hello"})
+        end)
+
+      assert %{"some_key" => "StringCharsValue says: hello"} = Jason.decode!(message)
+    end
+
+    test "Jason.Encoder" do
+      Logger.configure_backend(:console, metadata: :all)
 
-    <<"#Reference", ref_code::binary>> = inspect(ref)
-    expected_ref = "#Ref" <> ref_code
-    expected_pid = inspect(pid)
+      message =
+        capture_log(fn ->
+          Logger.debug("this is a message", some_key: %JasonEncoderValue{message: "hello", secret: "password"})
+        end)
 
-    Logger.metadata(pid: pid, ref: ref)
+      assert %{"some_key" => %{"message" => "hello"}} = Jason.decode!(message)
+    end
 
-    message =
-      capture_log(fn ->
-        Logger.info("this is a message")
-      end)
+    test "Inspect" do
+      Logger.configure_backend(:console, metadata: :all)
 
-    {:ok, decoded_log} = Jason.decode(message)
+      message =
+        capture_log(fn ->
+          Logger.debug("this is a message", some_key: %InspectValue{message: "hello", secret: "password"})
+        end)
 
-    assert %{
-             "msg" => "this is a message",
-             "level" => "info",
-             "pid" => ^expected_pid,
-             "ref" => ^expected_ref
-           } = decoded_log
+      assert %{"some_key" => "#InspectValue<message: \"hello\", ...>"} = Jason.decode!(message)
+    end
   end
 end

test/plug/logger_test.exs

@@ -1,5 +1,5 @@
 defmodule ExJsonLogger.Plug.LoggerTest do
-  use ExUnit.Case, async: true
+  use ExUnit.Case
   use Plug.Test
 
   import TestUtils, only: [capture_log: 1]

test/support/protocols.ex

@@ -0,0 +1,23 @@
+defmodule StringCharsValue do
+  @moduledoc false
+  defstruct [:message]
+
+  defimpl String.Chars do
+    @impl true
+    def to_string(%{message: message}) do
+      "StringCharsValue says: " <> message
+    end
+  end
+end
+
+defmodule JasonEncoderValue do
+  @moduledoc false
+  @derive {Jason.Encoder, only: [:message]}
+  defstruct [:message, :secret]
+end
+
+defmodule InspectValue do
+  @moduledoc false
+  @derive {Inspect, only: [:message]}
+  defstruct [:message, :secret]
+end