Use logging instead of prints (#736)

Author: Mariatta

Procfile

@@ -1,2 +1,2 @@
 web: python3 -m miss_islington
-worker: celery --app miss_islington.tasks.app worker --concurrency=1
+worker: celery --app miss_islington.tasks.app worker --concurrency=1 --loglevel=INFO

miss_islington/__main__.py

@@ -1,7 +1,6 @@
 import asyncio
+import logging
 import os
-import sys
-import traceback
 
 import aiohttp
 import cachetools
@@ -16,6 +15,9 @@
 
 from . import backport_pr, delete_branch
 
+logging.basicConfig(level=logging.INFO)
+logger = logging.getLogger(__name__)
+
 router = routing.Router(
     backport_pr.router, delete_branch.router
 )
@@ -29,7 +31,10 @@ async def main(request):
 
         secret = os.environ.get("GH_SECRET")
         event = sansio.Event.from_http(request.headers, body, secret=secret)
-        print("GH delivery ID", event.delivery_id, file=sys.stderr)
+        logger.info(
+            "received GitHub webhook",
+            extra={"delivery_id": event.delivery_id, "event": event.event},
+        )
         if event.event == "ping":
             return web.Response(status=200)
         async with aiohttp.ClientSession() as session:
@@ -50,25 +55,32 @@ async def main(request):
             await asyncio.sleep(1)
             await router.dispatch(event, gh)
             try:
-                print(
-                    f"""\
-GH requests remaining: {gh.rate_limit.remaining}/{gh.rate_limit.limit}, \
-reset time: {gh.rate_limit.reset_datetime:%b-%d-%Y %H:%M:%S %Z}, \
-GH delivery ID {event.delivery_id} \
-"""
+                logger.info(
+                    "GitHub rate limit",
+                    extra={
+                        "remaining": gh.rate_limit.remaining,
+                        "limit": gh.rate_limit.limit,
+                        "reset": gh.rate_limit.reset_datetime.isoformat(),
+                        "delivery_id": event.delivery_id,
+                    },
                 )
             except AttributeError:
                 pass
         return web.Response(status=200)
-    except Exception as exc:
-        traceback.print_exc(file=sys.stderr)
+    except Exception:
+        logger.exception("webhook handler crashed")
         return web.Response(status=500)
 
 
 @router.register("installation", action="created")
 async def repo_installation_added(event, gh, *args, **kwargs):
-    # installation_id = event.data["installation"]["id"]
-    print(f"App installed by {event.data['installation']['account']['login']}, installation_id: {event.data['installation']['id']}")
+    logger.info(
+        "app installed",
+        extra={
+            "account": event.data["installation"]["account"]["login"],
+            "installation_id": event.data["installation"]["id"],
+        },
+    )
 
 
 sentry_sdk.init(dsn=os.environ.get("SENTRY_DSN"), integrations=[AioHttpIntegration()])

miss_islington/tasks.py

@@ -44,7 +44,7 @@
 
 @app.task()
 def setup_cpython_repo():
-    print("Setting up CPython repository")  # pragma: nocover
+    logger.info("setting up CPython repository")  # pragma: nocover
     if "cpython" not in os.listdir("."):
         subprocess.check_output(
             f"git clone https://{os.environ.get('GH_AUTH')}:x-oauth-basic@github.com/miss-islington/cpython.git".split()
@@ -59,9 +59,9 @@ def setup_cpython_repo():
         subprocess.check_output(
             f"git remote add upstream https://{os.environ.get('GH_AUTH')}:x-oauth-basic@github.com/python/cpython.git".split()
         )
-        print("Finished setting up CPython Repo")
+        logger.info("finished setting up CPython repository")
     else:
-        print("cpython directory already exists")
+        logger.info("cpython directory already exists")
 
 
 @app.task()
@@ -100,7 +100,16 @@ async def backport_task_asyncio(
             if "cpython" in os.listdir("."):
                 os.chdir("./cpython")
             else:
-                print(f"pwd: {os.getcwd()}, listdir: {os.listdir('.')}")
+                logger.warning(
+                    "cpython directory not found",
+                    extra={
+                        "pwd": os.getcwd(),
+                        "listdir": os.listdir("."),
+                        "branch": branch,
+                        "commit_hash": commit_hash,
+                        "issue_number": issue_number,
+                    },
+                )
 
                 await util.comment_on_pr(
                     gh,
@@ -150,7 +159,14 @@ async def backport_task_asyncio(
                 """,
             )
             await util.assign_pr_to_core_dev(gh, issue_number, merged_by)
-            logger.exception("InvalidRepoException while backporting to %s", branch)
+            logger.exception(
+                "backport failed: invalid repo state",
+                extra={
+                    "branch": branch,
+                    "commit_hash": commit_hash,
+                    "issue_number": issue_number,
+                },
+            )
         except cherry_picker.BranchCheckoutException as bce:
             await util.comment_on_pr(
                 gh,
@@ -166,7 +182,15 @@ async def backport_task_asyncio(
             )
             await util.assign_pr_to_core_dev(gh, issue_number, merged_by)
             bce_state = cp.get_state_and_verify()
-            print(bce_state, bce)
+            logger.exception(
+                "backport failed: branch checkout error",
+                extra={
+                    "branch": branch,
+                    "commit_hash": commit_hash,
+                    "issue_number": issue_number,
+                    "state": bce_state.name,
+                },
+            )
             cp.abort_cherry_pick()
         except cherry_picker.CherryPickException as cpe:
             await util.comment_on_pr(
@@ -182,7 +206,15 @@ async def backport_task_asyncio(
             )
             await util.assign_pr_to_core_dev(gh, issue_number, merged_by)
             cpe_state = cp.get_state_and_verify()
-            print(cpe_state, cpe)
+            logger.exception(
+                "backport failed: cherry-pick conflict",
+                extra={
+                    "branch": branch,
+                    "commit_hash": commit_hash,
+                    "issue_number": issue_number,
+                    "state": cpe_state.name,
+                },
+            )
             cp.abort_cherry_pick()
         except cherry_picker.GitHubException as ghe:
             await util.comment_on_pr(
@@ -199,7 +231,15 @@ async def backport_task_asyncio(
             )
             await util.assign_pr_to_core_dev(gh, issue_number, merged_by)
             ghe_state = cp.get_state_and_verify()
-            print(ghe_state, ghe)
+            logger.exception(
+                "backport failed: github error",
+                extra={
+                    "branch": branch,
+                    "commit_hash": commit_hash,
+                    "issue_number": issue_number,
+                    "state": ghe_state.name,
+                },
+            )
             cp.abort_cherry_pick()
 
 
@@ -220,8 +260,14 @@ async def _delete_branch_task_asyncio(branch_name, pr_url, merged, *, installati
         if "cpython" in os.listdir("."):
             os.chdir("./cpython")
         else:
-            print(f"Cannot delete branch: cpython repo not found. "
-                  f"pwd: {os.getcwd()}, listdir: {os.listdir('.')}")
+            logger.warning(
+                "cannot delete branch: cpython repo not found",
+                extra={
+                    "branch": branch_name,
+                    "pwd": os.getcwd(),
+                    "listdir": os.listdir("."),
+                },
+            )
             return
 
     if merged:
@@ -249,15 +295,18 @@ def _git_delete_branch(branch_name):
             ["git", "push", "origin", "--delete", branch_name],
             stderr=subprocess.STDOUT
         )
-        print(f"Deleted branch {branch_name}")
+        logger.info("deleted branch", extra={"branch": branch_name})
     except subprocess.CalledProcessError as e:
-        print(f"Failed to delete branch {branch_name}: {e.output.decode()}")
+        logger.exception(
+            "failed to delete branch",
+            extra={"branch": branch_name, "output": e.output.decode()},
+        )
         raise
 
 
 class InitRepoStep(bootsteps.StartStopStep):
     def start(self, c):
-        print("Initialize the repository.")
+        logger.info("initializing the repository")
         setup_cpython_repo()
 
 

miss_islington/util.py

@@ -1,6 +1,9 @@
+import logging
 import subprocess
 import textwrap
 
+logger = logging.getLogger(__name__)
+
 
 async def comment_on_pr(gh, issue_number, message):
     """
@@ -10,7 +13,10 @@ async def comment_on_pr(gh, issue_number, message):
     message = textwrap.dedent(message)
     data = {"body": message}
     response = await gh.post(issue_comment_url, data=data)
-    print(f"Commented at {response['html_url']}, message: {message}")
+    logger.info(
+        "commented on PR",
+        extra={"issue_number": issue_number, "url": response["html_url"]},
+    )
     return response