feat: reports safelisted contents of Logger.metadata

lib/tower/event.ex

@@ -133,7 +133,7 @@ defmodule Tower.Event do
       datetime: event_datetime(log_event),
       log_event: log_event,
       plug_conn: plug_conn(options),
-      metadata: Keyword.get(options, :metadata, %{}),
+      metadata: Map.merge(logger_metadata(log_event), Keyword.get(options, :metadata, %{})),
       by: Keyword.get(options, :by)
     }
   end
@@ -156,6 +156,16 @@ defmodule Tower.Event do
     Keyword.get(options, :plug_conn, Keyword.get(options, :log_event)[:meta][:conn])
   end
 
+  defp logger_metadata(log_event) do
+    (log_event[:meta] || %{})
+    |> Map.merge(Enum.into(Logger.metadata(), %{}))
+    |> Map.take(logger_metadata_keys())
+  end
+
+  defp logger_metadata_keys do
+    Application.fetch_env!(:tower, :logger_metadata)
+  end
+
   defp put_similarity_id(%__MODULE__{} = event) do
     struct!(event, similarity_id: :erlang.phash2(Map.take(event, @similarity_source_attributes)))
   end

mix.exs

@@ -35,7 +35,8 @@ defmodule Tower.MixProject do
       env: [
         reporters: [Tower.EphemeralReporter],
         log_level: :critical,
-        ignored_exceptions: []
+        ignored_exceptions: [],
+        logger_metadata: []
       ],
       mod: {Tower.Application, []}
     ]

test/support/test_app.ex

@@ -3,6 +3,8 @@ defmodule TestApp.UncaughtThrowWorker do
 
   @impl Oban.Worker
   def perform(%Oban.Job{}) do
+    Logger.metadata(user_id: 123, secret: "secret")
+
     throw("something")
 
     :ok
@@ -14,6 +16,8 @@ defmodule TestApp.AbnormalExitWorker do
 
   @impl Oban.Worker
   def perform(%Oban.Job{}) do
+    Logger.metadata(user_id: 123, secret: "secret")
+
     exit(:abnormal)
 
     :ok
@@ -25,6 +29,8 @@ defmodule TestApp.RuntimeErrorWorker do
 
   @impl Oban.Worker
   def perform(%Oban.Job{}) do
+    Logger.metadata(user_id: 123, secret: "secret")
+
     raise "error from an Oban worker"
 
     :ok

test/support/test_plug.ex

@@ -5,18 +5,24 @@ defmodule Tower.TestPlug do
   plug(:dispatch)
 
   get "/runtime-error" do
+    Logger.metadata(user_id: 123, secret: "secret")
+
     raise "an error"
 
     send_resp(conn, 200, "OK")
   end
 
   get "/abnormal-exit" do
+    Logger.metadata(user_id: 123, secret: "secret")
+
     exit(:abnormal)
 
     send_resp(conn, 200, "OK")
   end
 
   get "/uncaught-throw" do
+    Logger.metadata(user_id: 123, secret: "secret")
+
     throw("something")
 
     send_resp(conn, 200, "OK")

test/tower/oban_test.exs

@@ -26,6 +26,8 @@ defmodule TowerObanTest do
   end
 
   test "reports raised exception in an Oban worker" do
+    put_env(:logger_metadata, [:user_id])
+
     TestApp.RuntimeErrorWorker.new(%{}, max_attempts: 1)
     |> Oban.insert()
 
@@ -38,6 +40,7 @@ defmodule TowerObanTest do
           kind: :error,
           reason: %RuntimeError{message: "error from an Oban worker"},
           stacktrace: stacktrace,
+          metadata: metadata,
           by: Tower.ObanExceptionHandler
         }
       ] = Tower.EphemeralReporter.events()
@@ -46,9 +49,12 @@ defmodule TowerObanTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    assert metadata == %{user_id: 123}
   end
 
   test "reports uncaught throw generated in an Oban worker" do
+    put_env(:logger_metadata, [:user_id])
+
     TestApp.UncaughtThrowWorker.new(%{}, max_attempts: 1)
     |> Oban.insert()
 
@@ -61,6 +67,7 @@ defmodule TowerObanTest do
           kind: :error,
           reason: %Oban.CrashError{reason: "something"},
           stacktrace: stacktrace,
+          metadata: metadata,
           by: Tower.ObanExceptionHandler
         }
       ] = Tower.EphemeralReporter.events()
@@ -69,9 +76,12 @@ defmodule TowerObanTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    assert metadata == %{user_id: 123}
   end
 
   test "reports abnormal exit generated in an Oban worker" do
+    put_env(:logger_metadata, [:user_id])
+
     TestApp.AbnormalExitWorker.new(%{}, max_attempts: 1)
     |> Oban.insert()
 
@@ -84,6 +94,7 @@ defmodule TowerObanTest do
           kind: :error,
           reason: %Oban.CrashError{reason: :abnormal},
           stacktrace: stacktrace,
+          metadata: metadata,
           by: Tower.ObanExceptionHandler
         }
       ] = Tower.EphemeralReporter.events()
@@ -92,6 +103,20 @@ defmodule TowerObanTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    assert metadata == %{user_id: 123}
+  end
+
+  defp put_env(key, value) do
+    original_value = Application.get_env(:tower, key)
+    Application.put_env(:tower, key, value)
+
+    on_exit(fn ->
+      if original_value == nil do
+        Application.delete_env(:tower, key)
+      else
+        Application.put_env(:tower, key, original_value)
+      end
+    end)
   end
 
   defp recent_datetime?(datetime) do

test/tower/plug_test.exs

