Skip to content

Commit

Permalink
Add metadata to logger
Browse files Browse the repository at this point in the history
  • Loading branch information
teamon committed Oct 27, 2023
1 parent d3ea190 commit 7d041e6
Show file tree
Hide file tree
Showing 2 changed files with 140 additions and 8 deletions.
60 changes: 52 additions & 8 deletions lib/tesla/middleware/logger.ex
Original file line number Diff line number Diff line change
Expand Up @@ -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: :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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)"
Expand Down
88 changes: 88 additions & 0 deletions test/tesla/middleware/logger_test.exs
Original file line number Diff line number Diff line change
Expand Up @@ -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

Check warning on line 297 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 25.3 / Elixir 1.14

variable "level" is unused (if the variable is not meant to be used, prefix it with an underscore)

Check warning on line 297 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 24.3 / Elixir 1.14

variable "level" is unused (if the variable is not meant to be used, prefix it with an underscore)

Check warning on line 297 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 25.3 / Elixir 1.13

variable "level" is unused (if the variable is not meant to be used, prefix it with an underscore)

Check warning on line 297 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 24.3 / Elixir 1.13

variable "level" is unused (if the variable is not meant to be used, prefix it with an underscore)
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

Check failure on line 333 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 25.3 / Elixir 1.14

test Metadata include all metadata when set to true (Tesla.Middleware.LoggerTest)

Check failure on line 333 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 24.3 / Elixir 1.14

test Metadata include all metadata when set to true (Tesla.Middleware.LoggerTest)

Check failure on line 333 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 25.3 / Elixir 1.13

test Metadata include all metadata when set to true (Tesla.Middleware.LoggerTest)

Check failure on line 333 in test/tesla/middleware/logger_test.exs

View workflow job for this annotation

GitHub Actions / OTP 24.3 / Elixir 1.13

test Metadata include all metadata when set to true (Tesla.Middleware.LoggerTest)
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: ~c"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

0 comments on commit 7d041e6

Please sign in to comment.