Add endpoint url to the block_scout_web logging (#8609)

* Replace :console logger backend with LoggerJSON; Add endpoint url to the block_scout_web logging

* Move logger_json dependency

* Turn json logs only for prod environment

* Disable debug ecto logs for test environment

* Return HTTP method to logs

CHANGELOG.md

@@ -6,6 +6,7 @@
 
 - [#8795](https://github.com/blockscout/blockscout/pull/8795) - Disable catchup indexer by env
 - [#8750](https://github.com/blockscout/blockscout/pull/8750) - Support new eth-bytecode-db request metadata fields
+- [#8609](https://github.com/blockscout/blockscout/pull/8609) - Change logs format to JSON; Add endpoint url to the block_scout_web logging
 
 ### Fixes
 

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

@@ -19,53 +19,40 @@ defmodule BlockScoutWeb.Plug.Logger do
   @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 ->
+      stop = System.monotonic_time()
+      diff = System.convert_time_unit(stop - start, :native, :microsecond)
+      status = Integer.to_string(conn.status)
+
       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)]
+          [connection_type(conn), ?\s, status, " in ", formatted_diff(diff), " on ", conn.method, ?\s, endpoint(conn)]
         end,
-        opts
+        Keyword.merge(
+          [duration: diff, status: status, unit: "microsecond", endpoint: endpoint(conn), method: conn.method],
+          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"
+
+  defp endpoint(conn) do
+    if conn.query_string do
+      "#{conn.request_path}?#{conn.query_string}"
+    else
+      conn.request_path
+    end
+  end
 end

apps/block_scout_web/mix.exs

@@ -132,7 +132,8 @@ defmodule BlockScoutWeb.Mixfile do
       {:ex_json_schema, "~> 0.10.1"},
       {:ueberauth, "~> 0.7"},
       {:ueberauth_auth0, "~> 2.0"},
-      {:bureaucrat, "~> 0.2.9", only: :test}
+      {:bureaucrat, "~> 0.2.9", only: :test},
+      {:logger_json, "~> 5.1"}
     ]
   end
 

apps/ethereum_jsonrpc/mix.exs

@@ -85,7 +85,8 @@ defmodule EthereumJsonrpc.MixProject do
       {:decimal, "~> 2.0"},
       {:decorator, "~> 1.4"},
       {:hackney, "~> 1.18"},
-      {:poolboy, "~> 1.5.2"}
+      {:poolboy, "~> 1.5.2"},
+      {:logger_json, "~> 5.1"}
     ]
   end
 end

apps/explorer/config/test.exs

@@ -12,7 +12,8 @@ config :explorer, Explorer.Repo,
   ownership_timeout: :timer.minutes(7),
   timeout: :timer.seconds(60),
   queue_target: 1000,
-  migration_lock: nil
+  migration_lock: nil,
+  log: false
 
 # Configure API database
 config :explorer, Explorer.Repo.Replica1,
@@ -26,7 +27,8 @@ config :explorer, Explorer.Repo.Replica1,
   enable_caching_implementation_data_of_proxy: true,
   avg_block_time_as_ttl_cached_implementation_data_of_proxy: false,
   fallback_ttl_cached_implementation_data_of_proxy: :timer.seconds(20),
-  implementation_data_fetching_timeout: :timer.seconds(20)
+  implementation_data_fetching_timeout: :timer.seconds(20),
+  log: false
 
 # Configure API database
 config :explorer, Explorer.Repo.Account,
@@ -36,7 +38,8 @@ config :explorer, Explorer.Repo.Account,
   # Default of `5_000` was too low for `BlockFetcher` test
   ownership_timeout: :timer.minutes(1),
   timeout: :timer.seconds(60),
-  queue_target: 1000
+  queue_target: 1000,
+  log: false
 
 for repo <- [Explorer.Repo.PolygonEdge, Explorer.Repo.PolygonZkevm, Explorer.Repo.RSK, Explorer.Repo.Suave] do
   config :explorer, repo,
@@ -46,7 +49,8 @@ for repo <- [Explorer.Repo.PolygonEdge, Explorer.Repo.PolygonZkevm, Explorer.Rep
     # Default of `5_000` was too low for `BlockFetcher` test
     ownership_timeout: :timer.minutes(1),
     timeout: :timer.seconds(60),
-    queue_target: 1000
+    queue_target: 1000,
+    log: false
 end
 
 config :logger, :explorer,

apps/explorer/mix.exs

@@ -117,7 +117,8 @@ defmodule Explorer.Mixfile do
       {:cbor, "~> 1.0"},
       {:cloak_ecto, "~> 1.2.0"},
       {:redix, "~> 1.1"},
-      {:hammer_backend_redis, "~> 6.1"}
+      {:hammer_backend_redis, "~> 6.1"},
+      {:logger_json, "~> 5.1"}
     ]
   end
 

apps/indexer/mix.exs

@@ -55,7 +55,8 @@ defmodule Indexer.MixProject do
       # Tracing
       {:spandex, "~> 3.0"},
       # `:spandex` integration with Datadog
-      {:spandex_datadog, "~> 1.0"}
+      {:spandex_datadog, "~> 1.0"},
+      {:logger_json, "~> 5.1"}
     ]
   end
 

