From 2d8b764f27cabb794fcd37230ce37e371e3831d1 Mon Sep 17 00:00:00 2001 From: Joe Banks Date: Sat, 15 Jun 2024 03:22:06 +0100 Subject: [PATCH] Logging overhaul --- config/config.exs | 13 +++++++++++-- lib/ff_bot/auth/bearer_token_server.ex | 3 +++ lib/ff_bot/auth/installation_token_server.ex | 9 +++++++++ lib/ff_bot/dispatch/issue_comment.ex | 19 ++++++++++++++----- lib/ff_bot/github/merger.ex | 16 ++++++++++++++++ lib/ff_bot/github/request.ex | 4 ++++ lib/ff_bot/hmac.ex | 3 +++ lib/ff_bot/server/router.ex | 3 +++ mix.exs | 1 + mix.lock | 2 ++ 10 files changed, 66 insertions(+), 7 deletions(-) diff --git a/config/config.exs b/config/config.exs index 4d1ead1..fbc4965 100644 --- a/config/config.exs +++ b/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" diff --git a/lib/ff_bot/auth/bearer_token_server.ex b/lib/ff_bot/auth/bearer_token_server.ex index c3cfe1b..abe6a0f 100644 --- a/lib/ff_bot/auth/bearer_token_server.ex +++ b/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) diff --git a/lib/ff_bot/auth/installation_token_server.ex b/lib/ff_bot/auth/installation_token_server.ex index 177d5f2..06f0d68 100644 --- a/lib/ff_bot/auth/installation_token_server.ex +++ b/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} diff --git a/lib/ff_bot/dispatch/issue_comment.ex b/lib/ff_bot/dispatch/issue_comment.ex index 5f25806..417bcd9 100644 --- a/lib/ff_bot/dispatch/issue_comment.ex +++ b/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 diff --git a/lib/ff_bot/github/merger.ex b/lib/ff_bot/github/merger.ex index cadb40a..acec516 100644 --- a/lib/ff_bot/github/merger.ex +++ b/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 diff --git a/lib/ff_bot/github/request.ex b/lib/ff_bot/github/request.ex index 63a0f81..49eac09 100644 --- a/lib/ff_bot/github/request.ex +++ b/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 = diff --git a/lib/ff_bot/hmac.ex b/lib/ff_bot/hmac.ex index fb3ec56..19ee8c1 100644 --- a/lib/ff_bot/hmac.ex +++ b/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 diff --git a/lib/ff_bot/server/router.ex b/lib/ff_bot/server/router.ex index 9177c32..b5161ce 100644 --- a/lib/ff_bot/server/router.ex +++ b/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) diff --git a/mix.exs b/mix.exs index 8b96bf1..af768b2 100644 --- a/mix.exs +++ b/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 diff --git a/mix.lock b/mix.lock index 76a0ba6..ba5cb10 100644 --- a/mix.lock +++ b/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"},