Implement compliant centralised logger

Rewrite the existing `Appsignal.Logger` to comply with the specs
in our integration guide, specifically regarding the log levels,
the log message format, logging to a file, and logging to stderr.

Fixes #747, although this commit does not actually make it so the
logger is used. Most logging statements throughout the application
still use Elixir's `Logger`.

See [the integration guide specification][ig] for more information.

[ig]: https://github.com/appsignal/integration-guide/blob/main/build/logging.md

.changesets/add-centralized-logger.md

@@ -0,0 +1,8 @@
+---
+bump: "patch"
+type: "add"
+---
+
+Log messages are now sent through a centralised logger, defaulting to logging
+to the `/tmp/appsignal.log` file.
+To log to standard output instead, set the `log` config property to `"stdout"`.

config/config.exs

@@ -6,7 +6,8 @@ if Mix.env() in [:bench, :test, :test_no_nif] do
   config :appsignal, appsignal_diagnose_report: Appsignal.Diagnose.FakeReport
   config :appsignal, appsignal: Appsignal.FakeAppsignal
   config :appsignal, inet: FakeInet
-  config :appsignal, logger: Appsignal.Test.Logger
+  config :appsignal, io: FakeIO
+  config :appsignal, file: FakeFile
 
   config :appsignal, appsignal_tracer_nif: Appsignal.Test.Nif
   config :appsignal, appsignal_tracer: Appsignal.Test.Tracer

lib/appsignal/config.ex

