From f9b4bb05e05694f3000df2bc5331b1aaa501575c Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 30 Mar 2017 13:22:24 +0100 Subject: Fix the logcontext handling in the cache wrappers (#2077) The cache wrappers had a habit of leaking the logcontext into the reactor while the lookup function was running, and then not restoring it correctly when the lookup function had completed. It's all the fault of `preserve_context_over_{fn,deferred}` which are basically a bit broken. --- synapse/util/caches/descriptors.py | 30 ++++++++++++++---------------- synapse/util/logcontext.py | 23 +++++++++++++++++++++++ 2 files changed, 37 insertions(+), 16 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/caches/descriptors.py b/synapse/util/caches/descriptors.py index 19595df422..5c30ed235d 100644 --- a/synapse/util/caches/descriptors.py +++ b/synapse/util/caches/descriptors.py @@ -15,12 +15,9 @@ import logging from synapse.util.async import ObservableDeferred -from synapse.util import unwrapFirstError +from synapse.util import unwrapFirstError, logcontext from synapse.util.caches.lrucache import LruCache from synapse.util.caches.treecache import TreeCache, iterate_tree_cache_entry -from synapse.util.logcontext import ( - PreserveLoggingContext, preserve_context_over_deferred, preserve_context_over_fn -) from . import DEBUG_CACHES, register_cache @@ -328,11 +325,9 @@ class CacheDescriptor(_CacheDescriptorBase): defer.returnValue(cached_result) observer.addCallback(check_result) - return preserve_context_over_deferred(observer) except KeyError: ret = defer.maybeDeferred( - preserve_context_over_fn, - self.function_to_call, + logcontext.preserve_fn(self.function_to_call), obj, *args, **kwargs ) @@ -342,10 +337,11 @@ class CacheDescriptor(_CacheDescriptorBase): ret.addErrback(onErr) - ret = ObservableDeferred(ret, consumeErrors=True) - cache.set(cache_key, ret, callback=invalidate_callback) + result_d = ObservableDeferred(ret, consumeErrors=True) + cache.set(cache_key, result_d, callback=invalidate_callback) + observer = result_d.observe() - return preserve_context_over_deferred(ret.observe()) + return logcontext.make_deferred_yieldable(observer) wrapped.invalidate = cache.invalidate wrapped.invalidate_all = cache.invalidate_all @@ -362,7 +358,11 @@ class CacheListDescriptor(_CacheDescriptorBase): """Wraps an existing cache to support bulk fetching of keys. Given a list of keys it looks in the cache to find any hits, then passes - the list of missing keys to the wrapped fucntion. + the list of missing keys to the wrapped function. + + Once wrapped, the function returns either a Deferred which resolves to + the list of results, or (if all results were cached), just the list of + results. """ def __init__(self, orig, cached_method_name, list_name, num_args=None, @@ -433,8 +433,7 @@ class CacheListDescriptor(_CacheDescriptorBase): args_to_call[self.list_name] = missing ret_d = defer.maybeDeferred( - preserve_context_over_fn, - self.function_to_call, + logcontext.preserve_fn(self.function_to_call), **args_to_call ) @@ -443,8 +442,7 @@ class CacheListDescriptor(_CacheDescriptorBase): # We need to create deferreds for each arg in the list so that # we can insert the new deferred into the cache. for arg in missing: - with PreserveLoggingContext(): - observer = ret_d.observe() + observer = ret_d.observe() observer.addCallback(lambda r, arg: r.get(arg, None), arg) observer = ObservableDeferred(observer) @@ -471,7 +469,7 @@ class CacheListDescriptor(_CacheDescriptorBase): results.update(res) return results - return preserve_context_over_deferred(defer.gatherResults( + return logcontext.make_deferred_yieldable(defer.gatherResults( cached_defers.values(), consumeErrors=True, ).addCallback(update_results_dict).addErrback( diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index ff67b1d794..857afee7cb 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -310,6 +310,10 @@ def preserve_context_over_fn(fn, *args, **kwargs): def preserve_context_over_deferred(deferred, context=None): """Given a deferred wrap it such that any callbacks added later to it will be invoked with the current context. + + Deprecated: this almost certainly doesn't do want you want, ie make + the deferred follow the synapse logcontext rules: try + ``make_deferred_yieldable`` instead. """ if context is None: context = LoggingContext.current_context() @@ -359,6 +363,25 @@ def preserve_fn(f): return g +@defer.inlineCallbacks +def make_deferred_yieldable(deferred): + """Given a deferred, make it follow the Synapse logcontext rules: + + If the deferred has completed (or is not actually a Deferred), essentially + does nothing (just returns another completed deferred with the + result/failure). + + If the deferred has not yet completed, resets the logcontext before + returning a deferred. Then, when the deferred completes, restores the + current logcontext before running callbacks/errbacks. + + (This is more-or-less the opposite operation to preserve_fn.) + """ + with PreserveLoggingContext(): + r = yield deferred + defer.returnValue(r) + + # modules to ignore in `logcontext_tracer` _to_ignore = [ "synapse.util.logcontext", -- cgit 1.5.1 From 86780a8bc3eac566d2c03a601f84b5ccf5737ceb Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 28 Mar 2017 10:41:08 +0100 Subject: Don't convert to deferreds when not necessary --- synapse/push/push_tools.py | 7 ++----- synapse/util/async.py | 2 +- synapse/util/caches/descriptors.py | 5 ++++- synapse/util/logcontext.py | 3 +++ synapse/visibility.py | 3 ++- 5 files changed, 12 insertions(+), 8 deletions(-) (limited to 'synapse/util') diff --git a/synapse/push/push_tools.py b/synapse/push/push_tools.py index 287df94b4f..6835f54e97 100644 --- a/synapse/push/push_tools.py +++ b/synapse/push/push_tools.py @@ -17,15 +17,12 @@ from twisted.internet import defer from synapse.push.presentable_names import ( calculate_room_name, name_from_member_event ) -from synapse.util.logcontext import preserve_fn, preserve_context_over_deferred @defer.inlineCallbacks def get_badge_count(store, user_id): - invites, joins = yield preserve_context_over_deferred(defer.gatherResults([ - preserve_fn(store.get_invited_rooms_for_user)(user_id), - preserve_fn(store.get_rooms_for_user)(user_id), - ], consumeErrors=True)) + invites = yield store.get_invited_rooms_for_user(user_id) + joins = yield store.get_rooms_for_user(user_id) my_receipts_by_room = yield store.get_receipts_for_user( user_id, "m.read", diff --git a/synapse/util/async.py b/synapse/util/async.py index 35380bf8ed..8495de496a 100644 --- a/synapse/util/async.py +++ b/synapse/util/async.py @@ -101,7 +101,7 @@ class ObservableDeferred(object): return d else: success, res = self._result - return defer.succeed(res) if success else defer.fail(res) + return res if success else defer.fail(res) def observers(self): return self._observers diff --git a/synapse/util/caches/descriptors.py b/synapse/util/caches/descriptors.py index 5c30ed235d..1607978e29 100644 --- a/synapse/util/caches/descriptors.py +++ b/synapse/util/caches/descriptors.py @@ -341,7 +341,10 @@ class CacheDescriptor(_CacheDescriptorBase): cache.set(cache_key, result_d, callback=invalidate_callback) observer = result_d.observe() - return logcontext.make_deferred_yieldable(observer) + if isinstance(observer, defer.Deferred): + return logcontext.make_deferred_yieldable(observer) + else: + return observer wrapped.invalidate = cache.invalidate wrapped.invalidate_all = cache.invalidate_all diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 857afee7cb..183d9cf62f 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -315,6 +315,9 @@ def preserve_context_over_deferred(deferred, context=None): the deferred follow the synapse logcontext rules: try ``make_deferred_yieldable`` instead. """ + if not isinstance(deferred, defer.Deferred): + return deferred + if context is None: context = LoggingContext.current_context() d = _PreservingContextDeferred(context) diff --git a/synapse/visibility.py b/synapse/visibility.py index 31659156ae..c4dd9ae2c7 100644 --- a/synapse/visibility.py +++ b/synapse/visibility.py @@ -56,7 +56,8 @@ def filter_events_for_clients(store, user_tuples, events, event_id_to_state): events ([synapse.events.EventBase]): list of events to filter """ forgotten = yield preserve_context_over_deferred(defer.gatherResults([ - preserve_fn(store.who_forgot_in_room)( + defer.maybeDeferred( + preserve_fn(store.who_forgot_in_room), room_id, ) for room_id in frozenset(e.room_id for e in events) -- cgit 1.5.1 From 014fee93b38ea93ee7dd9f9f9211895272e50834 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 28 Mar 2017 11:14:15 +0100 Subject: Manually calculate cache key as getcallargs is expensive This is because getcallargs recomputes the getargspec, amongst other things, which we don't need to do as its already been done --- synapse/util/caches/descriptors.py | 34 ++++++++++++++++++++++++++++------ 1 file changed, 28 insertions(+), 6 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/caches/descriptors.py b/synapse/util/caches/descriptors.py index 1607978e29..eed60d567e 100644 --- a/synapse/util/caches/descriptors.py +++ b/synapse/util/caches/descriptors.py @@ -197,6 +197,7 @@ class _CacheDescriptorBase(object): arg_spec = inspect.getargspec(orig) all_args = arg_spec.args + self.arg_spec = arg_spec if "cache_context" in all_args: if not cache_context: @@ -226,6 +227,14 @@ class _CacheDescriptorBase(object): self.num_args = num_args self.arg_names = all_args[1:num_args + 1] + if arg_spec.defaults: + self.arg_defaults = dict(zip( + all_args[-len(arg_spec.defaults):], + arg_spec.defaults + )) + else: + self.arg_defaults = {} + if "cache_context" in self.arg_names: raise Exception( "cache_context arg cannot be included among the cache keys" @@ -289,18 +298,31 @@ class CacheDescriptor(_CacheDescriptorBase): iterable=self.iterable, ) + def get_cache_key(args, kwargs): + """Given some args/kwargs return a generator that resolves into + the cache_key. + + We loop through each arg name, looking up if its in the `kwargs`, + otherwise using the next argument in `args`. If there are no more + args then we try looking the arg name up in the defaults + """ + pos = 0 + for nm in self.arg_names: + if nm in kwargs: + yield kwargs[nm] + elif pos < len(args): + yield args[pos] + pos += 1 + else: + yield self.arg_defaults[nm] + @functools.wraps(self.orig) def wrapped(*args, **kwargs): # If we're passed a cache_context then we'll want to call its invalidate() # whenever we are invalidated invalidate_callback = kwargs.pop("on_invalidate", None) - # Add temp cache_context so inspect.getcallargs doesn't explode - if self.add_cache_context: - kwargs["cache_context"] = None - - arg_dict = inspect.getcallargs(self.orig, obj, *args, **kwargs) - cache_key = tuple(arg_dict[arg_nm] for arg_nm in self.arg_names) + cache_key = tuple(get_cache_key(args, kwargs)) # Add our own `cache_context` to argument list if the wrapped function # has asked for one -- cgit 1.5.1 From 6194a64ae913aa400e19c3a9bd9348ce2bc11305 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 30 Mar 2017 14:19:10 +0100 Subject: Doc new instance variables --- synapse/util/caches/descriptors.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) (limited to 'synapse/util') diff --git a/synapse/util/caches/descriptors.py b/synapse/util/caches/descriptors.py index eed60d567e..1f02cca8a5 100644 --- a/synapse/util/caches/descriptors.py +++ b/synapse/util/caches/descriptors.py @@ -197,7 +197,6 @@ class _CacheDescriptorBase(object): arg_spec = inspect.getargspec(orig) all_args = arg_spec.args - self.arg_spec = arg_spec if "cache_context" in all_args: if not cache_context: @@ -225,8 +224,16 @@ class _CacheDescriptorBase(object): ) self.num_args = num_args + + # list of the names of the args used as the cache key self.arg_names = all_args[1:num_args + 1] + # The arg spec of the wrapped function, see `inspect.getargspec` for + # the type. + self.arg_spec = arg_spec + + # self.arg_defaults is a map of arg name to its default value for each + # argument that has a default value if arg_spec.defaults: self.arg_defaults = dict(zip( all_args[-len(arg_spec.defaults):], -- cgit 1.5.1 From b282fe7170142191c8ce795270422754ab4bc58e Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 30 Mar 2017 17:03:59 +0100 Subject: Revert log context change --- synapse/util/logcontext.py | 3 --- 1 file changed, 3 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 183d9cf62f..857afee7cb 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -315,9 +315,6 @@ def preserve_context_over_deferred(deferred, context=None): the deferred follow the synapse logcontext rules: try ``make_deferred_yieldable`` instead. """ - if not isinstance(deferred, defer.Deferred): - return deferred - if context is None: context = LoggingContext.current_context() d = _PreservingContextDeferred(context) -- cgit 1.5.1 From 5b5b171f3e9223351f72150ea73e1c9797144eae Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 30 Mar 2017 17:05:53 +0100 Subject: Docs --- synapse/util/async.py | 5 +++++ 1 file changed, 5 insertions(+) (limited to 'synapse/util') diff --git a/synapse/util/async.py b/synapse/util/async.py index 8495de496a..1453faf0ef 100644 --- a/synapse/util/async.py +++ b/synapse/util/async.py @@ -89,6 +89,11 @@ class ObservableDeferred(object): deferred.addCallbacks(callback, errback) def observe(self): + """Observe the underlying deferred. + + Can return either a deferred if the underlying deferred is still pending + (or has failed), or the actual value. Callers may need to use maybeDeferred. + """ if not self._result: d = defer.Deferred() -- cgit 1.5.1 From 4d17add8de6d1c3bcd073246519f3cdaa5063bed Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 31 Mar 2017 09:38:27 +0100 Subject: Remove unused instance variable --- synapse/util/caches/descriptors.py | 4 ---- 1 file changed, 4 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/caches/descriptors.py b/synapse/util/caches/descriptors.py index 1f02cca8a5..9d0d0be1f9 100644 --- a/synapse/util/caches/descriptors.py +++ b/synapse/util/caches/descriptors.py @@ -228,10 +228,6 @@ class _CacheDescriptorBase(object): # list of the names of the args used as the cache key self.arg_names = all_args[1:num_args + 1] - # The arg spec of the wrapped function, see `inspect.getargspec` for - # the type. - self.arg_spec = arg_spec - # self.arg_defaults is a map of arg name to its default value for each # argument that has a default value if arg_spec.defaults: -- cgit 1.5.1