fix(hooks_processor): Lower the log message level (#407)

## 📝 Description
Use json logging formatter when running in production env
Lower the priority of some hot path logs and introduce metrics in their
place

## ✅ Checklist
- [x] I have tested this change
- [ ] This change requires documentation update

Author: hamir-suspect

hooks_processor/config/config.exs

@@ -2,6 +2,8 @@ import Config
 
 config :hooks_processor, environment: config_env()
 
+config :logger, :console, format: "$time $metadata[$level] $message\n"
+
 config :hooks_processor,
   ecto_repos: [HooksProcessor.EctoRepo]
 

hooks_processor/config/runtime.exs

@@ -24,6 +24,10 @@ config :hooks_processor, HooksProcessor.EctoRepo,
 
 config :logger, level: (System.get_env("LOG_LEVEL") || "info") |> String.to_atom()
 
+if config_env() == :prod do
+  config :logger, :default_handler, formatter: LoggerJSON.Formatters.Basic.new()
+end
+
 # We need valid dsn or nil
 sentry_dsn = System.get_env("SENTRY_DSN", "") |> String.trim() |> (&if(&1 != "", do: &1, else: nil)).()
 

hooks_processor/lib/hooks_processor/hooks/processing/bitbucket_worker.ex

@@ -40,7 +40,7 @@ defmodule HooksProcessor.Hooks.Processing.BitbucketWorker do
          requester_id <- get_requester_id(webhook, actor_id, "bitbucket"),
          {:ok, _webhook} <-
            process_webhook(hook_type, webhook, project.repository, requester_id) do
-      "Processing finished successfully." |> graceful_exit(state)
+      :ok |> graceful_exit(state)
     else
       error -> graceful_exit(error, state)
     end
@@ -94,6 +94,9 @@ defmodule HooksProcessor.Hooks.Processing.BitbucketWorker do
   end
 
   defp process_webhook(hook_type, _webhook, _project, _requester_id) do
+    # Increment unsupported hook type metric
+    Watchman.increment({"hooks.processing.bitbucket", ["unsupported_hook"]})
+
     "Unsuported type of the hook: '#{hook_type}'"
   end
 
@@ -109,9 +112,15 @@ defmodule HooksProcessor.Hooks.Processing.BitbucketWorker do
   defp should_build?(repository, hook_data, hook_type) do
     cond do
       hook_type not in repository.run_on ->
+        # Increment skip configuration metric
+        Watchman.increment({"hooks.processing.bitbucket", ["skip", "configuration"]})
+
         {:build, {false, hook_state(hook_type, :skip)}, hook_data}
 
       not whitelisted?(repository.whitelist, hook_data, hook_type) ->
+        # Increment skip configuration metric
+        Watchman.increment({"hooks.processing.bitbucket", ["skip", "whitelist"]})
+
         {:build, {false, hook_state(hook_type, :whitelist)}, hook_data}
 
       true ->
@@ -124,14 +133,28 @@ defmodule HooksProcessor.Hooks.Processing.BitbucketWorker do
   defp hook_state(:TAGS, :skip), do: "skip_tag"
   defp hook_state(:TAGS, :whitelist), do: "whitelist_tag"
 
-  defp graceful_exit(message, state) do
-    message
-    |> LT.info("Hook #{state.id} - bitbucket worker process exits: ")
+  defp graceful_exit(result, state) do
+    case result do
+      :ok ->
+        Watchman.increment({"hooks.processing.bitbucket", ["success"]})
+
+        "Processing finished successfully."
+        |> LT.debug("Hook #{state.id} - bitbucket worker process exits: ")
+
+      error ->
+        Watchman.increment({"hooks.processing.bitbucket", ["error"]})
+
+        error
+        |> LT.error("Hook #{state.id} - bitbucket worker process exits: ")
+    end
 
     {:stop, :normal, state}
   end
 
   defp restart(error, state) do
+    # Increment failure metric
+    Watchman.increment({"hooks.processing.bitbucket", ["restart"]})
+
     error
     |> LT.warn("Hook #{state.id} - bitbucket worker process failiure: ")
 

hooks_processor/mix.exs

@@ -38,6 +38,7 @@ defmodule HooksProcessor.MixProject do
       {:ecto_sql, "~> 3.0"},
       {:postgrex, ">= 0.0.0"},
       {:uuid, "~> 1.1"},
+      {:logger_json, "~> 7.0"},
       {:junit_formatter, "~> 3.1", only: [:test]},
       # head because support for JSON is not yet released
       {:sentry, github: "getsentry/sentry-elixir", ref: "f375551f32f35674f9baab470d0e571466b07055"},

hooks_processor/mix.lock

@@ -23,6 +23,7 @@
   "jason": {:hex, :jason, "1.4.4", "b9226785a9aa77b6857ca22832cffa5d5011a667207eb2a0ad56adb5db443b8a", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "c5eb0cab91f094599f94d55bc63409236a8ec69a21a67814529e8d5f6cc90b3b"},
   "junit_formatter": {:hex, :junit_formatter, "3.4.0", "d0e8db6c34dab6d3c4154c3b46b21540db1109ae709d6cf99ba7e7a2ce4b1ac2", [:mix], [], "hexpm", "bb36e2ae83f1ced6ab931c4ce51dd3dbef1ef61bb4932412e173b0cfa259dacd"},
   "log_tee": {:git, "https://github.com/renderedtext/log-tee.git", "30c69704d583bda8cffb324b8936ffd3680e6ae4", []},
+  "logger_json": {:hex, :logger_json, "7.0.3", "0f202788d743154796bd208e1078d878bb4fccf0adc4ed9c83cba821732d326c", [:mix], [{:decimal, ">= 0.0.0", [hex: :decimal, repo: "hexpm", optional: true]}, {:ecto, "~> 3.11", [hex: :ecto, repo: "hexpm", optional: true]}, {:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: true]}, {:plug, "~> 1.15", [hex: :plug, repo: "hexpm", optional: true]}, {:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "9d1ca7dfe77eb7eac4664edfd6f874168d4707aedbedea09fba8eaa6ed2e2f97"},
   "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], [], "hexpm", "69b09adddc4f74a40716ae54d140f93beb0fb8978d8636eaded0c31b6f099f16"},
   "mime": {:hex, :mime, "2.0.6", "8f18486773d9b15f95f4f4f1e39b710045fa1de891fada4516559967276e4dc2", [:mix], [], "hexpm", "c9945363a6b26d747389aac3643f8e0e09d30499a138ad64fe8fd1d13d9b153e"},
   "mimerl": {:hex, :mimerl, "1.3.0", "d0cd9fc04b9061f82490f6581e0128379830e78535e017f7780f37fea7545726", [:rebar3], [], "hexpm", "a1e15a50d1887217de95f0b9b0793e32853f7c258a5cd227650889b38839fe9d"},