Merge pull request #1736 from matrix-org/markjh/linearizer_logging

Add more useful logging when we block fetching events

synapse/federation/federation_server.py

@@ -538,7 +538,16 @@ class FederationServer(FederationBase):
                 if get_missing and prevs - seen:
                     # If we're missing stuff, ensure we only fetch stuff one
                     # at a time.
+                    logger.info(
+                        "Acquiring lock for room %r to fetch %d missing events: %r...",
+                        pdu.room_id, len(prevs - seen), list(prevs - seen)[:5],
+                    )
                     with (yield self._room_pdu_linearizer.queue(pdu.room_id)):
+                        logger.info(
+                            "Acquired lock for room %r to fetch %d missing events",
+                            pdu.room_id, len(prevs - seen),
+                        )
+
                         # We recalculate seen, since it may have changed.
                         have_seen = yield self.store.have_events(prevs)
                         seen = set(have_seen.keys())

synapse/util/async.py

@@ -23,6 +23,10 @@ from synapse.util import unwrapFirstError
 
 from contextlib import contextmanager
 
+import logging
+
+logger = logging.getLogger(__name__)
+
 
 @defer.inlineCallbacks
 def sleep(seconds):
@@ -181,6 +185,7 @@ class Linearizer(object):
         self.key_to_defer[key] = new_defer
 
         if current_defer:
+            logger.info("Waiting to acquire linearizer lock for key %r", key)
             with PreserveLoggingContext():
                 yield current_defer