Introduce logging

aleksis/apps/matrix/models.py

+import logging
 import re
 from typing import Any, Optional, Union
 
@@ -39,15 +40,19 @@ class MatrixProfile(ExtensibleModel):
     @classmethod
     def from_person(cls, person: Person, commit: bool = False) -> Union["MatrixProfile", None]:
         """Get or create a Matrix profile from a person."""
+        logging.debug(f"Build Matrix profile for {person}")
         if hasattr(person, "matrix_profile"):
+            logging.debug(f"Matrix profile already exists for {person}")
             return person.matrix_profile
         if not person.user:
+            logging.warning(f"Person {person} has no user")
             raise ValueError("Person must have a user.")
         if not get_site_preferences()["matrix__homeserver_ids"]:
             return None
         new_profile = MatrixProfile(
             matrix_id=cls.build_matrix_id(person.user.username), person=person
         )
+        logging.debug(f"Created Matrix profile {new_profile} for {person}")
         if commit:
             new_profile.save()
         return new_profile
@@ -91,6 +96,7 @@ class MatrixRoom(ExtensiblePolymorphicModel):
 
         if room.room_id:
             # Existing room, check if still accessible
+            logging.debug(f"Room {room} already exists, checking if accessible")
             r = do_matrix_request("GET", f"directory/list/room/{room.room_id}")
         else:
             # Room does not exist, create it
@@ -102,6 +108,7 @@ class MatrixRoom(ExtensiblePolymorphicModel):
             alias_found = False
             while not alias_found:
                 try:
+                    logging.debug(f"Try to create room {room} with alias {alias}")
                     r = cls._create_room(group.name, alias, profiles_to_invite)
                     alias_found = True
                 except MatrixException as e:
@@ -122,6 +129,8 @@ class MatrixRoom(ExtensiblePolymorphicModel):
                     # Counter not found, add one
                     alias = f"{alias}-2"
 
+            logging.debug(f"Created room {room} with alias {alias}")
+
             room.room_id = r["room_id"]
             room.alias = r["room_alias"]
             room.save()
@@ -197,6 +206,7 @@ class MatrixRoom(ExtensiblePolymorphicModel):
     @classmethod
     def get_profiles_for_group(cls, group: Group) -> QuerySet:
         """Get all profile objects for the members/owners of a group."""
+        logging.debug(f"Get profiles for group {group}")
         existing_profiles = MatrixProfile.objects.filter(
             Q(person__member_of=group) | Q(person__owner_of=group)
         )
@@ -210,6 +220,8 @@ class MatrixRoom(ExtensiblePolymorphicModel):
             new_profile = MatrixProfile.from_person(person)
             if new_profile:
                 profiles_to_create.append(new_profile)
+
+        logging.debug(f"Creating {len(profiles_to_create)} new Matrix profiles")
         MatrixProfile.objects.bulk_create(profiles_to_create)
 
         all_profiles = MatrixProfile.objects.filter(
@@ -229,7 +241,9 @@ class MatrixRoom(ExtensiblePolymorphicModel):
 
         # Invite all users who are not in the room yet
         for profile in all_profiles:
+            logging.debug(f"Check if {profile} is in room {self}")
             if profile.matrix_id not in members:
+                logging.debug(f"{profile} is not in room {self}, invite")
                 # Now invite
                 self._invite(profile)
 
@@ -241,11 +255,14 @@ class MatrixRoom(ExtensiblePolymorphicModel):
             else:
                 power_level = get_site_preferences()["matrix__power_level_for_members"]
 
+            logging.debug(f"Check if {profile} has power level {power_level} in room {self}")
+
             if (
                 profile.matrix_id not in user_levels
                 or user_levels[profile.matrix_id] < power_level
                 or get_site_preferences()["matrix__reduce_power_levels"]
             ):
+                logging.debug(f"{profile} has not power level {power_level} in room {self}, set")
                 user_levels[profile.matrix_id] = power_level
         self._set_power_levels(user_levels)
 
@@ -253,6 +270,7 @@ class MatrixRoom(ExtensiblePolymorphicModel):
         """Sync the space for this room."""
         if self.group.child_groups.all():
             # Do space stuff
+            logging.debug(f"Sync space for {self}")
             space = MatrixSpace.from_group(self.group)
             space.sync()
         return None
@@ -339,13 +357,17 @@ class MatrixSpace(MatrixRoom):
         missing_ids = set(child_ids).difference(set(current_children))
 
         for missing_id in missing_ids:
+            logging.debug(f"Add child room/space {missing_id} to {self}")
             self._add_child(missing_id)
 
     def ensure_children(self):
         """Ensure that all child rooms/spaces exist."""
+        logging.debug(f"Ensure that all child rooms/spaces for {self} exist")
         for group in self.group.child_groups.all().prefetch_related("child_groups"):
+            logging.debug(f"Ensure that room for {group} exists")
             group.provision_in_matrix(sync=True)
             if group.child_groups.all():
+                logging.debug(f"Ensure that space for {group} exists")
                 space = MatrixSpace.from_group(group)
                 space.ensure_children()
                 space.sync_children()

aleksis/apps/matrix/util/matrix.py

+import logging
 import time
 from json import JSONDecodeError
 from typing import Any, Optional
@@ -28,6 +29,7 @@ def get_headers() -> dict[str, str]:
 
 def do_matrix_request(method: str, url: str, body: Optional[dict] = None) -> dict[str, Any]:
     """Do a HTTP request to the Matrix Client Server API."""
+    logging.debug(f"Matrix request: {method} {url} {body}")
     while True:
         res = requests.request(method=method, url=build_url(url), headers=get_headers(), json=body)
 
@@ -41,8 +43,11 @@ def do_matrix_request(method: str, url: str, body: Optional[dict] = None) -> dic
 
         # If rate limit exceeded, wait and retry
         if data.get("errcode", "") == "M_LIMIT_EXCEEDED":
-            time.sleep(data["retry_after_ms"] / 1000)
+            wait_time = data["retry_after_ms"] / 1000
+            logging.debug(f"Rate limit exceeded, waiting {wait_time} seconds")
+            time.sleep(wait_time)
         else:
+            logging.error(f"Matrix request failed: {data}")
             raise MatrixException(data)
 
     return data