From 5c67bbc1e4bf352a382c6a0404406fdacbfd1cd6 Mon Sep 17 00:00:00 2001 From: Nikita Pozdniakov Date: Sat, 4 Mar 2023 13:01:06 +0300 Subject: [PATCH] Forward API v2 logs to api_v2.log; Refactor API logging --- apps/block_scout_web/.sobelow-conf | 1 - apps/block_scout_web/config/config.exs | 16 +++++ apps/block_scout_web/config/dev.exs | 7 +- apps/block_scout_web/config/prod.exs | 8 ++- .../lib/block_scout_web/api_router.ex | 4 +- .../controllers/api/api_logger.ex | 19 ++--- .../controllers/api/rpc/rpc_translator.ex | 5 +- .../decompiled_smart_contract_controller.ex | 3 - .../controllers/api/v1/health_controller.ex | 3 - .../controllers/api/v1/supply_controller.ex | 2 - .../v1/verified_smart_contract_controller.ex | 3 - .../lib/block_scout_web/endpoint.ex | 1 - .../lib/block_scout_web/plug/logger.ex | 71 +++++++++++++++++++ .../lib/block_scout_web/router.ex | 2 + .../smart_contracts_api_v2_router.ex | 7 +- .../lib/block_scout_web/web_router.ex | 2 + config/config.exs | 3 +- 17 files changed, 119 insertions(+), 38 deletions(-) create mode 100644 apps/block_scout_web/lib/block_scout_web/plug/logger.ex diff --git a/apps/block_scout_web/.sobelow-conf b/apps/block_scout_web/.sobelow-conf index 0efff68dd6..82604d65bf 100644 --- a/apps/block_scout_web/.sobelow-conf +++ b/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" ] ] diff --git a/apps/block_scout_web/config/config.exs b/apps/block_scout_web/config/config.exs index 9b90064043..92540b2fba 100644 --- a/apps/block_scout_web/config/config.exs +++ b/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` diff --git a/apps/block_scout_web/config/dev.exs b/apps/block_scout_web/config/dev.exs index d26e1b28d2..3f2bb8aa70 100644 --- a/apps/block_scout_web/config/dev.exs +++ b/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. diff --git a/apps/block_scout_web/config/prod.exs b/apps/block_scout_web/config/prod.exs index 366b8864af..d94e56e534 100644 --- a/apps/block_scout_web/config/prod.exs +++ b/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 diff --git a/apps/block_scout_web/lib/block_scout_web/api_router.ex b/apps/block_scout_web/lib/block_scout_web/api_router.ex index 7655afb689..192c81492c 100644 --- a/apps/block_scout_web/lib/block_scout_web/api_router.ex +++ b/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 diff --git a/apps/block_scout_web/lib/block_scout_web/controllers/api/api_logger.ex b/apps/block_scout_web/lib/block_scout_web/controllers/api/api_logger.ex index bc2d77d0cb..8a86aee843 100644 --- a/apps/block_scout_web/lib/block_scout_web/controllers/api/api_logger.ex +++ b/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 diff --git a/apps/block_scout_web/lib/block_scout_web/controllers/api/rpc/rpc_translator.ex b/apps/block_scout_web/lib/block_scout_web/controllers/api/rpc/rpc_translator.ex index 5e57d51620..0da4fd9e71 100644 --- a/apps/block_scout_web/lib/block_scout_web/controllers/api/rpc/rpc_translator.ex +++ b/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) diff --git a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/decompiled_smart_contract_controller.ex b/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/decompiled_smart_contract_controller.ex index 653eb14c0a..6b03afe82a 100644 --- a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/decompiled_smart_contract_controller.ex +++ b/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), diff --git a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/health_controller.ex b/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/health_controller.ex index 52352d55d4..923153b87f 100644 --- a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/health_controller.ex +++ b/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)) diff --git a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/supply_controller.ex b/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/supply_controller.ex index 869843a832..6b3cf3edd6 100644 --- a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/supply_controller.ex +++ b/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() diff --git a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/verified_smart_contract_controller.ex b/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/verified_smart_contract_controller.ex index 6794b519b0..3d9614a9d2 100644 --- a/apps/block_scout_web/lib/block_scout_web/controllers/api/v1/verified_smart_contract_controller.ex +++ b/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 diff --git a/apps/block_scout_web/lib/block_scout_web/endpoint.ex b/apps/block_scout_web/lib/block_scout_web/endpoint.ex index aaedee9000..ed33da3db5 100644 --- a/apps/block_scout_web/lib/block_scout_web/endpoint.ex +++ b/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, diff --git a/apps/block_scout_web/lib/block_scout_web/plug/logger.ex b/apps/block_scout_web/lib/block_scout_web/plug/logger.ex new file mode 100644 index 0000000000..883dd95ef3 --- /dev/null +++ b/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 diff --git a/apps/block_scout_web/lib/block_scout_web/router.ex b/apps/block_scout_web/lib/block_scout_web/router.ex index 42a04e05b4..b168e3f866 100644 --- a/apps/block_scout_web/lib/block_scout_web/router.ex +++ b/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) diff --git a/apps/block_scout_web/lib/block_scout_web/smart_contracts_api_v2_router.ex b/apps/block_scout_web/lib/block_scout_web/smart_contracts_api_v2_router.ex index fa4c81662b..88109c871c 100644 --- a/apps/block_scout_web/lib/block_scout_web/smart_contracts_api_v2_router.ex +++ b/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 diff --git a/apps/block_scout_web/lib/block_scout_web/web_router.ex b/apps/block_scout_web/lib/block_scout_web/web_router.ex index d039ae9b12..64315bb9ae 100644 --- a/apps/block_scout_web/lib/block_scout_web/web_router.ex +++ b/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 diff --git a/config/config.exs b/config/config.exs index 8ec1d34312..66c40f086e 100644 --- a/config/config.exs +++ b/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,