Improve logging (#259)

* Improve logging

* Fix tests

* Fix test coverage

* misc

Author: mfosterw

config/settings/local.py

@@ -76,7 +76,7 @@
     import socket
 
     hostname, _, ips = socket.gethostbyname_ex(socket.gethostname())
-    INTERNAL_IPS += [".".join(ip.split(".")[:-1] + ["1"]) for ip in ips]
+    INTERNAL_IPS += [".".join([*ip.split(".")[:-1], "1"]) for ip in ips]
     with contextlib.suppress(socket.gaierror):
         _, _, ips = socket.gethostbyname_ex("node")  # type: ignore[assignment]
         INTERNAL_IPS.extend(ips)

democrasite/webiscite/constitution.py

@@ -1,9 +1,8 @@
 """This module handles the logic behind the constitution.
 
-This contains methods to read the constitution as a dict, check which files in
-a diff contain constitutional amendments, and automatically update the
-constitution for changes which edit files included in the constitution without
-resulting in constitutional amendments
+This contains functions to read the constitution as json, check which files in a diff
+contain constitutional amendments, and automatically update the constitution for changes
+that moved constitutionally protected sections without editing them
 """
 
 import json

democrasite/webiscite/models.py

@@ -1,9 +1,9 @@
 """Models for the webiscite app"""
 
 import json
+import logging
 from collections.abc import Iterator
 from contextlib import contextmanager
-from logging import getLogger
 from typing import Any
 
 from django.conf import settings
@@ -20,7 +20,7 @@
 
 from .constitution import is_constitutional
 
-logger = getLogger(__name__)
+logger = logging.getLogger(__name__)
 
 
 class ClosedBillVoteError(Exception):
@@ -53,8 +53,7 @@ def create_from_github(self, pr: dict[str, Any]) -> T:
             },
         )
 
-        action = "created" if created else "updated"
-        logger.info("PR %s: Pull request %s", pr["number"], action)
+        pull_request.log("%s", "Created" if created else "Updated")
         return pull_request
 
 
@@ -86,6 +85,10 @@ class PullRequest(TimeStampedModel):
     def __str__(self) -> str:
         return f"PR #{self.number}"
 
+    def log(self, msg, *args, level=logging.INFO):
+        logger.log(level, f"PR #%s: {msg}", self.number, *args)  # noqa: G004
+        # f-string necessary to let string interpolation work in msg
+
     @property
     def diff_link(self) -> str:
         """Return base url of PR by removing ".diff" extension"""
@@ -106,7 +109,7 @@ def close(self) -> "Bill | None":
         try:
             bill: Bill = self.bill_set.get(status=Bill.Status.OPEN)
         except Bill.DoesNotExist:
-            logger.info("PR %s: No open bill found", self.number)
+            self.log("No open bill found")
             return None
         else:
             bill.close()
