feat: Add extensive debug logging for better traceability

webhook_server/libs/check_run_handler.py

@@ -63,6 +63,7 @@ async def set_verify_check_success(self) -> None:
 
     async def set_run_tox_check_queued(self) -> None:
         if not self.github_webhook.tox:
+            self.logger.debug(f"{self.log_prefix} tox is not configured, skipping.")
             return
 
         return await self.set_check_run_status(check_run=TOX_STR, status=QUEUED_STR)
@@ -78,6 +79,7 @@ async def set_run_tox_check_success(self, output: dict[str, Any]) -> None:
 
     async def set_run_pre_commit_check_queued(self) -> None:
         if not self.github_webhook.pre_commit:
+            self.logger.debug(f"{self.log_prefix} pre-commit is not configured, skipping.")
             return
 
         return await self.set_check_run_status(check_run=PRE_COMMIT_STR, status=QUEUED_STR)
@@ -105,6 +107,7 @@ async def set_merge_check_failure(self, output: dict[str, Any]) -> None:
 
     async def set_container_build_queued(self) -> None:
         if not self.github_webhook.build_and_push_container:
+            self.logger.debug(f"{self.log_prefix} build_and_push_container is not configured, skipping.")
             return
 
         return await self.set_check_run_status(check_run=BUILD_CONTAINER_STR, status=QUEUED_STR)
@@ -120,6 +123,7 @@ async def set_container_build_failure(self, output: dict[str, Any]) -> None:
 
     async def set_python_module_install_queued(self) -> None:
         if not self.github_webhook.pypi:
+            self.logger.debug(f"{self.log_prefix} pypi is not configured, skipping.")
             return
 
         return await self.set_check_run_status(check_run=PYTHON_MODULE_INSTALL_STR, status=QUEUED_STR)
