diff --git a/.gitignore b/.gitignore index f0b9050..c6d122d 100644 --- a/.gitignore +++ b/.gitignore @@ -5,3 +5,4 @@ erl_crash.dump *.ez .local.plt doc/ +.elixir_ls diff --git a/lib/plug/logger_json.ex b/lib/plug/logger_json.ex index 48eaecd..672a763 100644 --- a/lib/plug/logger_json.ex +++ b/lib/plug/logger_json.ex @@ -80,6 +80,7 @@ defmodule Plug.LoggerJSON do def call(conn, level_or_opts) when is_atom(level_or_opts) do call(conn, level: level_or_opts) end + def call(conn, opts) do level = Keyword.get(opts, :log, :info) start = :os.timestamp() @@ -95,50 +96,53 @@ defmodule Plug.LoggerJSON do def log(conn, :error, start, opts), do: log(conn, :info, start, opts) def log(conn, :info, start, opts), do: log_message(conn, :info, start, opts) def log(conn, :warn, start, opts), do: log(conn, :debug, start, opts) + def log(conn, :debug, start, opts) do log_message(conn, :info, start, Keyword.put_new(opts, :include_debug_logging, true)) end @spec log_error(atom(), map(), list()) :: atom() def log_error(kind, reason, stacktrace) do - _ = Logger.log :error, fn -> - %{ - "log_type" => "error", - "message" => Exception.format(kind, reason, stacktrace), - "request_id" => Logger.metadata[:request_id], - } - |> Poison.encode! - end + _ = + Logger.log(:error, fn -> + %{ + "log_type" => "error", + "message" => Exception.format(kind, reason, stacktrace), + "request_id" => Logger.metadata()[:request_id] + } + |> Jason.encode!() + end) end @spec log_message(Plug.Conn.t(), atom(), time(), opts) :: atom() defp log_message(conn, level, start, opts) do - Logger.log level, fn -> + Logger.log(level, fn -> conn |> basic_logging(start) |> Map.merge(debug_logging(conn, opts)) |> Map.merge(phoenix_attributes(conn)) |> Map.merge(extra_attributes(conn, opts)) - |> Poison.encode! - end + |> Jason.encode!() + end) end defp basic_logging(conn, start) do - stop = :os.timestamp() - duration = :timer.now_diff(stop, start) - req_id = Logger.metadata[:request_id] + stop = :os.timestamp() + duration = :timer.now_diff(stop, start) + req_id = Logger.metadata()[:request_id] req_headers = format_map_list(conn.req_headers) log_json = %{ - "api_version" => Map.get(req_headers, "accept", "N/A"), - "date_time" => iso8601(:calendar.now_to_datetime(:os.timestamp)), - "duration" => Float.round(duration / 1000, 3), - "log_type" => "http", - "method" => conn.method, - "path" => conn.request_path, - "request_id" => req_id, - "status" => conn.status + "api_version" => Map.get(req_headers, "accept", "N/A"), + "date_time" => iso8601(:calendar.now_to_datetime(:os.timestamp())), + "duration" => Float.round(duration / 1000, 3), + "log_type" => "http", + "method" => conn.method, + "path" => conn.request_path, + "request_id" => req_id, + "status" => conn.status } + Map.drop(log_json, Application.get_env(:plug_logger_json, :suppressed_keys, [])) end @@ -156,6 +160,7 @@ defmodule Plug.LoggerJSON do |> case do "N/A" -> Map.get(headers, "user-agent", "N/A") + accept_value -> accept_value end @@ -166,11 +171,13 @@ defmodule Plug.LoggerJSON do case Keyword.get(opts, :include_debug_logging) do true -> req_headers = format_map_list(conn.req_headers) + %{ - "client_ip" => format_ip(Map.get(req_headers, "x-forwarded-for", "N/A")), - "client_version" => client_version(req_headers), - "params" => format_map_list(conn.params), + "client_ip" => format_ip(Map.get(req_headers, "x-forwarded-for", "N/A")), + "client_version" => client_version(req_headers), + "params" => format_map_list(conn.params) } + _ -> %{} end @@ -179,6 +186,7 @@ defmodule Plug.LoggerJSON do @spec filter_values({String.t(), String.t()}) :: map() defp filter_values({k, v}) do filtered_keys = Application.get_env(:plug_logger_json, :filtered_keys, []) + if Enum.member?(filtered_keys, k) do %{k => "[FILTERED]"} else @@ -190,6 +198,7 @@ defmodule Plug.LoggerJSON do defp format_ip("N/A") do "N/A" end + defp format_ip(x_forwarded_for) do hd(String.split(x_forwarded_for, ", ")) end @@ -199,7 +208,7 @@ defmodule Plug.LoggerJSON do list |> Enum.take(20) |> Enum.map(&filter_values/1) - |> Enum.reduce(%{}, &(Map.merge(&2, &1))) + |> Enum.reduce(%{}, &Map.merge(&2, &1)) end defp format_value(value) when is_binary(value) do @@ -211,14 +220,19 @@ defmodule Plug.LoggerJSON do end defp iso8601({{year, month, day}, {hour, minute, second}}) do - zero_pad(year, 4) <> "-" <> zero_pad(month, 2) <> "-" <> zero_pad(day, 2) <> "T" <> - zero_pad(hour, 2) <> ":" <> zero_pad(minute, 2) <> ":" <> zero_pad(second, 2) <> "Z" + zero_pad(year, 4) <> + "-" <> + zero_pad(month, 2) <> + "-" <> + zero_pad(day, 2) <> + "T" <> zero_pad(hour, 2) <> ":" <> zero_pad(minute, 2) <> ":" <> zero_pad(second, 2) <> "Z" end @spec phoenix_attributes(map()) :: map() defp phoenix_attributes(%{private: %{phoenix_controller: controller, phoenix_action: action}}) do %{"handler" => "#{controller}##{action}"} end + defp phoenix_attributes(_) do %{"handler" => "N/A"} end diff --git a/mix.exs b/mix.exs index 138b943..dd0b7aa 100644 --- a/mix.exs +++ b/mix.exs @@ -4,7 +4,7 @@ defmodule PlugLoggerJson.Mixfile do def project do [ app: :plug_logger_json, - build_embedded: Mix.env == :prod, + build_embedded: Mix.env() == :prod, deps: deps(), dialyzer: [ plt_add_deps: true @@ -15,11 +15,16 @@ defmodule PlugLoggerJson.Mixfile do homepage_url: "https://github.com/bleacherreport/plug_logger_json", name: "Plug Logger JSON", package: package(), - preferred_cli_env: ["coveralls": :test, "coveralls.detail": :test, "coveralls.post": :test, "coveralls.html": :test], + preferred_cli_env: [ + coveralls: :test, + "coveralls.detail": :test, + "coveralls.post": :test, + "coveralls.html": :test + ], source_url: "https://github.com/bleacherreport/plug_logger_json", - start_permanent: Mix.env == :prod, + start_permanent: Mix.env() == :prod, test_coverage: [tool: ExCoveralls], - version: "0.6.0", + version: "0.6.0" ] end @@ -29,13 +34,13 @@ defmodule PlugLoggerJson.Mixfile do defp deps do [ - {:credo, "~> 0.8.10", only: [:dev]}, - {:dialyxir, "~> 0.5.1", only: [:dev]}, - {:earmark, "~> 1.2.4", only: [:dev]}, - {:ex_doc, "~> 0.18.0", only: [:dev]}, - {:excoveralls, "~> 0.8.0", only: [:test]}, - {:plug, "~> 1.0"}, - {:poison, "~> 1.5 or ~> 2.0 or ~> 3.0"} + {:credo, "~> 0.8.10", only: [:dev]}, + {:dialyxir, "~> 0.5.1", only: [:dev]}, + {:earmark, "~> 1.2.4", only: [:dev]}, + {:ex_doc, "~> 0.18.0", only: [:dev]}, + {:excoveralls, "~> 0.8.0", only: [:test]}, + {:plug, "~> 1.0"}, + {:jason, "~> 1.1"} ] end diff --git a/mix.lock b/mix.lock index 10eb9af..097f6be 100644 --- a/mix.lock +++ b/mix.lock @@ -1,4 +1,5 @@ -%{"bunt": {:hex, :bunt, "0.2.0", "951c6e801e8b1d2cbe58ebbd3e616a869061ddadcc4863d0a2182541acae9a38", [:mix], [], "hexpm"}, +%{ + "bunt": {:hex, :bunt, "0.2.0", "951c6e801e8b1d2cbe58ebbd3e616a869061ddadcc4863d0a2182541acae9a38", [:mix], [], "hexpm"}, "certifi": {:hex, :certifi, "2.0.0", "a0c0e475107135f76b8c1d5bc7efb33cd3815cb3cf3dea7aefdd174dabead064", [:rebar3], [], "hexpm"}, "credo": {:hex, :credo, "0.8.10", "261862bb7363247762e1063713bb85df2bbd84af8d8610d1272cd9c1943bba63", [:mix], [{:bunt, "~> 0.2.0", [hex: :bunt, repo: "hexpm", optional: false]}], "hexpm"}, "dialyxir": {:hex, :dialyxir, "0.5.1", "b331b091720fd93e878137add264bac4f644e1ddae07a70bf7062c7862c4b952", [:mix], [], "hexpm"}, @@ -8,6 +9,7 @@ "exjsx": {:hex, :exjsx, "4.0.0", "60548841e0212df401e38e63c0078ec57b33e7ea49b032c796ccad8cde794b5c", [:mix], [{:jsx, "~> 2.8.0", [hex: :jsx, repo: "hexpm", optional: false]}], "hexpm"}, "hackney": {:hex, :hackney, "1.10.1", "c38d0ca52ea80254936a32c45bb7eb414e7a96a521b4ce76d00a69753b157f21", [:rebar3], [{:certifi, "2.0.0", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "5.1.0", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "1.0.1", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "1.0.2", [hex: :mimerl, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "1.1.1", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}], "hexpm"}, "idna": {:hex, :idna, "5.1.0", "d72b4effeb324ad5da3cab1767cb16b17939004e789d8c0ad5b70f3cea20c89a", [:rebar3], [{:unicode_util_compat, "0.3.1", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm"}, + "jason": {:hex, :jason, "1.1.2", "b03dedea67a99223a2eaf9f1264ce37154564de899fd3d8b9a21b1a6fd64afe7", [:mix], [{:decimal, "~> 1.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm"}, "jsx": {:hex, :jsx, "2.8.3", "a05252d381885240744d955fbe3cf810504eb2567164824e19303ea59eef62cf", [:mix, :rebar3], [], "hexpm"}, "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], [], "hexpm"}, "mime": {:hex, :mime, "1.2.0", "78adaa84832b3680de06f88f0997e3ead3b451a440d183d688085be2d709b534", [:mix], [], "hexpm"}, @@ -15,4 +17,5 @@ "plug": {:hex, :plug, "1.4.3", "236d77ce7bf3e3a2668dc0d32a9b6f1f9b1f05361019946aae49874904be4aed", [:mix], [{:cowboy, "~> 1.0.1 or ~> 1.1", [hex: :cowboy, repo: "hexpm", optional: true]}, {:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}], "hexpm"}, "poison": {:hex, :poison, "3.1.0", "d9eb636610e096f86f25d9a46f35a9facac35609a7591b3be3326e99a0484665", [:mix], [], "hexpm"}, "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.1", "28a4d65b7f59893bc2c7de786dec1e1555bd742d336043fe644ae956c3497fbe", [:make, :rebar], [], "hexpm"}, - "unicode_util_compat": {:hex, :unicode_util_compat, "0.3.1", "a1f612a7b512638634a603c8f401892afbf99b8ce93a45041f8aaca99cadb85e", [:rebar3], [], "hexpm"}} + "unicode_util_compat": {:hex, :unicode_util_compat, "0.3.1", "a1f612a7b512638634a603c8f401892afbf99b8ce93a45041f8aaca99cadb85e", [:rebar3], [], "hexpm"}, +} diff --git a/test/plug/logger_json_test.exs b/test/plug/logger_json_test.exs index 04f0fdc..a9be1a0 100644 --- a/test/plug/logger_json_test.exs +++ b/test/plug/logger_json_test.exs @@ -12,7 +12,7 @@ defmodule Plug.LoggerJSONTest do plug Plug.Parsers, parsers: [:urlencoded, :multipart, :json], pass: ["*/*"], - json_decoder: Poison + json_decoder: Jason plug :passthrough defp passthrough(conn, _) do @@ -39,7 +39,7 @@ defmodule Plug.LoggerJSONTest do plug Plug.Parsers, parsers: [:urlencoded, :multipart, :json], pass: ["*/*"], - json_decoder: Poison + json_decoder: Jason plug :passthrough defp passthrough(conn, _) do @@ -54,7 +54,7 @@ defmodule Plug.LoggerJSONTest do plug Plug.Parsers, parsers: [:urlencoded, :multipart, :json], pass: ["*/*"], - json_decoder: Poison + json_decoder: Jason plug :passthrough defp passthrough(conn, _) do @@ -91,7 +91,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["api_version"] == "N/A" assert map["client_ip"] == "N/A" @@ -115,7 +115,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["api_version"] == "N/A" assert map["client_ip"] == "N/A" @@ -140,7 +140,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["client_ip"] == nil assert map["client_version"] == nil @@ -156,7 +156,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["client_ip"] == "209.49.75.165" assert map["client_version"] == "ios/1.5.4" @@ -172,7 +172,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["api_version"] == "N/A" assert map["client_ip"] == "N/A" @@ -195,7 +195,7 @@ defmodule Plug.LoggerJSONTest do "type" => "emoji", "user_id" => "a2e684ee-2e5f-4e4d-879a-bb253908eef3" }} - |> Poison.encode! + |> Jason.encode! {_conn, message} = conn(:post, "/", json) @@ -205,7 +205,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["api_version"] == "N/A" assert map["client_ip"] == "N/A" @@ -237,7 +237,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["api_version"] == "N/A" assert map["client_ip"] == "209.49.75.165" @@ -260,7 +260,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["client_version"] == "ios/1.5.4" end @@ -274,7 +274,7 @@ defmodule Plug.LoggerJSONTest do map = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert map["user_id"] == "123" assert map["other_id"] == 456 @@ -309,7 +309,7 @@ defmodule Plug.LoggerJSONTest do error_log = message |> remove_colors - |> Poison.decode! + |> Jason.decode! assert error_log["log_type"] == "error" assert error_log["message"] == "** (RuntimeError) ERROR\n web/controllers/reaction_controller.ex:53: Plug.LoggerJSONTest.MyDebugPlug.index/2\n web/controllers/reaction_controller.ex:1: Plug.LoggerJSONTest.MyDebugPlug.action/2\n web/controllers/reaction_controller.ex:1: Plug.LoggerJSONTest.MyDebugPlug.phoenix_controller_pipeline/2\n lib/reactions/endpoint.ex:1: Plug.LoggerJSONTest.MyDebugPlug.instrument/4\n lib/phoenix/router.ex:261: Plug.LoggerJSONTest.MyDebugPlug.dispatch/2\n web/router.ex:1: Plug.LoggerJSONTest.MyDebugPlug.do_call/2\n lib/plug/error_handler.ex:64: Plug.LoggerJSONTest.MyDebugPlug.call/2\n lib/reactions/endpoint.ex:1: Plug.LoggerJSONTest.MyDebugPlug.phoenix_pipeline/1\n lib/reactions/endpoint.ex:1: Plug.LoggerJSONTest.MyDebugPlug.call/2\n (plug) lib/plug/adapters/cowboy/handler.ex:15: Plug.Adapters.Cowboy.Handler.upgrade/4\n src/cowboy_protocol.erl:442: :cowboy_protocol.execute/4\n"