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

Author: akoutmos

README.md

@@ -21,15 +21,23 @@ 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
   {
     "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":{

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)

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 """

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

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

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

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)
 

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