Logging overhaul

config/config.exs

@@ -1,8 +1,17 @@
 import Config
 
 config :logger, :console,
-  metadata: [:request_id, :installation_id, :repo, :issue, :sender],
-  format: "[$level] $message $metadata\n"
+  metadata: [
+    :mfa,
+    :registered_name,
+    :remote_ip,
+    :request_id,
+    :installation_id,
+    :repo,
+    :issue,
+    :sender
+  ],
+  format: "[$level] $metadata | $message\n"
 
 if File.exists?("config/#[Mix.env()].exs") do
   import_config "#{Mix.env()}.exs"

lib/ff_bot/auth/bearer_token_server.ex

@@ -10,6 +10,8 @@ defmodule FFBot.Auth.BearerTokenServer do
 
   alias FFBot.Auth.BearerToken
 
+  require Logger
+
   def start_link(arg) do
     GenServer.start_link(__MODULE__, arg, name: __MODULE__)
   end
@@ -34,6 +36,7 @@ defmodule FFBot.Auth.BearerTokenServer do
 
     # Test for token expiry
     if state.exp - 10 <= time_now do
+      Logger.info("Issuing new bearer token JWT")
       # Create an issuing time in seconds
       issue_time = Integer.floor_div(System.os_time(), 1_000_000_000)
 

lib/ff_bot/auth/installation_token_server.ex

@@ -15,6 +15,8 @@ defmodule FFBot.Auth.InstallationTokenServer do
 
   alias FFBot.{Auth.BearerTokenServer, GitHub}
 
+  require Logger
+
   def start_link(arg) do
     GenServer.start_link(__MODULE__, arg, name: __MODULE__)
   end
@@ -32,6 +34,7 @@ defmodule FFBot.Auth.InstallationTokenServer do
   end
 
   defp generate_token(install_id) do
+    Logger.info("Generating new token", installation_id: install_id)
     # Create a new token by POSTing to the endpoint using the generated bearer token JWT
     {201, token} =
       GitHub.Request.request(
@@ -46,6 +49,8 @@ defmodule FFBot.Auth.InstallationTokenServer do
     # Add the newly generated token to the ETS table
     :ets.insert(:installation_tokens, {install_id, {expires, token["token"]}})
 
+    Logger.debug("New token generated, expires at #{expires}", installation_id: install_id)
+
     # Return the token
     token["token"]
   end
@@ -65,6 +70,10 @@ defmodule FFBot.Auth.InstallationTokenServer do
       [{install_id, {exp, token}}] ->
         # If it expired in the past, create and return a new token
         if exp <= DateTime.utc_now() do
+          Logger.info("Token was expired at lookup time, generating new one",
+            installation_id: install_id
+          )
+
           token = generate_token(install_id)
 
           {:reply, token, state}

lib/ff_bot/dispatch/issue_comment.ex

@@ -11,9 +11,6 @@ defmodule FFBot.Dispatch.IssueComment do
 
   @impl true
   def dispatch(:created, body) do
-    repo = body["repository"]
-    reference = "#{repo["owner"]["login"]}/#{repo["name"]}##{body["issue"]["number"]}"
-
     # If the pull request attribute of the issue is undefined, it's just a regular issue
     if body["issue"]["pull_request"] != nil do
       # If it is defined, the comment is on a PR
@@ -23,11 +20,12 @@ defmodule FFBot.Dispatch.IssueComment do
         _ -> nil
       end
     else
-      Logger.info("Ignoring comment event from non-PR #{reference}")
+      Logger.info("Ignoring comment event from non-PR")
     end
   end
 
   defp command_dispatch(command, body) do
+    Logger.info("Received command: #{command}")
     # Generate a new token for this specific installation
     token = InstallationTokenServer.get_token(body["installation"]["id"])
 
@@ -75,6 +73,8 @@ defmodule FFBot.Dispatch.IssueComment do
     repo = body["repository"]["name"]
     pr_num = body["issue"]["number"]
 
+    Logger.debug("Fetching repo details")
+
     # Fetch the repo details, which we will use to determine the default branch
     # which is used later in the comparison process
     {200, repo_details} =
@@ -84,6 +84,8 @@ defmodule FFBot.Dispatch.IssueComment do
         auth: {:token, token}
       )
 
+    Logger.debug("Fetching PR details")
+
     # Fetch details on the PR from GitHub, which we will later use to help determine
     # if the branches are in a state where a fast-forward merge can be performed
     {200, pr_details} =
@@ -93,6 +95,8 @@ defmodule FFBot.Dispatch.IssueComment do
         auth: {:token, token}
       )
 
