From 0aff09f6c93193c2f3000e1e70e713f615445fe9 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 30 Dec 2016 20:00:44 +0000 Subject: [PATCH 1/2] 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 3fa7b2315c..6e600fcb89 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 16ed183d4c..1e124163fa 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 From 62ce3034f3096d7a7e920200d2a7cbd5534f655b Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 30 Dec 2016 20:04:44 +0000 Subject: [PATCH 2/2] s/aquire/acquire/g --- synapse/federation/federation_server.py | 4 ++-- synapse/util/async.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/synapse/federation/federation_server.py b/synapse/federation/federation_server.py index 6e600fcb89..f4c60e67e3 100644 --- a/synapse/federation/federation_server.py +++ b/synapse/federation/federation_server.py @@ -539,12 +539,12 @@ class FederationServer(FederationBase): # 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...", + "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( - "Aquired lock for room %r to fetch %d missing events", + "Acquired lock for room %r to fetch %d missing events", pdu.room_id, len(prevs - seen), ) diff --git a/synapse/util/async.py b/synapse/util/async.py index 1e124163fa..4280455cbe 100644 --- a/synapse/util/async.py +++ b/synapse/util/async.py @@ -185,7 +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) + logger.info("Waiting to acquire linearizer lock for key %r", key) with PreserveLoggingContext(): yield current_defer