@@ -156,14 +156,9 @@ defmodule Appsignal.Config do
   """
   @spec debug?() :: boolean
   def debug? do
-    config = Application.get_env(:appsignal, :config, @default_config)
-    log_level = config[:log_level]
+    level = log_level()
 
-    if Enum.member?(["error", "warn", "info", "debug", "trace"], log_level) do
-      log_level == "debug" || log_level == "trace"
-    else
-      !!(config[:debug] || config[:transaction_debug_mode])
-    end
+    level == :debug || level == :trace
   end
 
   def request_headers do
@@ -390,9 +385,43 @@ defmodule Appsignal.Config do
 
   @log_filename "appsignal.log"
 
-  def log_file_path do
+  def log_level do
     config = Application.fetch_env!(:appsignal, :config)
-    do_log_file_path(config[:log_path])
+
+    log_level(config)
+  end
+
+  defp log_level(config) do
+    case config[:log_level] do
+      "trace" -> :trace
+      "debug" -> :debug
+      "info" -> :info
+      "warn" -> :warn
+      "error" -> :error
+      _ -> deprecated_log_level(config)
+    end
+  end
+
+  defp deprecated_log_level(config) do
+    cond do
+      config[:transaction_debug_mode] -> :trace
+      config[:debug] -> :debug
+      true -> :info
+    end
+  end
+
+  def log_file_path do
+    case Application.fetch_env(:appsignal, :"$log_file_path") do
+      {:ok, value} ->
+        value
+
+      :error ->
+        config = Application.fetch_env!(:appsignal, :config)
+        value = do_log_file_path(config[:log_path])
+        Application.put_env(:appsignal, :"$log_file_path", value)
+
+        value
+    end
   end
 
   defp do_log_file_path(nil), do: log_file_path_tmp_location()

lib/appsignal/logger.ex

@@ -1,16 +1,100 @@
 defmodule Appsignal.Logger do
-  require Logger
   require Appsignal.Utils
 
-  @logger Appsignal.Utils.compile_env(:appsignal, :logger, Logger)
+  @io Appsignal.Utils.compile_env(:appsignal, :io, IO)
+  @file_module Appsignal.Utils.compile_env(:appsignal, :file, File)
 
-  @spec debug(any()) :: :ok
-  @doc """
-  Passes the debug message to `Logger.debug/1` if `Appsignal.Config.debug?/0`
-  is `true`.
-  """
-  def debug(log) do
-    Appsignal.Config.debug?() && @logger.debug(log)
-    :ok
+  @log_levels [:trace, :debug, :info, :warn, :error]
+
+  def trace(message) do
+    log(:trace, message, [])
+  end
+
+  def debug(message) do
+    log(:debug, message, [])
+  end
+
+  def info(message) do
+    log(:info, message, [])
+  end
+
+  def warn(message, options \\ []) do
+    log(:warn, message, options)
+  end
+
+  def error(message, options \\ []) do
+    log(:error, message, options)
+  end
+
+  defp log(level, message, options) do
+    threshold = Appsignal.Config.log_level()
+
+    if log_level?(level, threshold) do
+      case {device(), Keyword.get(options, :stderr, false)} do
+        {device, false} ->
+          do_log(device, level, message)
+
+        {:stdio, true} ->
+          do_log(:stderr, level, message)
+
+        {:file, true} ->
+          do_log(:file, level, message)
+          do_log(:stderr, level, message)
+      end
+    end
+  end
+
+  defp device do
+    case Application.fetch_env!(:appsignal, :config)[:log] do
+      "stdout" -> :stdio
+      _ -> :file
+    end
+  end
+
+  defp log_level?(level, threshold) do
+    Enum.find_index(@log_levels, &(&1 == level)) >=
+      Enum.find_index(@log_levels, &(&1 == threshold))
+  end
+
+  defp do_log(device, level, message) do
+    time = NaiveDateTime.from_erl!(:calendar.local_time())
+    pid = System.pid()
+
+    puts(device, format(device, time, pid, level, message))
+  end
+
+  defp puts(:file, content) do
+    @file_module.write(Appsignal.Config.log_file_path(), content <> "\n", [:append, :utf8])
+  end
+
+  defp puts(device, content) do
+    @io.puts(device, content)
+  end
+
+  defp format(device, time, pid, level, message) do
+    time = format_time(time)
+    level = format_level(level)
+
+    case device do
+      :stdio -> "\n[#{time} (process) ##{pid}][appsignal][#{level}] #{message}"
+      :stderr -> "\n[appsignal][#{level}] #{message}"
+      :file -> "[#{time} (process) ##{pid}][#{level}] #{message}"
+    end
+  end
+
+  defp format_level(level) do
+    case level do
+      :trace -> "TRACE"
+      :debug -> "DEBUG"
+      :info -> "INFO"
+      :warn -> "WARNING"
+      :error -> "ERROR"
+    end
+  end
+
+  defp format_time(time) do
+    time
+    |> NaiveDateTime.truncate(:second)
+    |> NaiveDateTime.to_iso8601()
   end
 end

test/appsignal/config_test.exs

@@ -12,6 +12,7 @@ defmodule Appsignal.ConfigTest do
     environment = freeze_environment()
     Application.delete_env(:appsignal, :config)
     Application.delete_env(:appsignal, :config_sources)
+    Application.delete_env(:appsignal, :"$log_file_path")
 
     ExUnit.Callbacks.on_exit(fn ->
       unfreeze_environment(environment)
@@ -147,23 +148,29 @@ defmodule Appsignal.ConfigTest do
     end
   end
 
-  describe "debug?" do
-    test "when debug is turned on" do
-      assert with_config(%{debug: true}, &Config.debug?/0) == true
+  describe "log_level" do
+    test "when log level is set to a known log level" do
+      assert with_config(%{log_level: "warn"}, &Config.log_level/0) == :warn
+    end
+
+    test "when log level is set to an invalid value" do
+      assert with_config(%{log_level: "foobar"}, &Config.log_level/0) == :info
     end
 
-    test "when debug is turned off" do
-      assert with_config(%{debug: false}, &Config.debug?/0) == false
+    test "when log level is not set" do
+      assert with_config(%{}, &Config.log_level/0) == :info
     end
 
-    test "when transaction debug mode is turned on" do
-      assert with_config(%{transaction_debug_mode: true}, &Config.debug?/0) == true
+    test "when log level is not set and debug is set" do
+      assert with_config(%{debug: true}, &Config.log_level/0) == :debug
     end
 
-    test "when transaction debug mode is turned off" do
-      assert with_config(%{transaction_debug_mode: false}, &Config.debug?/0) == false
+    test "when log level is not set and transaction debug mode is set" do
+      assert with_config(%{transaction_debug_mode: true}, &Config.log_level/0) == :trace
     end
+  end
 
+  describe "debug?" do
     test "when log_level is trace" do
       assert with_config(%{log_level: "trace"}, &Config.debug?/0) == true
     end
@@ -172,42 +179,8 @@ defmodule Appsignal.ConfigTest do
       assert with_config(%{log_level: "debug"}, &Config.debug?/0) == true
     end
 
-    test "when log_level is a logging level other than debug or trace" do
-      config = %{log_level: "warn"}
-
-      assert with_config(config, &Config.debug?/0) == false
-
-      # ignores debug and transaction_debug_mode
-      assert with_config(
-               Map.put(config, :debug, true),
-               &Config.debug?/0
-             ) == false
-
-      assert with_config(
-               Map.put(config, :transaction_debug_mode, true),
-               &Config.debug?/0
-             ) == false
-    end
-
-    test "when log_level is not a logging level" do
-      config = %{log_level: "foobar"}
-
-      assert with_config(config, &Config.debug?/0) == false
-
-      # checks debug and transaction_debug_mode
-      assert with_config(
-               Map.put(config, :debug, true),
-               &Config.debug?/0
-             ) == true
-
-      assert with_config(
-               Map.put(config, :transaction_debug_mode, true),
-               &Config.debug?/0
-             ) == true
-    end
-
-    test "with empty config" do
-      assert with_config(%{}, &Config.debug?/0) == false
+    test "when log_level is something other than trace or debug" do
+      assert with_config(%{log_level: "warn"}, &Config.debug?/0) == false
     end
   end
 
@@ -875,6 +848,9 @@ defmodule Appsignal.ConfigTest do
         end)
 
       assert output =~ "Deprecation warning: File names are no longer supported in the 'log_path'"
+
+      # assert warning is emitted only once
+      assert capture_io(:stderr, &Config.log_file_path/0) == ""
     end
 
     test "falls back on /tmp/appsignal.log when user path is not writable" do
@@ -892,6 +868,9 @@ defmodule Appsignal.ConfigTest do
                "appsignal: Unable to log to '#{log_path}' or the " <>
                  "'#{system_tmp_dir}' fallback. " <>
                  "Please check the write permissions for the log directory."
+
+      # assert warning is emitted only once
+      assert capture_io(:stderr, &Config.log_file_path/0) == ""
     end
   end
 

test/appsignal/diagnose/paths_test.exs

@@ -3,6 +3,11 @@ defmodule Mix.Tasks.Appsignal.Diagnose.PathsTest do
   import AppsignalTest.Utils
   alias Appsignal.Diagnose.Paths
 
+  setup do
+    Application.delete_env(:appsignal, :"$log_file_path")
+    :ok
+  end
+
   describe "with file bigger than 2 Mebibytes" do
     setup do
       path = System.tmp_dir()