From 2e6fa25293835a034b88d59e40e55343f9c8cede Mon Sep 17 00:00:00 2001 From: Alexander Koutmos Date: Thu, 2 Apr 2020 04:33:35 -0400 Subject: [PATCH] Added basic formatter and refactored common functions (#35) * Added basic formatter and refactored common functions * Added tests for basic logger and made it the default * Fixed tests and added option to disable callback * Removed unused import * Setting formatter in ecto+plug tests * Trying to fix test race condition * Fixed testing errors * Fixing Elixir 1.6 formatting error --- README.md | 13 +++- lib/logger_json.ex | 15 +++- lib/logger_json/formatter.ex | 3 +- lib/logger_json/formatter_utils.ex | 76 +++++++++++++++++++ lib/logger_json/formatters/basic_logger.ex | 29 +++++++ .../formatters/google_cloud_logger.ex | 73 ++---------------- test/unit/logger_json/ecto_test.exs | 15 +++- test/unit/logger_json/plug_test.exs | 17 +++-- test/unit/logger_json_basic_test.exs | 67 ++++++++++++++++ ...n_test.exs => logger_json_google_test.exs} | 21 +++-- 10 files changed, 239 insertions(+), 90 deletions(-) create mode 100644 lib/logger_json/formatter_utils.ex create mode 100644 lib/logger_json/formatters/basic_logger.ex create mode 100644 test/unit/logger_json_basic_test.exs rename test/unit/{logger_json_test.exs => logger_json_google_test.exs} (94%) diff --git a/README.md b/README.md index 2ad413a..d1b6343 100644 --- a/README.md +++ b/README.md @@ -21,7 +21,15 @@ After adding this back-end you may also be interested in [redirecting otp and sa ## Log Format -By-default, generated JSON is compatible with +LoggerJSON provides two JSON formatters out of the box (see below for implementing your own custom formatter). + +The `LoggerJSON.Formatters.BasicLogger` formatter provides a generic JSON formatted message with no vendor specific entries in the payload. A sample log entry from `LoggerJSON.Formatters.BasicLogger` looks like the following: + +```json + +``` + +The other formatter that comes with LoggerJSON is `LoggerJSON.Formatters.GoogleCloudLogger` and generates JSON that is compatible with the [Google Cloud Logger LogEntry](https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry) format: ```json @@ -29,7 +37,7 @@ By-default, generated JSON is compatible with "log":"hello", "logging.googleapis.com/sourceLocation":{ "file":"/os/logger_json/test/unit/logger_json_test.exs", - "function":"Elixir.LoggerJSONTest.test metadata can be configured/1", + "function":"Elixir.LoggerJSONGoogleTest.test metadata can be configured/1", "line":71 }, "severity":"DEBUG", @@ -40,7 +48,6 @@ By-default, generated JSON is compatible with Log entry in Google Cloud Logger would looks something like this: - ```json { "httpRequest":{ diff --git a/lib/logger_json.ex b/lib/logger_json.ex index 0a40f92..3861d2a 100644 --- a/lib/logger_json.ex +++ b/lib/logger_json.ex @@ -16,7 +16,7 @@ defmodule LoggerJSON do "log":"hello", "logging.googleapis.com/sourceLocation":{ "file":"/os/logger_json/test/unit/logger_json_test.exs", - "function":"Elixir.LoggerJSONTest.test metadata can be configured/1", + "function":"Elixir.LoggerJSONGoogleTest.test metadata can be configured/1", "line":71 }, "severity":"DEBUG", @@ -26,7 +26,8 @@ defmodule LoggerJSON do ``` You can change this structure by implementing `LoggerJSON.Formatter` behaviour and passing module - name to `:formatter` config option. Example module can be found in `LoggerJSON.Formatters.GoogleCloudLogger`. + name to `:formatter` config option. Example implementations can be found in `LoggerJSON.Formatters.GoogleCloudLogger` + and `LoggerJSON.Formatters.BasicLogger`. ```elixir config :logger_json, :backend, @@ -50,7 +51,9 @@ defmodule LoggerJSON do For dynamically configuring the endpoint, such as loading data from environment variables or configuration files, LoggerJSON provides an `:on_init` option that allows developers to set a module, function - and list of arguments that is invoked when the endpoint starts. + and list of arguments that is invoked when the endpoint starts. If you + would like to disable the `:on_init` callback function dynamically, you + can pass in `:disabled` and no callback function will be called. ```elixir config :logger_json, :backend, @@ -121,6 +124,7 @@ defmodule LoggerJSON do def handle_call({:configure, options}, state) do config = configure_merge(get_env(), options) put_env(config) + {:ok, :ok, init(config, state)} end @@ -193,6 +197,9 @@ defmodule LoggerJSON do {:ok, conf} = apply(mod, fun, [config | args]) conf + {:ok, :disabled} -> + config + {:ok, other} -> raise ArgumentError, "invalid :on_init option for :logger_json application. " <> @@ -203,7 +210,7 @@ defmodule LoggerJSON do end json_encoder = Keyword.get(config, :json_encoder, Jason) - formatter = Keyword.get(config, :formatter, LoggerJSON.Formatters.GoogleCloudLogger) + formatter = Keyword.get(config, :formatter, LoggerJSON.Formatters.BasicLogger) level = Keyword.get(config, :level) device = Keyword.get(config, :device, :user) max_buffer = Keyword.get(config, :max_buffer, 32) diff --git a/lib/logger_json/formatter.ex b/lib/logger_json/formatter.ex index 9692da8..62f7f0b 100644 --- a/lib/logger_json/formatter.ex +++ b/lib/logger_json/formatter.ex @@ -2,7 +2,8 @@ defmodule LoggerJSON.Formatter do @moduledoc """ Behaviour that should be implemented by log formatters. - Example implementation can be found in `LoggerJSON.Formatters.GoogleCloudLogger`. + Example implementations can be found in `LoggerJSON.Formatters.GoogleCloudLogger` and + `LoggerJSON.Formatters.BasicLogger`. """ @doc """ diff --git a/lib/logger_json/formatter_utils.ex b/lib/logger_json/formatter_utils.ex new file mode 100644 index 0000000..35f7a5d --- /dev/null +++ b/lib/logger_json/formatter_utils.ex @@ -0,0 +1,76 @@ +defmodule LoggerJSON.FormatterUtils do + @moduledoc """ + This module contains functions that can be used across different + `LoggerJSON.Formatter` implementations to provide common functionality. + """ + + import Jason.Helpers, only: [json_map: 1] + + @doc """ + Format an exception for use within a log entry + """ + def format_process_crash(md) do + if crash_reason = Keyword.get(md, :crash_reason) do + initial_call = Keyword.get(md, :initial_call) + + json_map( + initial_call: format_initial_call(initial_call), + reason: format_crash_reason(crash_reason) + ) + end + end + + @doc """ + RFC3339 UTC "Zulu" format + """ + def format_timestamp({date, time}) do + [format_date(date), ?T, format_time(time), ?Z] + |> IO.iodata_to_binary() + end + + @doc """ + Provide a string output of the MFA log entry + """ + def format_function(nil, function), do: function + def format_function(module, function), do: "#{module}.#{function}" + def format_function(module, function, arity), do: "#{module}.#{function}/#{arity}" + + @doc """ + """ + def maybe_put(map, _key, nil), do: map + def maybe_put(map, key, value), do: Map.put(map, key, value) + + defp format_initial_call(nil), do: nil + defp format_initial_call({module, function, arity}), do: format_function(module, function, arity) + + defp format_crash_reason({:throw, reason}) do + Exception.format(:throw, reason) + end + + defp format_crash_reason({:exit, reason}) do + Exception.format(:exit, reason) + end + + defp format_crash_reason({%{} = exception, stacktrace}) do + Exception.format(:error, exception, stacktrace) + end + + defp format_crash_reason(other) do + inspect(other) + end + + defp format_time({hh, mi, ss, ms}) do + [pad2(hh), ?:, pad2(mi), ?:, pad2(ss), ?., pad3(ms)] + end + + defp format_date({yy, mm, dd}) do + [Integer.to_string(yy), ?-, pad2(mm), ?-, pad2(dd)] + end + + defp pad3(int) when int < 10, do: [?0, ?0, Integer.to_string(int)] + defp pad3(int) when int < 100, do: [?0, Integer.to_string(int)] + defp pad3(int), do: Integer.to_string(int) + + defp pad2(int) when int < 10, do: [?0, Integer.to_string(int)] + defp pad2(int), do: Integer.to_string(int) +end diff --git a/lib/logger_json/formatters/basic_logger.ex b/lib/logger_json/formatters/basic_logger.ex new file mode 100644 index 0000000..f3fc799 --- /dev/null +++ b/lib/logger_json/formatters/basic_logger.ex @@ -0,0 +1,29 @@ +defmodule LoggerJSON.Formatters.BasicLogger do + @moduledoc """ + Basic JSON log formatter with no vender specific formatting + """ + + import Jason.Helpers, only: [json_map: 1] + + alias LoggerJSON.FormatterUtils + + @behaviour LoggerJSON.Formatter + + @processed_metadata_keys ~w[pid file line function module application]a + + @impl true + def format_event(level, msg, ts, md, md_keys) do + json_map( + time: FormatterUtils.format_timestamp(ts), + severity: Atom.to_string(level), + message: IO.iodata_to_binary(msg), + metadata: format_metadata(md, md_keys) + ) + end + + defp format_metadata(md, md_keys) do + md + |> LoggerJSON.take_metadata(md_keys, @processed_metadata_keys) + |> FormatterUtils.maybe_put(:error, FormatterUtils.format_process_crash(md)) + end +end diff --git a/lib/logger_json/formatters/google_cloud_logger.ex b/lib/logger_json/formatters/google_cloud_logger.ex index 0255bc9..929b3a2 100644 --- a/lib/logger_json/formatters/google_cloud_logger.ex +++ b/lib/logger_json/formatters/google_cloud_logger.ex @@ -4,6 +4,8 @@ defmodule LoggerJSON.Formatters.GoogleCloudLogger do """ import Jason.Helpers, only: [json_map: 1] + alias LoggerJSON.FormatterUtils + @behaviour LoggerJSON.Formatter @processed_metadata_keys ~w[pid file line function module application]a @@ -13,7 +15,6 @@ defmodule LoggerJSON.Formatters.GoogleCloudLogger do @severity_levels [ {:debug, "DEBUG"}, {:info, "INFO"}, - {:warning, "WARNING"}, {:warn, "WARNING"}, {:error, "ERROR"} ] @@ -28,7 +29,7 @@ defmodule LoggerJSON.Formatters.GoogleCloudLogger do def format_event(unquote(level), msg, ts, md, md_keys) do Map.merge( %{ - time: format_timestamp(ts), + time: FormatterUtils.format_timestamp(ts), severity: unquote(gcp_level), message: IO.iodata_to_binary(msg) }, @@ -40,7 +41,7 @@ defmodule LoggerJSON.Formatters.GoogleCloudLogger do def format_event(_level, msg, ts, md, md_keys) do Map.merge( %{ - time: format_timestamp(ts), + time: FormatterUtils.format_timestamp(ts), severity: "DEFAULT", message: IO.iodata_to_binary(msg) }, @@ -50,56 +51,17 @@ defmodule LoggerJSON.Formatters.GoogleCloudLogger do defp format_metadata(md, md_keys) do LoggerJSON.take_metadata(md, md_keys, @processed_metadata_keys) - |> maybe_put(:error, format_process_crash(md)) - |> maybe_put(:"logging.googleapis.com/sourceLocation", format_source_location(md)) - |> maybe_put(:"logging.googleapis.com/operation", format_operation(md)) + |> FormatterUtils.maybe_put(:error, FormatterUtils.format_process_crash(md)) + |> FormatterUtils.maybe_put(:"logging.googleapis.com/sourceLocation", format_source_location(md)) + |> FormatterUtils.maybe_put(:"logging.googleapis.com/operation", format_operation(md)) end - defp maybe_put(map, _key, nil), do: map - defp maybe_put(map, key, value), do: Map.put(map, key, value) - defp format_operation(md) do if request_id = Keyword.get(md, :request_id) do json_map(id: request_id) end end - defp format_process_crash(md) do - if crash_reason = Keyword.get(md, :crash_reason) do - initial_call = Keyword.get(md, :initial_call) - - json_map( - initial_call: format_initial_call(initial_call), - reason: format_crash_reason(crash_reason) - ) - end - end - - defp format_initial_call(nil), do: nil - defp format_initial_call({module, function, arity}), do: format_function(module, function, arity) - - defp format_crash_reason({:throw, reason}) do - Exception.format(:throw, reason) - end - - defp format_crash_reason({:exit, reason}) do - Exception.format(:exit, reason) - end - - defp format_crash_reason({%{} = exception, stacktrace}) do - Exception.format(:error, exception, stacktrace) - end - - defp format_crash_reason(other) do - inspect(other) - end - - # RFC3339 UTC "Zulu" format - defp format_timestamp({date, time}) do - [format_date(date), ?T, format_time(time), ?Z] - |> IO.iodata_to_binary() - end - # Description can be found in Google Cloud Logger docs; # https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogEntrySourceLocation defp format_source_location(metadata) do @@ -111,26 +73,7 @@ defmodule LoggerJSON.Formatters.GoogleCloudLogger do json_map( file: file, line: line, - function: format_function(module, function) + function: FormatterUtils.format_function(module, function) ) end - - defp format_function(nil, function), do: function - defp format_function(module, function), do: "#{module}.#{function}" - defp format_function(module, function, arity), do: "#{module}.#{function}/#{arity}" - - defp format_time({hh, mi, ss, ms}) do - [pad2(hh), ?:, pad2(mi), ?:, pad2(ss), ?., pad3(ms)] - end - - defp format_date({yy, mm, dd}) do - [Integer.to_string(yy), ?-, pad2(mm), ?-, pad2(dd)] - end - - defp pad3(int) when int < 10, do: [?0, ?0, Integer.to_string(int)] - defp pad3(int) when int < 100, do: [?0, Integer.to_string(int)] - defp pad3(int), do: Integer.to_string(int) - - defp pad2(int) when int < 10, do: [?0, Integer.to_string(int)] - defp pad2(int), do: Integer.to_string(int) end diff --git a/test/unit/logger_json/ecto_test.exs b/test/unit/logger_json/ecto_test.exs index 488d816..0e24c7c 100644 --- a/test/unit/logger_json/ecto_test.exs +++ b/test/unit/logger_json/ecto_test.exs @@ -1,12 +1,19 @@ defmodule LoggerJSON.EctoTest do - use Logger.Case + use Logger.Case, async: false import ExUnit.CaptureIO require Logger setup do - on_exit(fn -> - :ok = Logger.configure_backend(LoggerJSON, device: :user, level: nil, metadata: [], json_encoder: Jason) - end) + :ok = + Logger.configure_backend( + LoggerJSON, + device: :user, + level: nil, + metadata: [], + json_encoder: Jason, + on_init: :disabled, + formatter: LoggerJSON.Formatters.GoogleCloudLogger + ) diff = :erlang.convert_time_unit(1, :microsecond, :native) diff --git a/test/unit/logger_json/plug_test.exs b/test/unit/logger_json/plug_test.exs index 1dc7c1e..8e30b9f 100644 --- a/test/unit/logger_json/plug_test.exs +++ b/test/unit/logger_json/plug_test.exs @@ -1,5 +1,5 @@ defmodule LoggerJSON.PlugTest do - use Logger.Case + use Logger.Case, async: false use Plug.Test import ExUnit.CaptureIO require Logger @@ -16,11 +16,16 @@ defmodule LoggerJSON.PlugTest do end setup do - on_exit(fn -> - :ok = Logger.configure_backend(LoggerJSON, device: :user, level: nil, metadata: [], json_encoder: Jason) - end) - - Logger.configure_backend(LoggerJSON, device: :standard_error, metadata: :all) + :ok = + Logger.configure_backend( + LoggerJSON, + device: :standard_error, + level: nil, + metadata: :all, + json_encoder: Jason, + on_init: :disabled, + formatter: LoggerJSON.Formatters.GoogleCloudLogger + ) end test "logs request information" do diff --git a/test/unit/logger_json_basic_test.exs b/test/unit/logger_json_basic_test.exs new file mode 100644 index 0000000..2ba87c7 --- /dev/null +++ b/test/unit/logger_json_basic_test.exs @@ -0,0 +1,67 @@ +defmodule LoggerJSONBasicTest do + use Logger.Case, async: false + require Logger + alias LoggerJSON.Formatters.BasicLogger + + setup do + :ok = + Logger.configure_backend( + LoggerJSON, + device: :user, + level: nil, + metadata: [], + json_encoder: Jason, + on_init: :disabled, + formatter: BasicLogger + ) + end + + describe "metadata" do + test "can be configured" do + Logger.configure_backend(LoggerJSON, metadata: [:user_id]) + + assert capture_log(fn -> + Logger.debug("hello") + end) =~ "hello" + + Logger.metadata(user_id: 11) + Logger.metadata(dynamic_metadata: 5) + + log = + fn -> Logger.debug("hello") end + |> capture_log() + |> Jason.decode!() + + assert %{"user_id" => 11} == log["metadata"] + end + + test "can be configured to :all" do + Logger.configure_backend(LoggerJSON, metadata: :all) + + Logger.metadata(user_id: 11) + Logger.metadata(dynamic_metadata: 5) + + log = + fn -> Logger.debug("hello") end + |> capture_log() + |> Jason.decode!() + + assert %{"user_id" => 11, "dynamic_metadata" => 5} = log["metadata"] + end + + test "can be empty" do + Logger.configure_backend(LoggerJSON, metadata: []) + + Logger.metadata(user_id: 11) + Logger.metadata(dynamic_metadata: 5) + + log = + fn -> Logger.debug("hello") end + |> capture_log() + |> Jason.decode!() + + assert %{"message" => "hello"} = log + assert %{} == log["metadata"] + end + end +end diff --git a/test/unit/logger_json_test.exs b/test/unit/logger_json_google_test.exs similarity index 94% rename from test/unit/logger_json_test.exs rename to test/unit/logger_json_google_test.exs index 18d7c65..0c77008 100644 --- a/test/unit/logger_json_test.exs +++ b/test/unit/logger_json_google_test.exs @@ -1,12 +1,20 @@ -defmodule LoggerJSONTest do - use Logger.Case +defmodule LoggerJSONGoogleTest do + use Logger.Case, async: false import ExUnit.CaptureIO require Logger + alias LoggerJSON.Formatters.GoogleCloudLogger setup do - on_exit(fn -> - :ok = Logger.configure_backend(LoggerJSON, device: :user, level: nil, metadata: [], json_encoder: Jason) - end) + :ok = + Logger.configure_backend( + LoggerJSON, + device: :user, + level: nil, + metadata: [], + json_encoder: Jason, + on_init: :disabled, + formatter: GoogleCloudLogger + ) end describe "configure_log_level!/1" do @@ -126,7 +134,6 @@ defmodule LoggerJSONTest do Logger.debug("hello") end) =~ "hello" - Logger.metadata(user_id: 11) Logger.metadata(user_id: 13) log = @@ -175,7 +182,7 @@ defmodule LoggerJSONTest do end test "is triggered" do - Logger.configure_backend(LoggerJSON, metadata: [], on_init: {LoggerJSONTest, :on_init_cb, []}) + Logger.configure_backend(LoggerJSON, metadata: [], on_init: {LoggerJSONGoogleTest, :on_init_cb, []}) Logger.metadata(user_id: 11)