+    Logger.debug("Comparing tips of branches")
+
     # Using the information collected in the prior requests, call the GitHub API
     # to determine the commit diff between two branches. This will tell us whether
     # the branches are up to date (and so, whether a fast-forward merge can take place)
@@ -111,6 +115,8 @@ defmodule FFBot.Dispatch.IssueComment do
     # If the status is anything but "ahead" (branch only has new commits and is up to date with default),
     # then we return an error onto the PR
     if comparison_details["status"] != "ahead" do
+      Logger.info("Aborting merge attempt, branch was #{comparison_details["status"]}")
+
       GitHub.Request.comment(
         token,
         owner,
@@ -124,8 +130,11 @@ defmodule FFBot.Dispatch.IssueComment do
           "or merge locally."
       )
     else
+      Logger.info("Triggering merger...")
       # If the PR status was "ahead", we can start the merge process.
-      GitHub.Merger.start_merge(token, repo_details, pr_details)
+      spawn(fn ->
+        GitHub.Merger.start_merge(token, repo_details, pr_details)
+      end)
     end
   end
 end

lib/ff_bot/github/merger.ex

@@ -8,13 +8,29 @@ defmodule FFBot.GitHub.Merger do
   - The changes are pushed to GitHub
   - Temporary files are cleaned up and removed
   """
+
+  require Logger
+
   def start_merge(token, repo, pull_request) do
+    Logger.metadata(
+      repo: "#{repo["owner"]["login"]}/#{repo["name"]}",
+      issue: pull_request["number"]
+    )
+
+    Logger.info("Cloning repository...")
+
     {directory, cloned} = clone_repo(token, repo)
 
+    Logger.info("Cloned to #{directory}, merging branch")
+
     merge_pull_req(cloned, pull_request)
 
+    Logger.info("Pushing changes to remote")
+
     push_changes(cloned)
 
+    Logger.info("Running clearup")
+
     File.rm_rf(directory)
   end
 

lib/ff_bot/github/request.ex

@@ -4,6 +4,8 @@ defmodule FFBot.GitHub.Request do
   """
   alias FFBot.GitHub.Endpoint
 
+  require Logger
+
   # Helper function to build a specified auth header into the valid
   # format to send to the API
   defp build_auth({:jwt, jwt}) do
@@ -26,6 +28,8 @@ defmodule FFBot.GitHub.Request do
         other -> List.to_string(:json.encode(other))
       end
 
+    Logger.debug("Making #{method} request to #{endpoint}")
+
     # Build and send the request with the provided parameters,
     # filling in auth if needed
     request =

lib/ff_bot/hmac.ex

