No OneTemporary
Actions

Size

15 KB

Referenced Files

None

Subscribers

None

View Options

	diff --git a/lib/tesla/middleware/logger.ex b/lib/tesla/middleware/logger.ex
	index eeb3ef2..66f3bda 100644
	--- a/lib/tesla/middleware/logger.ex
	+++ b/lib/tesla/middleware/logger.ex
	@@ -1,256 +1,274 @@
	defmodule Tesla.Middleware.Logger.Formatter do
	@moduledoc false

	# Heavily based on Elixir's Logger.Formatter
	# 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)

	@type format :: [atom \| binary]

	@spec compile(binary \| nil) :: format
	def compile(nil), do: compile(@default_format)

	def compile(binary) do
	~r/(?<h>)\$[a-z]+(?<t>)/
	\|> Regex.split(binary, on: [:h, :t], trim: true)
	\|> Enum.map(&compile_key/1)
	end

	defp compile_key("$" <> key) when key in @keys, do: String.to_atom(key)
	defp compile_key("$" <> key), do: raise(ArgumentError, "$#{key} is an invalid format pattern.")
	defp compile_key(part), do: part

	@spec format(Tesla.Env.t(), Tesla.Env.result(), integer, format) :: IO.chardata()
	def format(request, response, time, format) do
	Enum.map(format, &output(&1, request, response, time))
	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
	end

	defmodule Tesla.Middleware.Logger do
	@moduledoc """
	Log requests using Elixir's Logger.

	With the default settings it logs request method, url, response status and time taken in milliseconds.

	## Example usage
	```
	defmodule MyClient do
	use Tesla

	plug Tesla.Middleware.Logger
	end
	```

	## Options
	- `:log_level` - custom function for calculating log level (see below)
	- `:filter_headers` - sanitizes sensitive headers before logging in debug mode (see below)
	+ - `:debug` - show detailed request/response logging

	## Custom log format

	The default log format is `"$method $url -> $status ($time ms)"`
	which shows in logs like:

	```
	2018-03-25 18:32:40.397 [info] GET https://bitebot.io -> 200 (88.074 ms)
	```

	Because log format is processed during compile time it needs to be set in config:

	```
	config :tesla, Tesla.Middleware.Logger, format: "$method $url ====> $status / time=$time"
	```

	## Custom log levels

	By default, the following log levels will be used:
	- `:error` - for errors, 5xx and 4xx responses
	- `:warn` - for 3xx responses
	- `:info` - for 2xx responses

	You can customize this setting by providing your own `log_level/1` function:

	```
	defmodule MyClient do
	use Tesla

	plug Tesla.Middleware.Logger, log_level: &my_log_level/1

	def my_log_level(env) do
	case env.status do
	404 -> :info
	_ -> :default
	end
	end
	end
	```

	## Logger Debug output

	When the Elixir Logger log level is set to `:debug`
	Tesla Logger will show full request & response.

	If you want to disable detailed request/response logging
	but keep the `:debug` log level (i.e. in development)
	you can set `debug: false` in your config:

	```
	# config/dev.local.exs
	config :tesla, Tesla.Middleware.Logger, debug: false
	```

	Note that the logging configuration is evaluated at compile time,
	so Tesla must be recompiled for the configuration to take effect:

	```
	mix deps.clean --build tesla
	mix deps.compile tesla
	```

	+ In order to be able to set `:debug` at runtime we can
	+ pass it as a option to the middleware at runtime.
	+
	+ ```elixir
	+ def client do
	+ middleware = [
	+ # ...
	+ {Tesla.Middleware.Logger, debug: false}
	+ ]
	+
	+ Tesla.client(middleware)
	+ end
	+ ```
	+
	### Filter headers

	To sanitize sensitive headers such as `authorization` in
	debug logs, add them to the `:filter_headers` option.
	`:filter_headers` expects a list of header names as strings.

	```
	# config/dev.local.exs
	config :tesla, Tesla.Middleware.Logger,
	filter_headers: ["authorization"]
	```
	"""

	@behaviour Tesla.Middleware

	alias Tesla.Middleware.Logger.Formatter

	@config Application.get_env(:tesla, __MODULE__, [])
	@format Formatter.compile(@config[:format])

	@type log_level :: :info \| :warn \| :error

	require Logger

	@impl Tesla.Middleware
	def call(env, next, opts) do
	{time, response} = :timer.tc(Tesla, :run, [env, next])
	- level = log_level(response, opts)
	+
	+ config = Keyword.merge(@config, opts)
	+
	+ level = log_level(response, config)
	Logger.log(level, fn -> Formatter.format(env, response, time, @format) end)

	- if Keyword.get(@config, :debug, true) do
	- Logger.debug(fn -> debug(env, response, opts) end)
	+ if Keyword.get(config, :debug, true) do
	+ Logger.debug(fn -> debug(env, response, config) end)
	end

	response
	end

	defp log_level({:error, _}, _), do: :error

	- defp log_level({:ok, env}, opts) do
	- case Keyword.get(opts, :log_level) do
	+ defp log_level({:ok, env}, config) do
	+ case Keyword.get(config, :log_level) do
	nil ->
	default_log_level(env)

	fun when is_function(fun) ->
	case fun.(env) do
	:default -> default_log_level(env)
	level -> level
	end

	atom when is_atom(atom) ->
	atom
	end
	end

	@spec default_log_level(Tesla.Env.t()) :: log_level
	def default_log_level(env) do
	cond do
	env.status >= 400 -> :error
	env.status >= 300 -> :warn
	true -> :info
	end
	end

	@debug_no_query "(no query)"
	@debug_no_headers "(no headers)"
	@debug_no_body "(no body)"
	@debug_stream "[Elixir.Stream]"

	- defp debug(request, {:ok, response}, opts) do
	+ defp debug(request, {:ok, response}, config) do
	[
	"\n>>> REQUEST >>>\n",
	debug_query(request.query),
	?\n,
	- debug_headers(request.headers, opts),
	+ debug_headers(request.headers, config),
	?\n,
	debug_body(request.body),
	?\n,
	"\n<<< RESPONSE <<<\n",
	- debug_headers(response.headers, opts),
	+ debug_headers(response.headers, config),
	?\n,
	debug_body(response.body)
	]
	end

	- defp debug(request, {:error, error}, opts) do
	+ defp debug(request, {:error, error}, config) do
	[
	"\n>>> REQUEST >>>\n",
	debug_query(request.query),
	?\n,
	- debug_headers(request.headers, opts),
	+ debug_headers(request.headers, config),
	?\n,
	debug_body(request.body),
	?\n,
	"\n<<< RESPONSE ERROR <<<\n",
	inspect(error)
	]
	end

	defp debug_query([]), do: @debug_no_query

	defp debug_query(query) do
	query
	\|> Enum.flat_map(&Tesla.encode_pair/1)
	\|> Enum.map(fn {k, v} -> ["Query: ", to_string(k), ": ", to_string(v), ?\n] end)
	end

	- defp debug_headers([], _opts), do: @debug_no_headers
	+ defp debug_headers([], _config), do: @debug_no_headers

	- defp debug_headers(headers, opts) do
	- filtered = Keyword.get(opts, :filter_headers, [])
	+ defp debug_headers(headers, config) do
	+ filtered = Keyword.get(config, :filter_headers, [])

	Enum.map(headers, fn {k, v} ->
	v = if k in filtered, do: "[FILTERED]", else: v
	[k, ": ", v, ?\n]
	end)
	end

	defp debug_body(nil), do: @debug_no_body
	defp debug_body([]), do: @debug_no_body
	defp debug_body(%Stream{}), do: @debug_stream
	defp debug_body(stream) when is_function(stream), do: @debug_stream

	defp debug_body(%Tesla.Multipart{} = mp) do
	[
	"[Tesla.Multipart]\n",
	"boundary: ",
	mp.boundary,
	?\n,
	"content_type_params: ",
	inspect(mp.content_type_params),
	?\n
	\| Enum.map(mp.parts, &[inspect(&1), ?\n])
	]
	end

	defp debug_body(data) when is_binary(data) or is_list(data), do: data
	defp debug_body(term), do: inspect(term)
	end
	diff --git a/test/tesla/middleware/logger_test.exs b/test/tesla/middleware/logger_test.exs
	index 5d3258d..2846961 100644
	--- a/test/tesla/middleware/logger_test.exs
	+++ b/test/tesla/middleware/logger_test.exs
	@@ -1,242 +1,252 @@
	defmodule Tesla.Middleware.LoggerTest do
	use ExUnit.Case, async: false

	defmodule Client do
	use Tesla

	plug Tesla.Middleware.Logger

	adapter fn env ->
	env = Tesla.put_header(env, "content-type", "text/plain")

	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
	end

	import ExUnit.CaptureLog

	describe "Logger" do
	setup do
	Logger.configure(level: :info)

	:ok
	end

	test "connection error" do
	log = capture_log(fn -> Client.get("/connection-error") end)
	assert log =~ "/connection-error -> error: :econnrefused"
	end

	test "server error" do
	log = capture_log(fn -> Client.get("/server-error") end)
	assert log =~ "/server-error -> 500"
	end

	test "client error" do
	log = capture_log(fn -> Client.get("/client-error") end)
	assert log =~ "/client-error -> 404"
	end

	test "redirect" do
	log = capture_log(fn -> Client.get("/redirect") end)
	assert log =~ "/redirect -> 301"
	end

	test "ok" do
	log = capture_log(fn -> Client.get("/ok") end)
	assert log =~ "/ok -> 200"
	end
	end

	describe "Debug mode" do
	setup do
	Logger.configure(level: :debug)
	:ok
	end

	test "ok with params" do
	log = capture_log(fn -> Client.get("/ok", query: %{"test" => "true"}) end)
	assert log =~ "Query: test: true"
	end

	test "ok with list params" do
	log = capture_log(fn -> Client.get("/ok", query: %{"test" => ["first", "second"]}) end)
	assert log =~ "Query: test[]: first"
	assert log =~ "Query: test[]: second"
	end

	test "multipart" do
	mp = Tesla.Multipart.new() \|> Tesla.Multipart.add_field("field1", "foo")
	log = capture_log(fn -> Client.post("/ok", mp) end)
	assert log =~ "boundary: #{mp.boundary}"
	assert log =~ inspect(List.first(mp.parts))
	end

	test "stream" do
	stream = Stream.map(1..10, fn i -> "chunk: #{i}" end)
	log = capture_log(fn -> Client.post("/ok", stream) end)
	assert log =~ "/ok -> 200"
	assert log =~ "Stream"
	end
	+
	+ test "config at runtime" do
	+ client =
	+ Tesla.client([{Tesla.Middleware.Logger, debug: false}], fn env ->
	+ {:ok, %{env \| body: "response"}}
	+ end)
	+
	+ log = capture_log(fn -> Tesla.get(client, "/ok", query: %{"test" => "true"}) end)
	+ refute log =~ "Query: test: true"
	+ end
	end

	describe "Debug mode with custom structs" do
	# An example of such use case is google-elixir-apis

	setup do
	Logger.configure(level: :debug)
	:ok
	end

	defmodule CustomStruct do
	defstruct [:data]

	def call(env, next, _opts) do
	env = %{env \| body: encode(env.body)}

	with {:ok, env} <- Tesla.run(env, next) do
	{:ok, %{env \| body: decode(env.body)}}
	end
	end

	defp encode(%__MODULE__{data: body}), do: body
	defp decode(body), do: %__MODULE__{data: body}
	end

	defmodule CustomStructClient do
	use Tesla

	plug Tesla.Middleware.Logger
	plug CustomStruct

	adapter fn env -> {:ok, %{env \| status: 200, body: "ok"}} end
	end

	test "when used with custom encoders" do
	body = %CustomStruct{data: "some data"}
	log = capture_log(fn -> CustomStructClient.post("/", body) end)
	assert log =~ "CustomStruct{data"
	end
	end

	describe "with log_level" do
	defmodule ClientWithLogLevel do
	use Tesla

	plug Tesla.Middleware.Logger, log_level: &log_level/1

	defp log_level(env) do
	cond do
	env.status == 404 -> :info
	true -> Tesla.Middleware.Logger.default_log_level(env)
	end
	end

	adapter fn env ->
	case env.url do
	"/bad-request" ->
	{:ok, %{env \| status: 400, body: "bad request"}}

	"/not-found" ->
	{:ok, %{env \| status: 404, body: "not found"}}

	"/ok" ->
	{:ok, %{env \| status: 200, body: "ok"}}
	end
	end
	end

	test "not found" do
	log = capture_log(fn -> ClientWithLogLevel.get("/not-found") end)
	assert log =~ "[info] GET /not-found -> 404"
	end

	test "bad request" do
	log = capture_log(fn -> ClientWithLogLevel.get("/bad-request") end)
	assert log =~ "[error] GET /bad-request -> 400"
	end

	test "ok" do
	log = capture_log(fn -> ClientWithLogLevel.get("/ok") end)
	assert log =~ "[info] GET /ok -> 200"
	end
	end

	describe "with filter_headers" do
	setup do
	Logger.configure(level: :debug)
	middleware = [{Tesla.Middleware.Logger, filter_headers: ["authorization"]}]
	adapter = fn env -> {:ok, %{env \| status: 200, body: "ok"}} end
	client = Tesla.client(middleware, adapter)
	%{client: client}
	end

	test "sanitizes given header values", %{client: client} do
	headers = [
	{"authorization", "Basic my-secret"},
	{"other-header", "is not filtered"}
	]

	log = capture_log(fn -> Tesla.get(client, "/ok", headers: headers) end)

	assert log =~ "authorization: [FILTERED]"
	assert log =~ "other-header: is not filtered"
	end
	end

	alias Tesla.Middleware.Logger.Formatter

	describe "Formatter: compile/1" do
	test "compile default format" do
	assert is_list(Formatter.compile(nil))
	end

	test "comppile pattern" do
	assert Formatter.compile("$method $url => $status") == [:method, " ", :url, " => ", :status]
	end

	test "raise compile-time error when pattern not found" do
	assert_raise ArgumentError, fn ->
	Formatter.compile("$method $nope")
	end
	end
	end

	describe "Formatter: format/2" do
	setup do
	format = Formatter.compile("$method $url -> $status \| $time")
	{:ok, format: format}
	end

	test "format error", %{format: format} do
	req = %Tesla.Env{method: :get, url: "/error"}
	res = {:error, :econnrefused}

	assert IO.chardata_to_string(Formatter.format(req, res, 200_000, format)) ==
	"GET /error -> error: :econnrefused \| 200.000"
	end

	test "format ok response", %{format: format} do
	req = %Tesla.Env{method: :get, url: "/ok"}
	res = {:ok, %Tesla.Env{method: :get, url: "/ok", status: 201}}

	assert IO.chardata_to_string(Formatter.format(req, res, 200_000, format)) ==
	"GET /ok -> 201 \| 200.000"
	end
	end
	end

File Metadata

Mime Type: text/x-diff
Expires: Sun, Nov 24, 6:56 AM (20 h, 36 m)
Storage Engine: blob
Storage Format: Raw Data
Storage Handle: 39363
Default Alt Text: (15 KB)

No OneTemporaryActions

View Options

File Metadata

Event Timeline

No OneTemporary
Actions