From 6ebac0da6e33e08be7e83551a88b40014815159a Mon Sep 17 00:00:00 2001 From: ruslandoga <67764432+ruslandoga@users.noreply.github.com> Date: Fri, 22 Dec 2023 11:16:06 +0800 Subject: [PATCH] support more metadata types --- bench/format.exs | 14 +++- lib/ex_json_logger.ex | 109 ++++++++++++++++++++------- mix.exs | 4 + test/ex_json_logger_test.exs | 140 ++++++++++++++++++++++++++++++----- test/plug/logger_test.exs | 2 +- test/support/protocols.ex | 23 ++++++ 6 files changed, 245 insertions(+), 47 deletions(-) create mode 100644 test/support/protocols.ex diff --git a/bench/format.exs b/bench/format.exs index e9e18f6..3ee577f 100644 --- a/bench/format.exs +++ b/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 + ]} } ) diff --git a/lib/ex_json_logger.ex b/lib/ex_json_logger.ex index c373ba3..5b06cc2 100644 --- a/lib/ex_json_logger.ex +++ b/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 diff --git a/mix.exs b/mix.exs index dcfc774..ee03dcb 100644 --- a/mix.exs +++ b/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}, diff --git a/test/ex_json_logger_test.exs b/test/ex_json_logger_test.exs index a18086c..35d33d5 100644 --- a/test/ex_json_logger_test.exs +++ b/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"} = Jason.decode!(message) + end end end diff --git a/test/plug/logger_test.exs b/test/plug/logger_test.exs index a09496f..bf0c163 100644 --- a/test/plug/logger_test.exs +++ b/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] diff --git a/test/support/protocols.ex b/test/support/protocols.ex new file mode 100644 index 0000000..b8330b2 --- /dev/null +++ b/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