@@ -183,6 +187,7 @@ async def set_check_run_status(
         msg: str = f"{self.log_prefix} check run {check_run} status: {status or conclusion}"
 
         try:
+            self.logger.debug(f"{self.log_prefix} Set check run status with {kwargs}")
             await asyncio.to_thread(self.github_webhook.repository_by_github_app.create_check_run, **kwargs)
             if conclusion in (SUCCESS_STR, IN_PROGRESS_STR):
                 self.logger.success(msg)  # type: ignore
@@ -221,14 +226,15 @@ async def is_check_run_in_progress(self, check_run: str) -> bool:
         if self.github_webhook.last_commit:
             for run in await asyncio.to_thread(self.github_webhook.last_commit.get_check_runs):
                 if run.name == check_run and run.status == IN_PROGRESS_STR:
+                    self.logger.debug(f"{self.log_prefix} Check run {check_run} is in progress.")
                     return True
         return False
 
     async def required_check_failed_or_no_status(
         self, pull_request: PullRequest, last_commit_check_runs: list[CheckRun], check_runs_in_progress: list[str]
     ) -> str:
-        failed_check_runs = []
-        no_status_check_runs = []
+        failed_check_runs: list[str] = []
+        no_status_check_runs: list[str] = []
 
         for check_run in last_commit_check_runs:
             self.logger.debug(f"{self.log_prefix} Check if {check_run.name} failed or do not have status.")
@@ -237,6 +243,7 @@ async def required_check_failed_or_no_status(
                 or check_run.conclusion == SUCCESS_STR
                 or check_run.name not in await self.all_required_status_checks(pull_request=pull_request)
             ):
+                self.logger.debug(f"{self.log_prefix} {check_run.name} is success or not required, skipping.")
                 continue
 
             if check_run.conclusion is None:
@@ -254,9 +261,11 @@ async def required_check_failed_or_no_status(
                 if failed_check_run not in check_runs_in_progress
             ]
             msg += f"Some check runs failed: {', '.join(exclude_in_progress)}\n"
+        self.logger.debug(f"failed_check_runs: {failed_check_runs}")
 
         if no_status_check_runs:
             msg += f"Some check runs not started: {', '.join(no_status_check_runs)}\n"
+        self.logger.debug(f"no_status_check_runs: {no_status_check_runs}")
 
         return msg
 
@@ -292,7 +301,9 @@ async def get_branch_required_status_checks(self, pull_request: PullRequest) ->
 
         pull_request_branch = await asyncio.to_thread(self.repository.get_branch, pull_request.base.ref)
         branch_protection = await asyncio.to_thread(pull_request_branch.get_protection)
-        return branch_protection.required_status_checks.contexts
+        branch_required_status_checks = branch_protection.required_status_checks.contexts
+        self.logger.debug(f"branch_required_status_checks: {branch_required_status_checks}")
+        return branch_required_status_checks
 
     async def required_check_in_progress(
         self, pull_request: PullRequest, last_commit_check_runs: list[CheckRun]

webhook_server/libs/issue_comment_handler.py

@@ -107,11 +107,20 @@ async def user_commands(
             return
 
         self.logger.info(f"{self.log_prefix} Processing label/user command {command} by user {reviewed_user}")
+        self.logger.debug(f"{self.log_prefix} Command {command} is supported.")
 
         if remove := len(command_and_args) > 1 and _args == "cancel":
             self.logger.debug(f"{self.log_prefix} User requested 'cancel' for command {_command}")
 
-        if _command in (COMMAND_RETEST_STR, COMMAND_ASSIGN_REVIEWER_STR, COMMAND_ADD_ALLOWED_USER_STR) and not _args:
+        if (
+            _command
+            in (
+                COMMAND_RETEST_STR,
+                COMMAND_ASSIGN_REVIEWER_STR,
+                COMMAND_ADD_ALLOWED_USER_STR,
+            )
+            and not _args
+        ):
             missing_command_arg_comment_msg: str = f"{_command} requires an argument"
             error_msg: str = f"{self.log_prefix} {missing_command_arg_comment_msg}"
             self.logger.debug(error_msg)
@@ -121,6 +130,7 @@ async def user_commands(
         await self.create_comment_reaction(
             pull_request=pull_request, issue_comment_id=issue_comment_id, reaction=REACTIONS.ok
         )
+        self.logger.debug(f"{self.log_prefix} Added reaction to comment.")
 
         if _command == COMMAND_ASSIGN_REVIEWER_STR:
             await self._add_reviewer_by_user_comment(pull_request=pull_request, reviewer=_args)
@@ -170,6 +180,9 @@ async def user_commands(
 
         elif _command == HOLD_LABEL_STR:
             if reviewed_user not in self.owners_file_handler.all_pull_request_approvers:
+                self.logger.debug(
+                    f"{self.log_prefix} {reviewed_user} is not an approver, not adding {HOLD_LABEL_STR} label"
+                )
                 await asyncio.to_thread(
                     pull_request.create_issue_comment,
                     f"{reviewed_user} is not part of the approver, only approvers can mark pull request with hold",
@@ -205,8 +218,10 @@ async def create_comment_reaction(self, pull_request: PullRequest, issue_comment
     async def _add_reviewer_by_user_comment(self, pull_request: PullRequest, reviewer: str) -> None:
         reviewer = reviewer.strip("@")
         self.logger.info(f"{self.log_prefix} Adding reviewer {reviewer} by user comment")
+        repo_contributors = list(await asyncio.to_thread(self.repository.get_contributors))
+        self.logger.debug(f"Repo contributors are: {repo_contributors}")
 
-        for contributer in await asyncio.to_thread(self.repository.get_contributors):
+        for contributer in repo_contributors:
             if contributer.login == reviewer:
                 await asyncio.to_thread(pull_request.create_review_request, [reviewer])
                 return
@@ -221,13 +236,17 @@ async def process_cherry_pick_command(
         _target_branches: list[str] = command_args.split()
         _exits_target_branches: set[str] = set()
         _non_exits_target_branches_msg: str = ""
+        self.logger.debug(f"{self.log_prefix} Processing cherry pick for branches {_target_branches}")
 
         for _target_branch in _target_branches:
             try:
                 await asyncio.to_thread(self.repository.get_branch, _target_branch)
                 _exits_target_branches.add(_target_branch)
             except Exception:
                 _non_exits_target_branches_msg += f"Target branch `{_target_branch}` does not exist\n"
+        self.logger.debug(
+            f"{self.log_prefix} Found target branches {_exits_target_branches} and not found {_non_exits_target_branches_msg}"
+        )
 
         if _non_exits_target_branches_msg:
             self.logger.info(f"{self.log_prefix} {_non_exits_target_branches_msg}")
@@ -254,13 +273,16 @@ async def process_cherry_pick_command(
                         reviewed_user=reviewed_user,
                     )
 
-    async def process_retest_command(self, pull_request: PullRequest, command_args: str, reviewed_user: str) -> None:
+    async def process_retest_command(
+        self, pull_request: PullRequest, command_args: str, reviewed_user: str, automerge: bool = False
+    ) -> None:
         if not await self.owners_file_handler.is_user_valid_to_run_commands(
             pull_request=pull_request, reviewed_user=reviewed_user
         ):
             return
 
         _target_tests: list[str] = command_args.split()
+        self.logger.debug(f"{self.log_prefix} Target tests for re-test: {_target_tests}")
         _not_supported_retests: list[str] = []
         _supported_retests: list[str] = []
         _retests_to_func_map: dict[str, Callable] = {
@@ -270,6 +292,7 @@ async def process_retest_command(self, pull_request: PullRequest, command_args:
             PYTHON_MODULE_INSTALL_STR: self.runner_handler.run_install_python_module,
             CONVENTIONAL_TITLE_STR: self.runner_handler.run_conventional_title_check,
         }
+        self.logger.debug(f"Retest map is {_retests_to_func_map}")
 
         if not _target_tests:
             msg = "No test defined to retest"
@@ -288,6 +311,7 @@ async def process_retest_command(self, pull_request: PullRequest, command_args:
 
             else:
                 _supported_retests = self.github_webhook.current_pull_request_supported_retest
+                self.logger.debug(f"{self.log_prefix} running all supported retests: {_supported_retests}")
 
         else:
             for _test in _target_tests:
@@ -296,6 +320,8 @@ async def process_retest_command(self, pull_request: PullRequest, command_args:
 
                 else:
                     _not_supported_retests.append(_test)
+        self.logger.debug(f"Supported retests are {_supported_retests}")
+        self.logger.debug(f"Not supported retests are {_not_supported_retests}")
 
         if _not_supported_retests:
             msg = f"No {' '.join(_not_supported_retests)} configured for this repository"
@@ -314,3 +340,6 @@ async def process_retest_command(self, pull_request: PullRequest, command_args:
             for result in results:
                 if isinstance(result, Exception):
                     self.logger.error(f"{self.log_prefix} Async task failed: {result}")
+
+        if automerge:
+            await self.labels_handler._add_label(pull_request=pull_request, label="automerge")

webhook_server/libs/labels_handler.py

@@ -44,6 +44,7 @@ async def pull_request_labels_names(self, pull_request: PullRequest) -> list[str
         return [lb.name for lb in labels]
 
     async def _remove_label(self, pull_request: PullRequest, label: str) -> bool:
+        self.logger.debug(f"{self.log_prefix} Removing label {label}")
         try:
             if await self.label_exists_in_pull_request(pull_request=pull_request, label=label):
                 self.logger.info(f"{self.log_prefix} Removing label {label}")
@@ -58,6 +59,7 @@ async def _remove_label(self, pull_request: PullRequest, label: str) -> bool:
 
     async def _add_label(self, pull_request: PullRequest, label: str) -> None:
         label = label.strip()
+        self.logger.debug(f"{self.log_prefix} Adding label {label}")
         if len(label) > 49:
             self.logger.debug(f"{label} is too long, not adding.")
             return
@@ -90,6 +92,7 @@ async def _add_label(self, pull_request: PullRequest, label: str) -> None:
         await self.wait_for_label(pull_request=pull_request, label=label, exists=True)
 
     async def wait_for_label(self, pull_request: PullRequest, label: str, exists: bool) -> bool:
+        self.logger.debug(f"{self.log_prefix} waiting for label {label} to {'exists' if exists else 'not exists'}")
         while TimeoutWatch(timeout=30).remaining_time() > 0:
             res = await self.label_exists_in_pull_request(pull_request=pull_request, label=label)
             if res == exists:
@@ -107,6 +110,7 @@ def get_size(self, pull_request: PullRequest) -> str:
         additions = pull_request.additions if pull_request.additions is not None else 0
         deletions = pull_request.deletions if pull_request.deletions is not None else 0
         size = additions + deletions
+        self.logger.debug(f"{self.log_prefix} PR size is {size} (additions: {additions}, deletions: {deletions})")
 
         # Define label thresholds in a more readable way
         threshold_sizes = [20, 50, 100, 300, 500]
@@ -122,6 +126,7 @@ def get_size(self, pull_request: PullRequest) -> str:
     async def add_size_label(self, pull_request: PullRequest) -> None:
         """Add a size label to the pull request based on its additions and deletions."""
         size_label = self.get_size(pull_request=pull_request)
+        self.logger.debug(f"{self.log_prefix} size label is {size_label}")
         if not size_label:
             self.logger.debug(f"{self.log_prefix} Size label not found")
             return
@@ -136,6 +141,7 @@ async def add_size_label(self, pull_request: PullRequest) -> None:
         ]
 
         if exists_size_label:
+            self.logger.debug(f"{self.log_prefix} Found existing size label {exists_size_label}, removing it.")
             await self._remove_label(pull_request=pull_request, label=exists_size_label[0])
 
         await self._add_label(pull_request=pull_request, label=size_label)
@@ -174,6 +180,7 @@ async def manage_reviewed_by_label(
         )
         label_prefix: str = ""
         label_to_remove: str = ""
+        self.logger.debug(f"{self.log_prefix} label_prefix is {label_prefix}, label_to_remove is {label_to_remove}")
 
         if review_state == APPROVE_STR:
             if (
@@ -182,6 +189,10 @@ async def manage_reviewed_by_label(
             ):
                 label_prefix = APPROVED_BY_LABEL_PREFIX
                 label_to_remove = f"{CHANGED_REQUESTED_BY_LABEL_PREFIX}{reviewed_user}"
+                self.logger.debug(
+                    f"{self.log_prefix} User {reviewed_user} is approver, setting label prefix to "
+                    f"{label_prefix} and label to remove to {label_to_remove}"
+                )
 
             else:
                 self.logger.debug(f"{self.log_prefix} {reviewed_user} not in approvers list, will not {action} label.")
@@ -197,23 +208,32 @@ async def manage_reviewed_by_label(
             _remove_label = f"{CHANGED_REQUESTED_BY_LABEL_PREFIX}{reviewed_user}"
             label_prefix = LGTM_BY_LABEL_PREFIX
             label_to_remove = _remove_label
+            self.logger.debug(
+                f"{self.log_prefix} Setting label prefix to {label_prefix} and label to remove to {label_to_remove}"
+            )
 
         elif review_state == "changes_requested":
             label_prefix = CHANGED_REQUESTED_BY_LABEL_PREFIX
             _remove_label = LGTM_BY_LABEL_PREFIX
             label_to_remove = _remove_label
+            self.logger.debug(
+                f"{self.log_prefix} Setting label prefix to {label_prefix} and label to remove to {label_to_remove}"
+            )
 
         elif review_state == "commented":
             label_prefix = COMMENTED_BY_LABEL_PREFIX
+            self.logger.debug(f"{self.log_prefix} Setting label prefix to {label_prefix}")
 
         if label_prefix:
             reviewer_label = f"{label_prefix}{reviewed_user}"
 
             if action == ADD_STR:
+                self.logger.debug(f"{self.log_prefix} Adding reviewer label {reviewer_label}")
                 await self._add_label(pull_request=pull_request, label=reviewer_label)
                 await self._remove_label(pull_request=pull_request, label=label_to_remove)
 
             if action == DELETE_STR:
+                self.logger.debug(f"{self.log_prefix} Removing reviewer label {reviewer_label}")
                 await self._remove_label(pull_request=pull_request, label=reviewer_label)
         else:
             self.logger.warning(