Add metadata to logger

lib/tesla/middleware/logger.ex

@@ -5,7 +5,7 @@ defmodule Tesla.Middleware.Logger.Formatter do
   # https://github.com/elixir-lang/elixir/blob/v1.6.4/lib/logger/lib/logger/formatter.ex
 
   @default_format "$method $url -> $status ($time ms)"
-  @keys ~w(method url status time query)
+  @keys ~w(method url status time query request_body response_body)
 
   @type format :: [atom | binary]
 
@@ -43,18 +43,21 @@ defmodule Tesla.Middleware.Logger.Formatter do
     Enum.map(format, &output(&1, request, response, time))
   end
 
-  defp output(:query, env, _, _) do
+  def output(:query, env, _, _) do
     encoding = Keyword.get(env.opts, :query_encoding, :www_form)
 
     Tesla.encode_query(env.query, encoding)
   end
 
-  defp output(:method, env, _, _), do: env.method |> to_string() |> String.upcase()
-  defp output(:url, env, _, _), do: env.url
-  defp output(:status, _, {:ok, env}, _), do: to_string(env.status)
-  defp output(:status, _, {:error, reason}, _), do: "error: " <> inspect(reason)
-  defp output(:time, _, _, time), do: :io_lib.format("~.3f", [time / 1000])
-  defp output(binary, _, _, _), do: binary
+  def output(:method, env, _, _), do: env.method |> to_string() |> String.upcase()
+  def output(:url, env, _, _), do: env.url
+  def output(:status, _, {:ok, env}, _), do: to_string(env.status)
+  def output(:status, _, {:error, reason}, _), do: "error: " <> inspect(reason)
+  def output(:time, _, _, time), do: to_string(:io_lib.format("~.3f", [time / 1000]))
+  def output(:request_body, env, _, _), do: env.body
+  def output(:response_body, _, {:ok, env}, _), do: env.body
+  def output(:response_body, _, {:error, _}, _), do: nil
+  def output(binary, _, _, _), do: binary
 end
 
 defmodule Tesla.Middleware.Logger do
@@ -82,6 +85,7 @@ defmodule Tesla.Middleware.Logger do
   - `:metadata` - metadata to pass to `Logger`
   - `:debug` - use `Logger.debug/2` to log request/response details
   - `:format` - custom string template or function for log message (see below)
+  - `:metadata` - configure logger metadata
 
   ## Custom log format
 