@@ -12,6 +12,8 @@ defmodule TowerPlugTest do
   end
 
   test "reports runtime error during plug dispatch with Plug.Cowboy" do
+    put_env(:logger_metadata, [:user_id])
+
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/runtime-error"
@@ -31,6 +33,7 @@ defmodule TowerPlugTest do
           kind: :error,
           reason: %RuntimeError{message: "an error"},
           stacktrace: stacktrace,
+          metadata: metadata,
           plug_conn: %Plug.Conn{} = plug_conn,
           by: Tower.LoggerHandler
         }
@@ -40,6 +43,10 @@ defmodule TowerPlugTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    # Plug.Cowboy doesn't report Logger.metadata when logging plug call
+    # exceptions: https://github.com/elixir-plug/plug_cowboy/pull/103
+    # assert metadata == %{user_id: 123}
+    assert metadata == %{}
     assert Plug.Conn.request_url(plug_conn) == url
   end
 
@@ -63,6 +70,7 @@ defmodule TowerPlugTest do
           kind: :throw,
           reason: "something",
           stacktrace: stacktrace,
+          metadata: metadata,
           plug_conn: %Plug.Conn{} = plug_conn,
           by: Tower.LoggerHandler
         }
@@ -72,6 +80,10 @@ defmodule TowerPlugTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    # Plug.Cowboy doesn't report Logger.metadata when logging plug call
+    # exceptions: https://github.com/elixir-plug/plug_cowboy/pull/103
+    # assert metadata == %{user_id: 123}
+    assert metadata == %{}
     assert Plug.Conn.request_url(plug_conn) == url
   end
 
@@ -95,6 +107,7 @@ defmodule TowerPlugTest do
           kind: :exit,
           reason: :abnormal,
           stacktrace: stacktrace,
+          metadata: metadata,
           plug_conn: %Plug.Conn{} = plug_conn,
           by: Tower.LoggerHandler
         }
@@ -105,10 +118,16 @@ defmodule TowerPlugTest do
     assert recent_datetime?(datetime)
     # Plug.Cowboy doesn't provide stacktrace for exits
     assert [] = stacktrace
+    # Plug.Cowboy doesn't report Logger.metadata when logging plug call
+    # exceptions: https://github.com/elixir-plug/plug_cowboy/pull/103
+    # assert metadata == %{user_id: 123}
+    assert metadata == %{}
     assert Plug.Conn.request_url(plug_conn) == url
   end
 
   test "reports runtime error during plug dispatch with Bandit" do
+    put_env(:logger_metadata, [:user_id])
+
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/runtime-error"
@@ -128,6 +147,7 @@ defmodule TowerPlugTest do
           kind: :error,
           reason: %RuntimeError{message: "an error"},
           stacktrace: stacktrace,
+          metadata: metadata,
           plug_conn: %Plug.Conn{} = plug_conn,
           by: Tower.LoggerHandler
         }
@@ -137,10 +157,13 @@ defmodule TowerPlugTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    assert metadata == %{user_id: 123}
     assert Plug.Conn.request_url(plug_conn) == url
   end
 
   test "reports uncaught throw during plug dispatch with Bandit" do
+    put_env(:logger_metadata, [:user_id])
+
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/uncaught-throw"
@@ -160,6 +183,7 @@ defmodule TowerPlugTest do
           kind: :throw,
           reason: "something",
           stacktrace: stacktrace,
+          metadata: metadata,
           plug_conn: %Plug.Conn{} = plug_conn,
           by: Tower.LoggerHandler
         }
@@ -169,10 +193,13 @@ defmodule TowerPlugTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    assert metadata == %{user_id: 123}
     assert Plug.Conn.request_url(plug_conn) == url
   end
 
   test "reports abnormal exit during plug dispatch with Bandit" do
+    put_env(:logger_metadata, [:user_id])
+
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/abnormal-exit"
@@ -192,6 +219,7 @@ defmodule TowerPlugTest do
           kind: :exit,
           reason: :abnormal,
           stacktrace: stacktrace,
+          metadata: metadata,
           # Bandit doesn't handle exits so it doesn't provide the conn in the metadata
           plug_conn: nil,
           by: Tower.LoggerHandler
@@ -202,6 +230,7 @@ defmodule TowerPlugTest do
     assert String.length(id) == 36
     assert recent_datetime?(datetime)
     assert [_ | _] = stacktrace
+    assert metadata == %{user_id: 123}
   end
 
   test "reports message plug_conn manually" do
@@ -224,6 +253,19 @@ defmodule TowerPlugTest do
     )
   end
 
+  defp put_env(key, value) do
+    original_value = Application.get_env(:tower, key)
+    Application.put_env(:tower, key, value)
+
+    on_exit(fn ->
+      if original_value == nil do
+        Application.delete_env(:tower, key)
+      else
+        Application.put_env(:tower, key, original_value)
+      end
+    end)
+  end
+
   defp recent_datetime?(datetime) do
     diff =
       :logger.timestamp()

test/tower_test.exs

@@ -681,6 +681,30 @@ defmodule TowerTest do
     )
   end
 
+  test "reports logger metadata" do
+    put_env(:logger_metadata, [:user_id])
+
+    capture_log(fn ->
+      in_unlinked_process(fn ->
+        Logger.metadata(user_id: 123, secret: "secret")
+
+        raise "an error"
+      end)
+    end)
+
+    assert_eventually(
+      [
+        %{
+          kind: :error,
+          reason: %RuntimeError{message: "an error"},
+          metadata: metadata
+        }
+      ] = reported_events()
+    )
+
+    assert metadata == %{user_id: 123}
+  end
+
   defp in_unlinked_process(fun) when is_function(fun, 0) do
     {:ok, pid} = Task.Supervisor.start_link()