@@ -8,6 +8,8 @@ defmodule FFBot.HMAC do
   """
   import Plug.Conn
 
+  require Logger
+
   @doc false
   @spec init(list()) :: list()
   def init(opts) do
@@ -37,6 +39,7 @@ defmodule FFBot.HMAC do
 
       # Signature provided in header was not base 16
       :error ->
+        Logger.info("Invalid signature provided")
         {nil, false}
     end
   end

lib/ff_bot/server/router.ex

@@ -7,6 +7,9 @@ defmodule FFBot.Server.Router do
   # Assign each request a unique ID for tracing
   plug(Plug.RequestId, assign_as: :plug_request_id)
 
+  # Find remote IP for each connection
+  plug(RemoteIp)
+
   # Log each request and timings to the console
   plug(Plug.Logger)
 

mix.exs

@@ -27,6 +27,7 @@ defmodule FFBot.MixProject do
       {:yaml_elixir, "~> 2.9"},
       {:temp, "~> 0.4"},
       {:git_cli, "~> 0.3"},
+      {:remote_ip, "~> 1.2"},
       {:credo, "~> 1.7", only: [:dev]}
     ]
   end

mix.lock

@@ -3,6 +3,7 @@
   "bunt": {:hex, :bunt, "1.0.0", "081c2c665f086849e6d57900292b3a161727ab40431219529f13c4ddcf3e7a44", [:mix], [], "hexpm", "dc5f86aa08a5f6fa6b8096f0735c4e76d54ae5c9fa2c143e5a1fc7c1cd9bb6b5"},
   "castore": {:hex, :castore, "1.0.7", "b651241514e5f6956028147fe6637f7ac13802537e895a724f90bf3e36ddd1dd", [:mix], [], "hexpm", "da7785a4b0d2a021cd1292a60875a784b6caef71e76bf4917bdee1f390455cf5"},
   "certifi": {:hex, :certifi, "2.12.0", "2d1cca2ec95f59643862af91f001478c9863c2ac9cb6e2f89780bfd8de987329", [:rebar3], [], "hexpm", "ee68d85df22e554040cdb4be100f33873ac6051387baf6a8f6ce82272340ff1c"},
+  "combine": {:hex, :combine, "0.10.0", "eff8224eeb56498a2af13011d142c5e7997a80c8f5b97c499f84c841032e429f", [:mix], [], "hexpm", "1b1dbc1790073076580d0d1d64e42eae2366583e7aecd455d1215b0d16f2451b"},
   "credo": {:hex, :credo, "1.7.7", "771445037228f763f9b2afd612b6aa2fd8e28432a95dbbc60d8e03ce71ba4446", [:mix], [{:bunt, "~> 0.2.1 or ~> 1.0", [hex: :bunt, repo: "hexpm", optional: false]}, {:file_system, "~> 0.2 or ~> 1.0", [hex: :file_system, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}], "hexpm", "8bc87496c9aaacdc3f90f01b7b0582467b69b4bd2441fe8aae3109d843cc2f2e"},
   "file_system": {:hex, :file_system, "1.0.0", "b689cc7dcee665f774de94b5a832e578bd7963c8e637ef940cd44327db7de2cd", [:mix], [], "hexpm", "6752092d66aec5a10e662aefeed8ddb9531d79db0bc145bb8c40325ca1d8536d"},
   "finch": {:hex, :finch, "0.18.0", "944ac7d34d0bd2ac8998f79f7a811b21d87d911e77a786bc5810adb75632ada4", [:mix], [{:castore, "~> 0.1 or ~> 1.0", [hex: :castore, repo: "hexpm", optional: false]}, {:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:mint, "~> 1.3", [hex: :mint, repo: "hexpm", optional: false]}, {:nimble_options, "~> 0.4 or ~> 1.0", [hex: :nimble_options, repo: "hexpm", optional: false]}, {:nimble_pool, "~> 0.2.6 or ~> 1.0", [hex: :nimble_pool, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "69f5045b042e531e53edc2574f15e25e735b522c37e2ddb766e15b979e03aa65"},
@@ -23,6 +24,7 @@
   "parse_trans": {:hex, :parse_trans, "3.4.1", "6e6aa8167cb44cc8f39441d05193be6e6f4e7c2946cb2759f015f8c56b76e5ff", [:rebar3], [], "hexpm", "620a406ce75dada827b82e453c19cf06776be266f5a67cff34e1ef2cbb60e49a"},
   "plug": {:hex, :plug, "1.16.0", "1d07d50cb9bb05097fdf187b31cf087c7297aafc3fed8299aac79c128a707e47", [:mix], [{:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2 or ~> 2.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4.3 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "cbf53aa1f5c4d758a7559c0bd6d59e286c2be0c6a1fac8cc3eee2f638243b93e"},
   "plug_crypto": {:hex, :plug_crypto, "2.1.0", "f44309c2b06d249c27c8d3f65cfe08158ade08418cf540fd4f72d4d6863abb7b", [:mix], [], "hexpm", "131216a4b030b8f8ce0f26038bc4421ae60e4bb95c5cf5395e1421437824c4fa"},
+  "remote_ip": {:hex, :remote_ip, "1.2.0", "fb078e12a44414f4cef5a75963c33008fe169b806572ccd17257c208a7bc760f", [:mix], [{:combine, "~> 0.10", [hex: :combine, repo: "hexpm", optional: false]}, {:plug, "~> 1.14", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm", "2ff91de19c48149ce19ed230a81d377186e4412552a597d6a5137373e5877cb7"},
   "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.7", "354c321cf377240c7b8716899e182ce4890c5938111a1296add3ec74cf1715df", [:make, :mix, :rebar3], [], "hexpm", "fe4c190e8f37401d30167c8c405eda19469f34577987c76dde613e838bbc67f8"},
   "telemetry": {:hex, :telemetry, "1.2.1", "68fdfe8d8f05a8428483a97d7aab2f268aaff24b49e0f599faa091f1d4e7f61c", [:rebar3], [], "hexpm", "dad9ce9d8effc621708f99eac538ef1cbe05d6a874dd741de2e689c47feafed5"},
   "temp": {:hex, :temp, "0.4.7", "2c78482cc2294020a4bc0c95950b907ff386523367d4e63308a252feffbea9f2", [:mix], [], "hexpm", "6af19e7d6a85a427478be1021574d1ae2a1e1b90882586f06bde76c63cd03e0d"},