@@ -237,6 +241,27 @@ defmodule Tesla.Middleware.Logger do
   config :tesla, Tesla.Middleware.Logger,
     filter_headers: ["authorization"]
   ```
+
+  ### Configure Logger metadata
+
+  Set `metadata: true` to include metadata in the log output.
+
+  ```
+  plug Tesla.Middleware.Logger, metadata: true
+  ```
+
+  Pass a list of atoms to `metadata` to include only specific metadata.
+
+  ```
+  plug Tesla.Middleware.Logger, metadata: [:url, :status, :request_body]
+  ```
+
+  Use `:conceal` request option to conceal sensitive requests.
+
+  ```
+  Tesla.get(client, opts: [conceal: true]])
+  ```
+
   """
 
   @behaviour Tesla.Middleware
@@ -268,12 +293,17 @@ defmodule Tesla.Middleware.Logger do
     format =
       if optional_runtime_format, do: Formatter.compile(optional_runtime_format), else: @format
 
-    metadata = Keyword.get(config, :metadata, [])
     level = log_level(response, config)
-    Logger.log(level, fn -> Formatter.format(env, response, time, format) end, metadata)
+    metadata_opt = Keyword.get(config, :metadata, false)
+
+    Logger.log(
+      level,
+      fn -> Formatter.format(env, response, time, format) end,
+      metadata(env, response, time, metadata_opt)
+    )
 
     if Keyword.get(config, :debug, true) do
-      Logger.debug(fn -> debug(env, response, config) end, metadata)
+      Logger.debug(fn -> debug(env, response, config) end, metadata(env, response, time, metadata_opt))
     end
 
     response
@@ -343,6 +373,20 @@ defmodule Tesla.Middleware.Logger do
     end
   end
 
+  @metadata_keys [:method, :url, :query, :status, :request_body, :response_body, :time]
+
+  defp metadata(req, res, time, keys) when is_list(keys) do
+    if req.opts[:conceal] do
+      []
+    else
+      [tesla: Enum.into(keys, %{}, fn key -> {key, Formatter.output(key, req, res, time)} end)]
+    end
+  end
+
+  defp metadata(req, res, time, true), do: metadata(req, res, time, @metadata_keys)
+
+  defp metadata(_req, _res, _time, false), do: []
+
   @debug_no_query "(no query)"
   @debug_no_headers "(no headers)"
   @debug_no_body "(no body)"

test/tesla/middleware/logger_test.exs

@@ -223,19 +223,6 @@
     end
   end
 
-  describe "with metadata" do
-    setup do
-      middleware = [{Tesla.Middleware.Logger, metadata: [request_id: "abc123"]}]
-      adapter = fn env -> {:ok, %{env | status: 200, body: "ok"}} end
-      client = Tesla.client(middleware, adapter)
-      %{client: client}
-    end
-
-    test "metadata is passed to the main log call", %{client: client} do
-      log = capture_log([metadata: [:request_id]], fn -> Tesla.get(client, "/ok") end)
-      assert log =~ "[info] request_id=abc123"
-    end
-  end
 
   describe "with level" do
     defmodule ClientWithLevel do
@@ -489,4 +476,92 @@
       assert Formatter.format(nil, nil, nil, {CompileMod, :format}) == "message"
     end
   end
+
+  describe "Metadata" do
+    defmodule TestLoggerBackend do
+      def init(_mod), do: {:ok, []}
+
+      def handle_event({_level, _pid, {_mod, _msg, _time, meta}}, state) do
+        send(meta[:pid], {:metadata, meta})
+        {:ok, state}
+      end
+
+      def handle_event(_, state), do: {:ok, state}
+    end
+
+    setup do
+      {:ok, _} = Logger.add_backend(TestLoggerBackend)
+      on_exit(fn -> Logger.remove_backend(TestLoggerBackend) end)
+
+      adapter = fn env ->
+        case env.url do
+          "/connection-error" -> {:error, :econnrefused}
+          "/server-error" -> {:ok, %{env | status: 500, body: "error"}}
+          "/client-error" -> {:ok, %{env | status: 404, body: "error"}}
+          "/redirect" -> {:ok, %{env | status: 301, body: "moved"}}
+          "/ok" -> {:ok, %{env | status: 200, body: "ok"}}
+        end
+      end
+
+      [adapter: adapter]
+    end
+
+    test "do not include metadata by default", %{adapter: adapter} do
+      middleware = [
+        Tesla.Middleware.Logger
+      ]
+
+      client = Tesla.client(middleware, adapter)
+      capture_log(fn -> Tesla.get(client, "/ok") end)
+      assert_received {:metadata, meta}
+      refute meta[:tesla]
+    end
+
+    test "include all metadata when set to true", %{adapter: adapter} do
+      middleware = [
+        {Tesla.Middleware.Logger, metadata: true}
+      ]
+
+      client = Tesla.client(middleware, adapter)
+      capture_log(fn -> Tesla.post(client, "/ok", "reqdata") end)
+      assert_received {:metadata, meta}
+
+      assert meta[:tesla] == %{
+               status: "200",
+               time: "0.000",
+               url: "/ok",
+               query: "",
+               method: "POST",
+               request_body: "reqdata",
+               response_body: "ok"
+             }
+    end
+
+    test "include only selected metadata", %{adapter: adapter} do
+      middleware = [
+        {Tesla.Middleware.Logger, metadata: [:status, :method]}
+      ]
+
+      client = Tesla.client(middleware, adapter)
+      capture_log(fn -> Tesla.post(client, "/ok", "reqdata") end)
+      assert_received {:metadata, meta}
+
+      assert meta[:tesla] == %{
+               status: "200",
+               method: "POST"
+             }
+    end
+
+    test "do not include metadata for concealed reqeusts", %{adapter: adapter} do
+      middleware = [
+        {Tesla.Middleware.Logger, metadata: true}
+      ]
+
+      client = Tesla.client(middleware, adapter)
+      capture_log(fn -> Tesla.post(client, "/ok", "reqdata", opts: [conceal: true]) end)
+      assert_received {:metadata, meta}
+
+      refute meta[:tesla]
+    end
+  end
 end