Logger improvements (foundations) (#1556)

* Move the `ImAlive` plug to be before the `Telemetry` plug

* Don't log `mfa` (by default) and `pid`

* Use `x-forwarded-for`, if it exists

* Hook into Phoenix telemetry for logging

This is the recommended approach and means we don't need custom plugs.

config/runtime.exs

@@ -12,6 +12,7 @@ end
 config :nerves_hub,
   app: nerves_hub_app,
   deploy_env: System.get_env("DEPLOY_ENV", to_string(config_env())),
+  log_include_mfa: System.get_env("LOG_INCLUDE_MFA", "false") == "true",
   web_title_suffix: System.get_env("WEB_TITLE_SUFFIX", "NervesHub"),
   from_email: System.get_env("FROM_EMAIL", "no-reply@nerves-hub.org"),
   email_sender: System.get_env("EMAIL_SENDER", "NervesHub"),

lib/nerves_hub/application.ex

@@ -17,6 +17,8 @@ defmodule NervesHub.Application do
         config: %{metadata: [:file, :line]}
       })
 
+    NervesHub.Logger.install()
+
     topologies = Application.get_env(:libcluster, :topologies, [])
 
     children =

lib/nerves_hub/logger.ex

@@ -0,0 +1,75 @@
+defmodule NervesHub.Logger do
+  require Logger
+
+  @doc false
+  def install() do
+    handlers = %{
+      [:phoenix, :endpoint, :stop] => &__MODULE__.phoenix_endpoint_stop/4
+    }
+
+    for {key, fun} <- handlers do
+      :ok = :telemetry.attach({__MODULE__, key}, key, fun, :ok)
+    end
+
+    :ok
+  end
+
+  # Phoenix request logging
+
+  @doc false
+  def phoenix_endpoint_stop(_, %{duration: duration}, %{conn: conn} = metadata, _) do
+    case log_level(metadata[:options][:log], conn) do
+      false ->
+        :ok
+
+      level ->
+        Logger.log(level, fn ->
+          Logfmt.encode(
+            duration: duration(duration),
+            method: conn.method,
+            path: request_path(conn),
+            status: conn.status,
+            remote_ip: formatted_ip(conn)
+          )
+        end)
+    end
+  end
+
+  # Helper functions
+
+  defp duration(duration) do
+    duration = System.convert_time_unit(duration, :native, :microsecond)
+
+    if duration > 1000 do
+      [duration |> div(1000) |> Integer.to_string(), "ms"]
+    else
+      [Integer.to_string(duration), "µs"]
+    end
+    |> Enum.join()
+  end
+
+  defp request_path(%{request_path: request_path, query_string: query_string})
+       when query_string not in ["", nil],
+       do: request_path <> "?" <> query_string
+
+  defp request_path(%{request_path: request_path}), do: request_path
+  defp request_path(_), do: nil
+
+  defp formatted_ip(conn) do
+    case Plug.Conn.get_req_header(conn, "x-forwarded-for") do
+      [ips] ->
+        ips
+        |> String.split(",")
+        |> List.first()
+        |> String.trim()
+
+      _ ->
+        conn.remote_ip
+        |> :inet_parse.ntoa()
+        |> to_string()
+    end
+  end
+
+  defp log_level(nil, _conn), do: :info
+  defp log_level(level, _conn) when is_atom(level), do: level
+end

lib/nerves_hub/logger_formatter.ex

@@ -1,7 +1,17 @@
 defmodule NervesHub.LoggerFormatter do
+  @metadata_ignore_list [:line, :file, :domain, :application, :pid, :mfa]
   @pattern Logger.Formatter.compile("$time [$level] $metadata$message\n")
+
   def format(level, message, timestamp, metadata) do
-    metadata = Keyword.drop(metadata, [:line, :file, :domain, :application])
+    metadata = Keyword.drop(metadata, ignore_list())
     Logger.Formatter.format(@pattern, level, message, timestamp, metadata)
   end
+
+  defp ignore_list() do
+    if Application.get_env(:nerves_hub, :log_include_mfa) do
+      @metadata_ignore_list -- [:mfa]
+    else
+      @metadata_ignore_list
+    end
+  end
 end

lib/nerves_hub_web/device_endpoint.ex

@@ -35,7 +35,5 @@ defmodule NervesHubWeb.DeviceEndpoint do
 
   plug(Sentry.PlugContext)
 
-  plug(NervesHubWeb.Plugs.Logger)
-
   plug(NervesHubWeb.Plugs.DeviceEndpointRedirect)
 end

lib/nerves_hub_web/endpoint.ex

@@ -60,11 +60,10 @@ defmodule NervesHubWeb.Endpoint do
     cookie_key: "request_logger"
   )
 
+  plug(NervesHubWeb.Plugs.ImAlive)
+
   plug(Plug.RequestId)
   plug(Plug.Telemetry, event_prefix: [:phoenix, :endpoint])
-  plug(NervesHubWeb.Plugs.Logger)
-
-  plug(NervesHubWeb.Plugs.ImAlive)
 
   plug(
     Plug.Parsers,