Forward API v2 logs to api_v2.log; Refactor API logging

apps/block_scout_web/.sobelow-conf

@@ -7,7 +7,6 @@
   format: "compact",
   ignore: ["Config.Headers", "Config.CSWH", "XSS.SendResp", "XSS.Raw"],
   ignore_files: [
-    "apps/block_scout_web/lib/block_scout_web/views/tokens/instance/overview_view.ex",
     "apps/block_scout_web/lib/block_scout_web/smart_contracts_api_v2_router.ex"
   ]
 ]

apps/block_scout_web/config/config.exs

@@ -48,6 +48,22 @@ config :logger, :block_scout_web,
        block_number step count error_count shrunk import_id transaction_id)a,
   metadata_filter: [application: :block_scout_web]
 
+config :logger, :api,
+  # keep synced with `config/config.exs`
+  format: "$dateT$time $metadata[$level] $message\n",
+  metadata:
+    ~w(application fetcher request_id first_block_number last_block_number missing_block_range_count missing_block_count
+       block_number step count error_count shrunk import_id transaction_id)a,
+  metadata_filter: [application: :api]
+
+config :logger, :api_v2,
+  # keep synced with `config/config.exs`
+  format: "$dateT$time $metadata[$level] $message\n",
+  metadata:
+    ~w(application fetcher request_id first_block_number last_block_number missing_block_range_count missing_block_count
+       block_number step count error_count shrunk import_id transaction_id)a,
+  metadata_filter: [application: :api_v2]
+
 config :prometheus, BlockScoutWeb.Prometheus.Instrumenter,
   # override default for Phoenix 1.4 compatibility
   # * `:transport_name` to `:transport`

apps/block_scout_web/config/dev.exs

@@ -57,7 +57,12 @@ config :logger, :block_scout_web,
 config :logger, :api,
   level: :debug,
   path: Path.absname("logs/dev/api.log"),
-  metadata_filter: [fetcher: :api]
+  metadata_filter: [application: :api]
+
+config :logger, :api_v2,
+  level: :debug,
+  path: Path.absname("logs/dev/api_v2.log"),
+  metadata_filter: [application: :api_v2]
 
 # Set a higher stacktrace during development. Avoid configuring such
 # in production as building large stacktraces may be expensive.

apps/block_scout_web/config/prod.exs

@@ -27,7 +27,13 @@ config :logger, :block_scout_web,
 config :logger, :api,
   level: :debug,
   path: Path.absname("logs/prod/api.log"),
-  metadata_filter: [fetcher: :api],
+  metadata_filter: [application: :api],
+  rotate: %{max_bytes: 52_428_800, keep: 19}
+
+config :logger, :api_v2,
+  level: :debug,
+  path: Path.absname("logs/prod/api_v2.log"),
+  metadata_filter: [application: :api_v2],
   rotate: %{max_bytes: 52_428_800, keep: 19}
 
 config :block_scout_web, :captcha_helper, BlockScoutWeb.CaptchaHelper

apps/block_scout_web/lib/block_scout_web/api_router.ex

@@ -20,6 +20,7 @@ defmodule BlockScoutWeb.ApiRouter do
 
   pipeline :api do
     plug(:accepts, ["json"])
+    plug(BlockScoutWeb.Plug.Logger, application: :api)
   end
 
   pipeline :account_api do
@@ -29,9 +30,11 @@ defmodule BlockScoutWeb.ApiRouter do
   end
 
   pipeline :api_v2 do
+    plug(:accepts, ["json"])
     plug(CheckApiV2)
     plug(:fetch_session)
     plug(:protect_from_forgery)
+    plug(BlockScoutWeb.Plug.Logger, application: :api_v2)
   end
 
   alias BlockScoutWeb.Account.Api.V1.{TagsController, UserController}
@@ -93,7 +96,6 @@ defmodule BlockScoutWeb.ApiRouter do
   end
 
   scope "/v2", as: :api_v2 do
-    pipe_through(:api)
     pipe_through(:api_v2)
 
     alias BlockScoutWeb.API.V2

apps/block_scout_web/lib/block_scout_web/controllers/api/api_logger.ex

