From 33a9026cdf19dc13a3492e838f0893755d380981 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 25 Oct 2017 10:26:06 +0100 Subject: [PATCH 1/3] Add logging and fix log contexts for publicRooms --- synapse/handlers/room_list.py | 2 ++ synapse/util/caches/response_cache.py | 3 ++- 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/synapse/handlers/room_list.py b/synapse/handlers/room_list.py index 41e1781df7..ae7c611170 100644 --- a/synapse/handlers/room_list.py +++ b/synapse/handlers/room_list.py @@ -70,6 +70,7 @@ class RoomListHandler(BaseHandler): if search_filter: # We explicitly don't bother caching searches or requests for # appservice specific lists. + logger.info("Bypassing cache as search request.") return self._get_public_room_list( limit, since_token, search_filter, network_tuple=network_tuple, ) @@ -77,6 +78,7 @@ class RoomListHandler(BaseHandler): key = (limit, since_token, network_tuple) result = self.response_cache.get(key) if not result: + logger.info("No cached result, calculating one.") result = self.response_cache.set( key, self._get_public_room_list( diff --git a/synapse/util/caches/response_cache.py b/synapse/util/caches/response_cache.py index 00af539880..df0ae099c8 100644 --- a/synapse/util/caches/response_cache.py +++ b/synapse/util/caches/response_cache.py @@ -13,6 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +from synapse.util import logcontext from synapse.util.async import ObservableDeferred @@ -52,4 +53,4 @@ class ResponseCache(object): return r result.addBoth(remove) - return result.observe() + return logcontext.make_deferred_yieldable(result.observe()) From 2a7e9faeec9af8723b9613fef3b3059b1fe777f5 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 25 Oct 2017 15:21:08 +0100 Subject: [PATCH 2/3] Do logcontexts outside ResponseCache --- synapse/appservice/api.py | 10 +++++++--- synapse/federation/federation_server.py | 8 +++++--- synapse/handlers/room_list.py | 7 +++++-- synapse/handlers/sync.py | 6 +++--- synapse/util/caches/response_cache.py | 3 +-- 5 files changed, 21 insertions(+), 13 deletions(-) diff --git a/synapse/appservice/api.py b/synapse/appservice/api.py index 6893610e71..40c433d7ae 100644 --- a/synapse/appservice/api.py +++ b/synapse/appservice/api.py @@ -18,6 +18,7 @@ from synapse.api.constants import ThirdPartyEntityKind from synapse.api.errors import CodeMessageException from synapse.http.client import SimpleHttpClient from synapse.events.utils import serialize_event +from synapse.util.logcontext import preserve_fn, make_deferred_yieldable from synapse.util.caches.response_cache import ResponseCache from synapse.types import ThirdPartyInstanceID @@ -192,9 +193,12 @@ class ApplicationServiceApi(SimpleHttpClient): defer.returnValue(None) key = (service.id, protocol) - return self.protocol_meta_cache.get(key) or ( - self.protocol_meta_cache.set(key, _get()) - ) + result = self.protocol_meta_cache.get(key) + if not result: + result = self.protocol_meta_cache.set( + key, preserve_fn(_get)() + ) + return make_deferred_yieldable(result) @defer.inlineCallbacks def push_bulk(self, service, events, txn_id=None): diff --git a/synapse/federation/federation_server.py b/synapse/federation/federation_server.py index e15228e70b..a2327f24b6 100644 --- a/synapse/federation/federation_server.py +++ b/synapse/federation/federation_server.py @@ -18,6 +18,7 @@ from .federation_base import FederationBase from .units import Transaction, Edu from synapse.util import async +from synapse.util.logcontext import make_deferred_yieldable, preserve_fn from synapse.util.logutils import log_function from synapse.util.caches.response_cache import ResponseCache from synapse.events import FrozenEvent @@ -253,12 +254,13 @@ class FederationServer(FederationBase): result = self._state_resp_cache.get((room_id, event_id)) if not result: with (yield self._server_linearizer.queue((origin, room_id))): - resp = yield self._state_resp_cache.set( + d = self._state_resp_cache.set( (room_id, event_id), - self._on_context_state_request_compute(room_id, event_id) + preserve_fn(self._on_context_state_request_compute)(room_id, event_id) ) + resp = yield make_deferred_yieldable(d) else: - resp = yield result + resp = yield make_deferred_yieldable(result) defer.returnValue((200, resp)) diff --git a/synapse/handlers/room_list.py b/synapse/handlers/room_list.py index ae7c611170..5a47254b56 100644 --- a/synapse/handlers/room_list.py +++ b/synapse/handlers/room_list.py @@ -20,6 +20,7 @@ from ._base import BaseHandler from synapse.api.constants import ( EventTypes, JoinRules, ) +from synapse.util.logcontext import make_deferred_yieldable, preserve_fn from synapse.util.async import concurrently_execute from synapse.util.caches.descriptors import cachedInlineCallbacks from synapse.util.caches.response_cache import ResponseCache @@ -81,11 +82,13 @@ class RoomListHandler(BaseHandler): logger.info("No cached result, calculating one.") result = self.response_cache.set( key, - self._get_public_room_list( + preserve_fn(self._get_public_room_list)( limit, since_token, network_tuple=network_tuple ) ) - return result + else: + logger.info("Using cached result.") + return make_deferred_yieldable(result) @defer.inlineCallbacks def _get_public_room_list(self, limit=None, since_token=None, diff --git a/synapse/handlers/sync.py b/synapse/handlers/sync.py index 219529936f..b12988f3c9 100644 --- a/synapse/handlers/sync.py +++ b/synapse/handlers/sync.py @@ -15,7 +15,7 @@ from synapse.api.constants import Membership, EventTypes from synapse.util.async import concurrently_execute -from synapse.util.logcontext import LoggingContext +from synapse.util.logcontext import LoggingContext, make_deferred_yieldable, preserve_fn from synapse.util.metrics import Measure, measure_func from synapse.util.caches.response_cache import ResponseCache from synapse.push.clientformat import format_push_rules_for_user @@ -184,11 +184,11 @@ class SyncHandler(object): if not result: result = self.response_cache.set( sync_config.request_key, - self._wait_for_sync_for_user( + preserve_fn(self._wait_for_sync_for_user)( sync_config, since_token, timeout, full_state ) ) - return result + return make_deferred_yieldable(result) @defer.inlineCallbacks def _wait_for_sync_for_user(self, sync_config, since_token, timeout, diff --git a/synapse/util/caches/response_cache.py b/synapse/util/caches/response_cache.py index df0ae099c8..00af539880 100644 --- a/synapse/util/caches/response_cache.py +++ b/synapse/util/caches/response_cache.py @@ -13,7 +13,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -from synapse.util import logcontext from synapse.util.async import ObservableDeferred @@ -53,4 +52,4 @@ class ResponseCache(object): return r result.addBoth(remove) - return logcontext.make_deferred_yieldable(result.observe()) + return result.observe() From 566e21eac80f1bf921da5876a0fa03ecc412d551 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 26 Oct 2017 11:39:54 +0100 Subject: [PATCH 3/3] Update room_list.py --- synapse/handlers/room_list.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/handlers/room_list.py b/synapse/handlers/room_list.py index 5a47254b56..2cf34e51cb 100644 --- a/synapse/handlers/room_list.py +++ b/synapse/handlers/room_list.py @@ -87,7 +87,7 @@ class RoomListHandler(BaseHandler): ) ) else: - logger.info("Using cached result.") + logger.info("Using cached deferred result.") return make_deferred_yieldable(result) @defer.inlineCallbacks