@@ -141,6 +144,7 @@ def get_queryset(self):
         return (
             super()
             .get_queryset()
+            .select_related("pull_request")
             .annotate(
                 total_votes=models.Count("vote"),
                 yes_percent=models.Case(
@@ -203,7 +207,7 @@ def create_from_github(
             applicable
         """
         with self._create_submit_task() as submit_task:
-            self._bill = self.model(
+            self._bill: Bill = self.model(
                 name=title,
                 description=body,
                 author=author,
@@ -214,10 +218,10 @@ def create_from_github(
             )
             self._bill.full_clean()
             self._bill.save()
-            logger.info("PR %s: Bill %s created", pull_request.number, self._bill.id)
             bill = self._bill
+            bill.log("Created")
 
-        return bill  # noqa: RET504
+        return bill
 
     @contextmanager
     def _create_submit_task(self) -> Iterator[PeriodicTask]:
@@ -255,12 +259,9 @@ def _create_submit_task(self) -> Iterator[PeriodicTask]:
             submit_task.name = f"bill_submit:{self._bill.id}"
             submit_task.args = json.dumps([self._bill.id])
             submit_task.save()
-            logger.info(
-                "PR %s: Scheduled %s",
-                self._bill.pull_request.number,
-                submit_task.name,
-            )
+            self._bill.log("Scheduled %s", submit_task.name)
 
+            # Attribute could be shared between model instances
             del self._bill
 
 
@@ -322,6 +323,10 @@ class Meta:
     def __str__(self) -> str:
         return f"Bill {self.id}: {self.name} ({self.pull_request})"
 
+    def log(self, msg, *args):
+        logger.info(f"Bill %s (#%s): {msg}", self.id, self.pull_request.number, *args)  # noqa: G004
+        # f-string necessary to let string interpolation work in msg
+
     def get_absolute_url(self) -> str:
         """Returns URL to view this Bill instance"""
         return reverse("webiscite:bill-detail", kwargs={"pk": self.id})
@@ -359,39 +364,21 @@ def vote(self, user: User, *, support: bool) -> None:
         if self.status != self.Status.OPEN:
             raise ClosedBillVoteError("Bill is not open for voting")
 
+        supports = "yes" if support else "no"
         try:
             vote: Vote = self.vote_set.get(user=user)
             if vote.support == support:
                 vote.delete()
-                logger.info(
-                    'PR %s: User %s retracted their vote "%s" on bill %s',
-                    self.pull_request.number,
-                    user.username,
-                    "yes" if support else "no",
-                    self.id,
-                )
+                self.log("%s retracted their %s vote", user.username, supports)
 
             else:
                 vote.support = support
                 vote.save(update_fields=["support", "when"])  # Ensure "when" is updated
-                logger.info(
-                    "PR %s: User %s changed their vote on bill %s from %s to %s",
-                    self.pull_request.number,
-                    user.username,
-                    self.id,
-                    not support,
-                    support,
-                )
+                self.log("%s changed their vote to %s", user.username, supports)
 
         except Vote.DoesNotExist:
             self.votes.add(user, through_defaults={"support": support})
-            logger.info(
-                "PR %s: User %s voted %s on bill %s",
-                self.pull_request.number,
-                user.username,
-                "yes" if support else "no",
-                self.id,
-            )
+            self.log("%s voted %s", user.username, supports)
 
     def user_supports(self, user: User) -> bool | None:
         """
@@ -415,21 +402,17 @@ def close(self) -> None:
         """Close the bill and disable its submit task"""
         self.status = self.Status.CLOSED
         self.save()
-        logger.info("Bill %s set to closed", self.id)
+        self.log("Closed")
 
         self._submit_task.enabled = False
         self._submit_task.save()
-        logger.info("Submit task for bill %s disabled", self.id)
+        self.log("Submit task disabled")
 
     def submit(self) -> None:
         """Check if the bill has enough votes to pass and update the status"""
         # Bill was closed before voting period ended
         if self.status != Bill.Status.OPEN:
-            logger.info(
-                "PR %s: bill %s was not open when submitted",
-                self.pull_request.number,
-                self.id,
-            )
+            self.log("Bill was not open when submitted")
             return
 
         self.status = self._check_approval()
@@ -438,11 +421,7 @@ def submit(self) -> None:
     def _check_approval(self) -> "Bill.Status":
         total_votes = self.votes.count()
         if total_votes < settings.WEBISCITE_MINIMUM_QUORUM:
-            logger.info(
-                "PR %s: bill %s rejected due to insufficient votes",
-                self.pull_request.number,
-                self.id,
-            )
+            self.log("Rejected due to insufficient votes")
             return self.Status.FAILED
 
         approval = self.yes_votes.count() / total_votes
@@ -452,18 +431,8 @@ def _check_approval(self) -> "Bill.Status":
             approved = approval > settings.WEBISCITE_NORMAL_MAJORITY
 
         if not approved:
-            logger.info(
-                "PR %s: bill %s rejected with %s%% approval",
-                self.pull_request.number,
-                self.id,
-                approval * 100,
-            )
+            self.log("Rejected with %s%% approval", approval * 100)
             return self.Status.REJECTED
 
-        logger.info(
-            "PR %s: bill %s approved with %s%% approval",
-            self.pull_request.number,
-            self.id,
-            approval,
-        )
+        self.log("Approved with %s%% approval", approval * 100)
         return self.Status.APPROVED

democrasite/webiscite/tasks.py

@@ -16,7 +16,6 @@
 from . import constitution
 from .models import Bill
 
-# TODO (#58): Improve logging
 logger = get_task_logger(__name__)
 
 
@@ -36,19 +35,20 @@ def submit_bill(bill_id: int) -> None:
     bill = Bill.objects.get(pk=bill_id)
     bill.submit()
 
-    repo = Github(auth=Auth.Token(settings.WEBISCITE_GITHUB_TOKEN)).get_repo(
-        settings.WEBISCITE_REPO
-    )
+    github_auth = Auth.Token(settings.WEBISCITE_GITHUB_TOKEN)
+    repo = Github(auth=github_auth).get_repo(settings.WEBISCITE_REPO)
     pull = repo.get_pull(bill.pull_request.number)
 
     if bill.status != Bill.Status.APPROVED:
         pull.edit(state="closed")  # Close failed pull request
         return
 
-    merge = pull.merge(merge_method="squash", sha=bill.pull_request.sha)
-    logger.info(
-        "PR %s: bill %s merged (%s)", bill.pull_request.number, bill.id, merge.merged
-    )
+    merged = pull.merge(merge_method="squash", sha=bill.pull_request.sha)
+    if merged:
+        bill.log("Merged")
+    else:
+        logger.warning("Bill %s failed to merge", bill.id)
+        return
 
     # Automatically update constitution line numbers if necessary
     _update_constitution(bill, repo)
@@ -75,4 +75,4 @@ def _update_constitution(bill: Bill, repo: Repository) -> None:
             content=con_update,
             sha=con_sha,
         )
-        logger.info("PR %s: constitution updated", bill.pull_request.number)
+        bill.log("Constitution updated")

democrasite/webiscite/tests/test_models.py

@@ -21,20 +21,22 @@
 class TestPullRequestManager:
     def test_create_from_github_create(self, caplog):
         pr = GithubPullRequestFactory.create(number=FAKE.random_int())
-        pull_request = PullRequest.objects.create_from_github(pr)
-        assert any(
-            record.message == f"PR {pull_request.number}: Pull request created"
-            for record in caplog.records
-        )
+        assert not PullRequest.objects.filter(title=pr["title"]).exists()
+
+        pull_request: PullRequest = PullRequest.objects.create_from_github(pr)
+
+        assert hasattr(pull_request, "created")
+        assert PullRequest.objects.filter(title=pr["title"]).exists()
 
     def test_create_from_github_update(self, bill: Bill, caplog):
-        # PullRequest is created in the BillFactory
+        # PullRequest is created during creation of bill fixture
         pr = GithubPullRequestFactory.create(bill=bill)
-        pull_request = PullRequest.objects.create_from_github(pr)
-        assert any(
-            record.message == f"PR {pull_request.number}: Pull request updated"
-            for record in caplog.records
-        )
+        assert PullRequest.objects.filter(title=bill.pull_request.title).exists()
+        pr["title"] = "New Title"
+
+        PullRequest.objects.create_from_github(pr)
+
+        assert PullRequest.objects.filter(title="New Title").exists()
 
 
 class TestPullRequest:
@@ -51,14 +53,11 @@ def test_close_no_bill(self, caplog):
         pull_request = PullRequestFactory.create()
         assert pull_request.status == "open"
 
-        pull_request.close()
+        bill = pull_request.close()
 
         pull_request.refresh_from_db()
         assert pull_request.status == "closed"
-        assert any(
-            record.message == f"PR {pull_request.number}: No open bill found"
-            for record in caplog.records
-        )
+        assert bill is None
 
 
 class TestVote:
@@ -133,7 +132,7 @@ def test__create_submit_task(self):
         with (
             pytest.raises(
                 AttributeError,
-                match="self._bill was not saved in the submit task context",
+                match=r"self._bill was not saved in the submit task context",
             ),
             Bill.objects._create_submit_task(),  # noqa: SLF001
         ):

democrasite/webiscite/tests/test_tasks.py

@@ -40,6 +40,23 @@ def test_bill_passed(self, mock_token, mock_repo):
             merge_method="squash", sha=bill.pull_request.sha
         )
 
+    @patch("github.Github.get_repo")
+    @patch("github.Auth.Token", spec=True)
+    def test_bill_merge_failed(self, mock_token, mock_repo):
+        bill = BillFactory.create(constitutional=True)
+        # constitutional so _update_constitution isn't called
+        voters = UserFactory.create_batch(settings.WEBISCITE_MINIMUM_QUORUM)
+        Vote.objects.bulk_create(
+            [Vote(bill=bill, user=voter, support=True) for voter in voters]
+        )
+        mock_repo().get_pull().merge.return_value = None
+
+        submit_bill(bill.id)
+
+        mock_repo().get_pull().merge.assert_called_once_with(
+            merge_method="squash", sha=bill.pull_request.sha
+        )
+
     @patch.object(constitution, "update_constitution")
     @patch("requests.get")
     @patch("github.Repository.Repository")