@@ -4,22 +4,13 @@ defmodule BlockScoutWeb.API.APILogger do
   """
   require Logger
 
-  def log(conn) do
-    endpoint =
-      if conn.query_string do
-        "#{conn.request_path}?#{conn.query_string}"
-      else
-        conn.request_path
-      end
+  @params [application: :api]
 
-    Logger.debug(endpoint,
-      fetcher: :api
-    )
+  def message(text) do
+    Logger.debug(text, @params)
   end
 
-  def message(text) do
-    Logger.debug(text,
-      fetcher: :api
-    )
+  def error(error) do
+    Logger.error(error, @params)
   end
 end

apps/block_scout_web/lib/block_scout_web/controllers/api/rpc/rpc_translator.ex

@@ -35,7 +35,6 @@ defmodule BlockScoutWeb.API.RPC.RPCTranslator do
          true <- action_accessed?(action, write_actions),
          :ok <- AccessHelpers.check_rate_limit(conn),
          {:ok, conn} <- call_controller(conn, controller, action) do
-      APILogger.log(conn)
       conn
     else
       {:error, :no_action} ->
@@ -46,7 +45,9 @@ defmodule BlockScoutWeb.API.RPC.RPCTranslator do
         |> halt()
 
       {:error, error} ->
-        Logger.error(fn -> ["Error while calling RPC action", inspect(error)] end)
+        APILogger.error(fn ->
+          ["Error while calling RPC action", inspect(error, limit: :infinity, printable_limit: :infinity)]
+        end)
 
         conn
         |> put_status(500)

apps/block_scout_web/lib/block_scout_web/controllers/api/v1/decompiled_smart_contract_controller.ex

@@ -1,13 +1,10 @@
 defmodule BlockScoutWeb.API.V1.DecompiledSmartContractController do
   use BlockScoutWeb, :controller
 
-  alias BlockScoutWeb.API.APILogger
   alias Explorer.Chain
   alias Explorer.Chain.Hash.Address
 
   def create(conn, params) do
-    APILogger.log(conn)
-
     if auth_token(conn) == actual_token() do
       with {:ok, hash} <- validate_address_hash(params["address_hash"]),
            :ok <- Chain.check_address_exists(hash),

apps/block_scout_web/lib/block_scout_web/controllers/api/v1/health_controller.ex

@@ -1,13 +1,10 @@
 defmodule BlockScoutWeb.API.V1.HealthController do
   use BlockScoutWeb, :controller
 
-  alias BlockScoutWeb.API.APILogger
   alias Explorer.Chain
   alias Timex.Duration
 
   def health(conn, _) do
-    APILogger.log(conn)
-
     with {:ok, number, timestamp} <- Chain.last_db_block_status(),
          {:ok, cache_number, cache_timestamp} <- Chain.last_cache_block_status() do
       send_resp(conn, :ok, result(number, timestamp, cache_number, cache_timestamp))

apps/block_scout_web/lib/block_scout_web/controllers/api/v1/supply_controller.ex

@@ -1,11 +1,9 @@
 defmodule BlockScoutWeb.API.V1.SupplyController do
   use BlockScoutWeb, :controller
 
-  alias BlockScoutWeb.API.APILogger
   alias Explorer.Chain
 
   def supply(conn, _) do
-    APILogger.log(conn)
     total_supply = Chain.total_supply()
     circulating_supply = Chain.circulating_supply()
 

apps/block_scout_web/lib/block_scout_web/controllers/api/v1/verified_smart_contract_controller.ex

@@ -1,14 +1,11 @@
 defmodule BlockScoutWeb.API.V1.VerifiedSmartContractController do
   use BlockScoutWeb, :controller
 
-  alias BlockScoutWeb.API.APILogger
   alias Explorer.Chain
   alias Explorer.Chain.Hash.Address
   alias Explorer.SmartContract.Solidity.Publisher
 
   def create(conn, params) do
-    APILogger.log(conn)
-
     with {:ok, hash} <- validate_address_hash(params["address_hash"]),
          :ok <- Chain.check_address_exists(hash),
          {:contract, :not_found} <- {:contract, Chain.check_verified_smart_contract_exists(hash)} do

apps/block_scout_web/lib/block_scout_web/endpoint.ex

@@ -43,7 +43,6 @@ defmodule BlockScoutWeb.Endpoint do
   end
 
   plug(Plug.RequestId)
-  plug(Plug.Logger)
 
   plug(
     Plug.Parsers,

apps/block_scout_web/lib/block_scout_web/plug/logger.ex

@@ -0,0 +1,71 @@
+defmodule BlockScoutWeb.Plug.Logger do
+  @moduledoc """
+    Extended version of Plug.Logger from https://github.com/elixir-plug/plug/blob/v1.14.0/lib/plug/logger.ex
+    Now it's possible to put parameters in order to log API v2 requests separately from API and others
+
+    Usage example:
+      `plug(BlockScoutWeb.Plug.Logger, application: :api_v2)`
+  """
+
+  require Logger
+  alias Plug.Conn
+  @behaviour Plug
+
+  @impl true
+  def init(opts) do
+    opts
+  end
+
+  @impl true
+  def call(conn, opts) do
+    level = Keyword.get(opts, :log, :info)
+    application = Keyword.get(opts, :application, :block_scout_web)
+
+    log(application, conn, level, opts)
+
+    start = System.monotonic_time()
+
+    Conn.register_before_send(conn, fn conn ->
+      Logger.log(
+        level,
+        fn ->
+          stop = System.monotonic_time()
+          diff = System.convert_time_unit(stop - start, :native, :microsecond)
+          status = Integer.to_string(conn.status)
+
+          [connection_type(conn), ?\s, status, " in ", formatted_diff(diff)]
+        end,
+        opts
+      )
+
+      conn
+    end)
+  end
+
+  defp log(:api, conn, level, opts) do
+    endpoint =
+      if conn.query_string do
+        "#{conn.request_path}?#{conn.query_string}"
+      else
+        conn.request_path
+      end
+
+    Logger.log(level, endpoint, opts)
+  end
+
+  defp log(_application, conn, level, opts) do
+    Logger.log(
+      level,
+      fn ->
+        [conn.method, ?\s, conn.request_path]
+      end,
+      opts
+    )
+  end
+
+  defp formatted_diff(diff) when diff > 1000, do: [diff |> div(1000) |> Integer.to_string(), "ms"]
+  defp formatted_diff(diff), do: [Integer.to_string(diff), "µs"]
+
+  defp connection_type(%{state: :set_chunked}), do: "Chunked"
+  defp connection_type(_), do: "Sent"
+end

apps/block_scout_web/lib/block_scout_web/router.ex

@@ -18,10 +18,12 @@ defmodule BlockScoutWeb.Router do
     plug(:fetch_flash)
     plug(:protect_from_forgery)
     plug(BlockScoutWeb.CSPHeader)
+    plug(BlockScoutWeb.Plug.Logger, application: :block_scout_web)
   end
 
   pipeline :api do
     plug(:accepts, ["json"])
+    plug(BlockScoutWeb.Plug.Logger, application: :api)
   end
 
   forward("/api", ApiRouter)

apps/block_scout_web/lib/block_scout_web/smart_contracts_api_v2_router.ex

@@ -6,17 +6,14 @@ defmodule BlockScoutWeb.SmartContractsApiV2Router do
   use BlockScoutWeb, :router
   alias BlockScoutWeb.Plug.CheckApiV2
 
-  pipeline :api do
-    plug(:accepts, ["json"])
-  end
-
   pipeline :api_v2_no_forgery_protect do
+    plug(:accepts, ["json"])
     plug(CheckApiV2)
     plug(:fetch_session)
+    plug(BlockScoutWeb.Plug.Logger, application: :api_v2)
   end
 
   scope "/", as: :api_v2 do
-    pipe_through(:api)
     pipe_through(:api_v2_no_forgery_protect)
 
     alias BlockScoutWeb.API.V2

apps/block_scout_web/lib/block_scout_web/web_router.ex

@@ -14,6 +14,7 @@ defmodule BlockScoutWeb.WebRouter do
     plug(:protect_from_forgery)
     plug(BlockScoutWeb.CSPHeader)
     plug(BlockScoutWeb.ChecksumAddress)
+    plug(BlockScoutWeb.Plug.Logger, application: :block_scout_web)
   end
 
   pipeline :account do
@@ -24,6 +25,7 @@ defmodule BlockScoutWeb.WebRouter do
     plug(:protect_from_forgery)
     plug(BlockScoutWeb.CSPHeader)
     plug(BlockScoutWeb.ChecksumAddress)
+    plug(BlockScoutWeb.Plug.Logger, application: :block_scout_web)
   end
 
   if Mix.env() == :dev do

config/config.exs

@@ -36,7 +36,8 @@ config :logger,
     {LoggerFileBackend, :empty_blocks_to_refetch},
     {LoggerFileBackend, :api},
     {LoggerFileBackend, :block_import_timings},
-    {LoggerFileBackend, :account}
+    {LoggerFileBackend, :account},
+    {LoggerFileBackend, :api_v2}
   ]
 
 config :logger, :console,