diff --git a/.formatter.exs b/.formatter.exs new file mode 100644 index 0000000..00950e6 --- /dev/null +++ b/.formatter.exs @@ -0,0 +1,4 @@ +[ + inputs: ["mix.exs", "{config,lib,test}/**/*.{ex,exs}"], + line_length: 120 +] diff --git a/.gitignore b/.gitignore index f0b9050..8e044f8 100644 --- a/.gitignore +++ b/.gitignore @@ -5,3 +5,4 @@ erl_crash.dump *.ez .local.plt doc/ +.elixir_ls/* diff --git a/lib/ecto/logger_json.ex b/lib/ecto/logger_json.ex index 8e80cdb..b370288 100644 --- a/lib/ecto/logger_json.ex +++ b/lib/ecto/logger_json.ex @@ -27,24 +27,27 @@ defmodule Ecto.LoggerJSON do """ @spec log(%{}) :: %{} def log(entry) do - _ = Logger.debug(fn -> - %{query_time: query_time, decode_time: decode_time, queue_time: queue_time, query: query} = entry - [query_time, decode_time, queue_time] = - [query_time, decode_time, queue_time] - |> Enum.map(&format_time/1) + _ = + Logger.debug(fn -> + %{query_time: query_time, decode_time: decode_time, queue_time: queue_time, query: query} = entry - %{ - "decode_time" => decode_time, - "duration" => Float.round(query_time + decode_time + queue_time, 3), - "log_type" => "persistence", - "request_id" => Logger.metadata[:request_id], - "query" => query, - "query_time" => query_time, - "queue_time" => queue_time - } - |> Poison.encode! - end) - entry + [query_time, decode_time, queue_time] = + [query_time, decode_time, queue_time] + |> Enum.map(&format_time/1) + + %{ + "decode_time" => decode_time, + "duration" => Float.round(query_time + decode_time + queue_time, 3), + "log_type" => "persistence", + "request_id" => Logger.metadata()[:request_id], + "query" => query, + "query_time" => query_time, + "queue_time" => queue_time + } + |> Poison.encode!() + end) + + entry end @doc """ @@ -55,29 +58,33 @@ defmodule Ecto.LoggerJSON do """ @spec log(%{}, atom) :: %{} def log(entry, level) do - _ = Logger.log(level, fn -> - %{query_time: query_time, decode_time: decode_time, queue_time: queue_time, query: query} = entry - [query_time, decode_time, queue_time] = - [query_time, decode_time, queue_time] - |> Enum.map(&format_time/1) + _ = + Logger.log(level, fn -> + %{query_time: query_time, decode_time: decode_time, queue_time: queue_time, query: query} = entry + + [query_time, decode_time, queue_time] = + [query_time, decode_time, queue_time] + |> Enum.map(&format_time/1) + + %{ + "decode_time" => decode_time, + "duration" => Float.round(query_time + decode_time + queue_time, 3), + "log_type" => "persistence", + "request_id" => Logger.metadata()[:request_id], + "query" => query, + "query_time" => query_time, + "queue_time" => queue_time + } + |> Poison.encode!() + end) - %{ - "decode_time" => decode_time, - "duration" => Float.round(query_time + decode_time + queue_time, 3), - "log_type" => "persistence", - "request_id" => Logger.metadata[:request_id], - "query" => query, - "query_time" => query_time, - "queue_time" => queue_time - } - |> Poison.encode! - end) entry end ## Helpers defp format_time(nil), do: 0.0 + defp format_time(time) do ms = System.convert_time_unit(time, :native, :micro_seconds) / 1000 Float.round(ms, 3) diff --git a/mix.exs b/mix.exs index 164a5a4..04d3314 100644 --- a/mix.exs +++ b/mix.exs @@ -4,7 +4,7 @@ defmodule EctoLoggerJson.Mixfile do def project do [ app: :ecto_logger_json, - build_embedded: Mix.env == :prod, + build_embedded: Mix.env() == :prod, deps: deps(), dialyzer: [ plt_add_deps: true, @@ -16,11 +16,11 @@ defmodule EctoLoggerJson.Mixfile do homepage_url: "https://github.com/bleacherreport/ecto_logger_json", name: "Ecto 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/ecto_logger_json", - start_permanent: Mix.env == :prod, + start_permanent: Mix.env() == :prod, test_coverage: [tool: ExCoveralls], - version: "0.1.0", + version: "0.1.0" ] end @@ -30,12 +30,12 @@ defmodule EctoLoggerJson.Mixfile do defp deps do [ - {:credo, "~> 0.5", only: [:dev]}, - {:dialyxir, "~> 0.4", only: [:dev]}, - {:earmark, "~> 1.0", only: [:dev]}, - {:ex_doc, "~> 0.14", only: [:dev]}, - {:excoveralls, "~> 0.6", only: [:test]}, - {:poison, "~> 1.5 or ~> 2.0 or ~> 3.0"} + {:credo, "~> 0.5", only: [:dev]}, + {:dialyxir, "~> 0.4", only: [:dev]}, + {:earmark, "~> 1.0", only: [:dev]}, + {:ex_doc, "~> 0.14", only: [:dev]}, + {:excoveralls, "~> 0.6", only: [:test]}, + {:poison, "~> 1.5 or ~> 2.0 or ~> 3.0"} ] end diff --git a/mix.lock b/mix.lock index 8fa8793..e5915d4 100644 --- a/mix.lock +++ b/mix.lock @@ -1,4 +1,5 @@ -%{"bunt": {:hex, :bunt, "0.1.6", "5d95a6882f73f3b9969fdfd1953798046664e6f77ec4e486e6fafc7caad97c6f", [], []}, +%{ + "bunt": {:hex, :bunt, "0.1.6", "5d95a6882f73f3b9969fdfd1953798046664e6f77ec4e486e6fafc7caad97c6f", [:mix], [], "hexpm"}, "certifi": {:hex, :certifi, "0.7.0", "861a57f3808f7eb0c2d1802afeaae0fa5de813b0df0979153cbafcd853ababaf", [:rebar3], []}, "credo": {:hex, :credo, "0.5.3", "0c405b36e7651245a8ed63c09e2d52c2e2b89b6d02b1570c4d611e0fcbecf4a2", [:mix], [{:bunt, "~> 0.1.6", [hex: :bunt, optional: false]}]}, "dialyxir": {:hex, :dialyxir, "0.4.3", "a4daeebd0107de10d3bbae2ccb6b8905e69544db1ed5fe9148ad27cd4cb2c0cd", [:mix], []}, @@ -7,11 +8,12 @@ "excoveralls": {:hex, :excoveralls, "0.6.0", "bd8565173ad1b97c29329dcbabb9effb56a5fcd1a698fd2097108dfe84b4c4ef", [:mix], [{:exjsx, "~> 3.0", [hex: :exjsx, optional: false]}, {:hackney, ">= 0.12.0", [hex: :hackney, optional: false]}]}, "exjsx": {:hex, :exjsx, "3.2.1", "1bc5bf1e4fd249104178f0885030bcd75a4526f4d2a1e976f4b428d347614f0f", [:mix], [{:jsx, "~> 2.8.0", [hex: :jsx, optional: false]}]}, "hackney": {:hex, :hackney, "1.6.5", "8c025ee397ac94a184b0743c73b33b96465e85f90a02e210e86df6cbafaa5065", [:rebar3], [{:certifi, "0.7.0", [hex: :certifi, optional: false]}, {:idna, "1.2.0", [hex: :idna, optional: false]}, {:metrics, "1.0.1", [hex: :metrics, optional: false]}, {:mimerl, "1.0.2", [hex: :mimerl, optional: false]}, {:ssl_verify_fun, "1.1.1", [hex: :ssl_verify_fun, optional: false]}]}, - "idna": {:hex, :idna, "1.2.0", "ac62ee99da068f43c50dc69acf700e03a62a348360126260e87f2b54eced86b2", [], []}, + "idna": {:hex, :idna, "1.2.0", "ac62ee99da068f43c50dc69acf700e03a62a348360126260e87f2b54eced86b2", [:rebar3], [], "hexpm"}, "jsx": {:hex, :jsx, "2.8.1", "1453b4eb3615acb3e2cd0a105d27e6761e2ed2e501ac0b390f5bbec497669846", [:mix, :rebar3], []}, - "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [], []}, + "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], [], "hexpm"}, "mime": {:hex, :mime, "1.0.1", "05c393850524767d13a53627df71beeebb016205eb43bfbd92d14d24ec7a1b51", [:mix], []}, - "mimerl": {:hex, :mimerl, "1.0.2", "993f9b0e084083405ed8252b99460c4f0563e41729ab42d9074fd5e52439be88", [], []}, + "mimerl": {:hex, :mimerl, "1.0.2", "993f9b0e084083405ed8252b99460c4f0563e41729ab42d9074fd5e52439be88", [:rebar3], [], "hexpm"}, "plug": {:hex, :plug, "1.2.0", "496bef96634a49d7803ab2671482f0c5ce9ce0b7b9bc25bc0ae8e09859dd2004", [:mix], [{:cowboy, "~> 1.0", [hex: :cowboy, optional: true]}, {:mime, "~> 1.0", [hex: :mime, optional: false]}]}, "poison": {:hex, :poison, "3.0.0", "625ebd64d33ae2e65201c2c14d6c85c27cc8b68f2d0dd37828fde9c6920dd131", [:mix], []}, - "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.1", "28a4d65b7f59893bc2c7de786dec1e1555bd742d336043fe644ae956c3497fbe", [:make, :rebar], []}} + "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.1", "28a4d65b7f59893bc2c7de786dec1e1555bd742d336043fe644ae956c3497fbe", [:make, :rebar], []}, +} diff --git a/test/ecto/logger_json_test.exs b/test/ecto/logger_json_test.exs index 7003773..593aa78 100644 --- a/test/ecto/logger_json_test.exs +++ b/test/ecto/logger_json_test.exs @@ -12,86 +12,106 @@ defmodule Ecto.LoggerJSONTest do |> String.replace("\e[36m", "") |> String.replace("\e[22m", "") |> String.replace("\n\e[0m", "") - |> Poison.decode! + |> Poison.decode!() end describe "&log/1" do test "correct output - non nil times and request id" do - Logger.metadata [request_id: "fake_request_id"] + Logger.metadata(request_id: "fake_request_id") entry = %{ query_time: 100_000, decode_time: 10_000, - queue_time: 20_000, - query: "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + queue_time: 20_000, + query: + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" } - log = get_log fn -> Ecto.LoggerJSON.log(entry) end + + log = get_log(fn -> Ecto.LoggerJSON.log(entry) end) assert log["decode_time"] == 0.01 - assert log["duration"] == 0.13 - assert log["log_type"] == "persistence" - assert log["query"] == "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" - assert log["query_time"] == 0.1 - assert log["queue_time"] == 0.02 - assert log["request_id"] == "fake_request_id" + assert log["duration"] == 0.13 + assert log["log_type"] == "persistence" + + assert log["query"] == + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + + assert log["query_time"] == 0.1 + assert log["queue_time"] == 0.02 + assert log["request_id"] == "fake_request_id" end test "correct output - nil times" do entry = %{ - query_time: nil, + query_time: nil, decode_time: nil, - queue_time: nil, - query: "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + queue_time: nil, + query: + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" } - log = get_log fn -> Ecto.LoggerJSON.log(entry) end + + log = get_log(fn -> Ecto.LoggerJSON.log(entry) end) assert log["decode_time"] == 0 - assert log["duration"] == 0 - assert log["log_type"] == "persistence" - assert log["query"] == "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" - assert log["query_time"] == 0 - assert log["queue_time"] == 0 - assert log["request_id"] == nil + assert log["duration"] == 0 + assert log["log_type"] == "persistence" + + assert log["query"] == + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + + assert log["query_time"] == 0 + assert log["queue_time"] == 0 + assert log["request_id"] == nil end end describe "&log/2" do test "correct output - non nil times and request id" do - Logger.metadata [request_id: "fake_request_id"] + Logger.metadata(request_id: "fake_request_id") entry = %{ query_time: 100_000, decode_time: 10_000, - queue_time: 20_000, - query: "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + queue_time: 20_000, + query: + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" } - log = get_log fn -> Ecto.LoggerJSON.log(entry, :info) end + + log = get_log(fn -> Ecto.LoggerJSON.log(entry, :info) end) assert log["decode_time"] == 0.01 - assert log["duration"] == 0.13 - assert log["log_type"] == "persistence" - assert log["query"] == "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" - assert log["query_time"] == 0.1 - assert log["queue_time"] == 0.02 - assert log["request_id"] == "fake_request_id" + assert log["duration"] == 0.13 + assert log["log_type"] == "persistence" + + assert log["query"] == + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + + assert log["query_time"] == 0.1 + assert log["queue_time"] == 0.02 + assert log["request_id"] == "fake_request_id" end test "correct output - nil times" do entry = %{ - query_time: nil, + query_time: nil, decode_time: nil, - queue_time: nil, - query: "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + queue_time: nil, + query: + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" } - log = get_log fn -> Ecto.LoggerJSON.log(entry, :info) end + + log = get_log(fn -> Ecto.LoggerJSON.log(entry, :info) end) assert log["decode_time"] == 0 - assert log["duration"] == 0 - assert log["log_type"] == "persistence" - assert log["query"] == "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" - assert log["query_time"] == 0 - assert log["queue_time"] == 0 - assert log["request_id"] == nil + assert log["duration"] == 0 + assert log["log_type"] == "persistence" + + assert log["query"] == + "SELECT l0.\"id\", l0.\"reaction_id\", l0.\"inserted_at\", l0.\"updated_at\" FROM \"last_processed_reactions\"" + + assert log["query_time"] == 0 + assert log["queue_time"] == 0 + assert log["request_id"] == nil end end end