config/config.exs

@@ -38,9 +38,17 @@ config :logger,
     {LoggerFileBackend, :api},
     {LoggerFileBackend, :block_import_timings},
     {LoggerFileBackend, :account},
-    {LoggerFileBackend, :api_v2}
+    {LoggerFileBackend, :api_v2},
+    LoggerJSON
   ]
 
+config :logger_json, :backend,
+  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 duration status unit endpoint method)a,
+  json_encoder: Jason,
+  formatter: LoggerJSON.Formatters.BasicLogger
+
 config :logger, :console,
   # Use same format for all loggers, even though the level should only ever be `:error` for `:error` backend
   format: "$dateT$time $metadata[$level] $message\n",

config/dev.exs

@@ -3,6 +3,8 @@ import Config
 # DO NOT make it `:debug` or all Ecto logs will be shown for indexer
 config :logger, :console, level: :info
 
+config :logger_json, :backend, level: :none
+
 config :logger, :ecto,
   level: :debug,
   path: Path.absname("logs/dev/ecto.log")

config/prod.exs

@@ -2,7 +2,9 @@ import Config
 
 # Do not print debug messages in production
 
-config :logger, :console, level: :info
+config :logger, :console, level: :none
+
+config :logger_json, :backend, level: :info
 
 config :logger, :ecto,
   level: :info,

config/test.exs

@@ -4,6 +4,8 @@ import Config
 
 config :logger, :console, level: :warn
 
+config :logger_json, :backend, level: :none
+
 config :logger, :ecto,
   level: :warn,
   path: Path.absname("logs/test/ecto.log")

mix.lock

@@ -75,6 +75,7 @@
   "jsx": {:hex, :jsx, "2.8.3", "a05252d381885240744d955fbe3cf810504eb2567164824e19303ea59eef62cf", [:mix, :rebar3], [], "hexpm", "fc3499fed7a726995aa659143a248534adc754ebd16ccd437cd93b649a95091f"},
   "junit_formatter": {:hex, :junit_formatter, "3.3.1", "c729befb848f1b9571f317d2fefa648e9d4869befc4b2980daca7c1edc468e40", [:mix], [], "hexpm", "761fc5be4b4c15d8ba91a6dafde0b2c2ae6db9da7b8832a55b5a1deb524da72b"},
   "logger_file_backend": {:hex, :logger_file_backend, "0.0.13", "df07b14970e9ac1f57362985d76e6f24e3e1ab05c248055b7d223976881977c2", [:mix], [], "hexpm", "71a453a7e6e899ae4549fb147b1c6621f4233f8f48f58ca10a64ec67b6c50018"},
+  "logger_json": {:hex, :logger_json, "5.1.2", "7dde5f6dff814aba033f045a3af9408f5459bac72357dc533276b47045371ecf", [:mix], [{:ecto, "~> 2.1 or ~> 3.0", [hex: :ecto, repo: "hexpm", optional: true]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}, {:phoenix, ">= 1.5.0", [hex: :phoenix, repo: "hexpm", optional: true]}, {:plug, "~> 1.0", [hex: :plug, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4.0 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "ed42047e5c57a60d0fa1450aef36bc016d0f9a5e6c0807ebb0c03d8895fb6ebc"},
   "makeup": {:hex, :makeup, "1.1.0", "6b67c8bc2882a6b6a445859952a602afc1a41c2e08379ca057c0f525366fc3ca", [:mix], [{:nimble_parsec, "~> 1.2.2 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "0a45ed501f4a8897f580eabf99a2e5234ea3e75a4373c8a52824f6e873be57a6"},
   "makeup_elixir": {:hex, :makeup_elixir, "0.16.1", "cc9e3ca312f1cfeccc572b37a09980287e243648108384b97ff2b76e505c3555", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "e127a341ad1b209bd80f7bd1620a15693a9908ed780c3b763bccf7d200c767c6"},
   "makeup_erlang": {:hex, :makeup_erlang, "0.1.2", "ad87296a092a46e03b7e9b0be7631ddcf64c790fa68a9ef5323b6cbb36affc72", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "f3f5a1ca93ce6e092d92b6d9c049bcda58a3b617a8d888f8e7231c85630e8108"},