From 0aff09f6c93193c2f3000e1e70e713f615445fe9 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 30 Dec 2016 20:00:44 +0000 Subject: [PATCH] Add more useful logging when we block fetching events --- synapse/federation/federation_server.py | 9 +++++++++ synapse/util/async.py | 5 +++++ 2 files changed, 14 insertions(+) diff --git a/synapse/federation/federation_server.py b/synapse/federation/federation_server.py index 3fa7b2315..6e600fcb8 100644 --- a/synapse/federation/federation_server.py +++ b/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( + "Aquiring 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( + "Aquired 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()) diff --git a/synapse/util/async.py b/synapse/util/async.py index 16ed183d4..1e124163f 100644 --- a/synapse/util/async.py +++ b/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 aquire linearizer lock for key %r", key) with PreserveLoggingContext(): yield current_defer