Add debug logging

synapse/push/bulk_push_rule_evaluator.py

@@ -224,6 +224,7 @@ class RulesForRoom(object):
 
         with (yield self.linearizer.queue(())):
             if state_group and self.state_group == state_group:
+                logger.debug("Using cached rules for %r", self.room_id)
                 defer.returnValue(self.rules_by_user)
 
             ret_rules_by_user = {}
@@ -236,6 +237,10 @@ class RulesForRoom(object):
             else:
                 current_state_ids = context.current_state_ids
 
+            logger.debug(
+                "Looking for member changes in %r %r", state_group, current_state_ids
+            )
+
             # Loop through to see which member events we've seen and have rules
             # for and which we need to fetch
             for key in current_state_ids:
@@ -273,10 +278,16 @@ class RulesForRoom(object):
             if missing_member_event_ids:
                 # If we have some memebr events we haven't seen, look them up
                 # and fetch push rules for them if appropriate.
+                logger.debug("Found new member events %r", missing_member_event_ids)
                 yield self._update_rules_with_member_event_ids(
                     ret_rules_by_user, missing_member_event_ids, state_group
                 )
 
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug(
+                "Returning push rules for %r %r",
+                self.room_id, ret_rules_by_user.keys(),
+            )
         defer.returnValue(ret_rules_by_user)
 
     @defer.inlineCallbacks
@@ -310,11 +321,17 @@ class RulesForRoom(object):
             for row in rows
         }
 
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug("Found members %r: %r", self.room_id, members.values())
+
         interested_in_user_ids = set(
             user_id for user_id, membership in members.itervalues()
             if membership == Membership.JOIN
         )
 
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug("Joined: %r", interested_in_user_ids)
+
         if_users_with_pushers = yield self.store.get_if_users_have_pushers(
             interested_in_user_ids,
             on_invalidate=self.invalidate_all_cb,
@@ -324,10 +341,16 @@ class RulesForRoom(object):
             uid for uid, have_pusher in if_users_with_pushers.iteritems() if have_pusher
         )
 
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug("With pushers: %r", user_ids)
+
         users_with_receipts = yield self.store.get_users_with_read_receipts_in_room(
             self.room_id, on_invalidate=self.invalidate_all_cb,
         )
 
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug("With receipts: %r", users_with_receipts)
+
         # any users with pushers must be ours: they have pushers
         for uid in users_with_receipts:
             if uid in interested_in_user_ids:
@@ -348,6 +371,7 @@ class RulesForRoom(object):
         # as it keeps a reference to self and will stop this instance from being
         # GC'd if it gets dropped from the rules_to_user cache. Instead use
         # `self.invalidate_all_cb`
+        logger.debug("Invalidating RulesForRoom for %r", self.room_id)
         self.sequence += 1
         self.state_group = object()
         self.member_map = {}