From c058660c1a6c8e6cd39ccb2ce05ac0b0f89ab889 Mon Sep 17 00:00:00 2001 From: Tymon Tobolski Date: Fri, 27 Oct 2023 11:12:43 +0200 Subject: [PATCH] Add metadata to logger --- lib/tesla/middleware/logger.ex | 60 +++++++++++++++--- test/tesla/middleware/logger_test.exs | 88 +++++++++++++++++++++++++++ test/tesla/middleware/retry_test.exs | 2 +- 3 files changed, 141 insertions(+), 9 deletions(-) diff --git a/lib/tesla/middleware/logger.ex b/lib/tesla/middleware/logger.ex index 0db42ae68..ab0d75bf1 100644 --- a/lib/tesla/middleware/logger.ex +++ b/lib/tesla/middleware/logger.ex @@ -43,13 +43,16 @@ defmodule Tesla.Middleware.Logger.Formatter do Enum.map(format, &output(&1, request, response, time)) end - defp output(:query, env, _, _), do: env.query |> Tesla.encode_query() - 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(:query, env, _, _), do: env.query |> Tesla.encode_query() + 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 @@ -74,6 +77,7 @@ defmodule Tesla.Middleware.Logger do - `:filter_headers` - sanitizes sensitive headers before logging in debug mode (see below) - `:debug` - show detailed request/response logging - `:format` - custom string template or function for log message (see below) + - `:metadata` - configure logger metadata ## Custom log format @@ -176,6 +180,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 @@ -208,7 +233,12 @@ defmodule Tesla.Middleware.Logger do if optional_runtime_format, do: Formatter.compile(optional_runtime_format), else: @format level = log_level(response, config) - Logger.log(level, fn -> Formatter.format(env, response, time, format) end) + + Logger.log( + level, + fn -> Formatter.format(env, response, time, format) end, + metadata(env, response, time, Keyword.get(config, :metadata, false)) + ) if Keyword.get(config, :debug, true) do Logger.debug(fn -> debug(env, response, config) end) @@ -248,6 +278,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)" diff --git a/test/tesla/middleware/logger_test.exs b/test/tesla/middleware/logger_test.exs index b708fde91..557d2fb66 100644 --- a/test/tesla/middleware/logger_test.exs +++ b/test/tesla/middleware/logger_test.exs @@ -289,4 +289,92 @@ defmodule Tesla.Middleware.LoggerTest do 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 diff --git a/test/tesla/middleware/retry_test.exs b/test/tesla/middleware/retry_test.exs index dc02e430c..90a2bc6ed 100644 --- a/test/tesla/middleware/retry_test.exs +++ b/test/tesla/middleware/retry_test.exs @@ -75,7 +75,7 @@ defmodule Tesla.Middleware.RetryTest do end test "finally pass on laggy request" do - assert {:ok, %Tesla.Env{url: "/maybe", method: :get}} = Client.get("/maybe") |> dbg() + assert {:ok, %Tesla.Env{url: "/maybe", method: :get}} = Client.get("/maybe") end test "pass retry_count opt" do