From 1d6dd1c2944c22147258dda8ccf2777c68b38fba Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 10:53:06 +0100 Subject: Move patch_inline_callbacks into synapse/ --- synapse/util/patch_inline_callbacks.py | 179 +++++++++++++++++++++++++++++++++ 1 file changed, 179 insertions(+) create mode 100644 synapse/util/patch_inline_callbacks.py (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py new file mode 100644 index 0000000000..4fb49b0b2b --- /dev/null +++ b/synapse/util/patch_inline_callbacks.py @@ -0,0 +1,179 @@ +# -*- coding: utf-8 -*- +# Copyright 2018 New Vector Ltd +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from __future__ import print_function + +import functools +import sys + +from twisted.internet import defer +from twisted.internet.defer import Deferred +from twisted.python.failure import Failure + + +def do_patch(): + """ + Patch defer.inlineCallbacks so that it checks the state of the logcontext on exit + """ + + from synapse.logging.context import LoggingContext + + orig_inline_callbacks = defer.inlineCallbacks + if hasattr(orig_inline_callbacks, "patched_by_synapse"): + return + + def new_inline_callbacks(f): + @functools.wraps(f) + def wrapped(*args, **kwargs): + start_context = LoggingContext.current_context() + changes = [] + orig = orig_inline_callbacks(_check_yield_points(f, changes, start_context)) + + try: + res = orig(*args, **kwargs) + except Exception: + if LoggingContext.current_context() != start_context: + for err in changes: + print(err, file=sys.stderr) + + err = "%s changed context from %s to %s on exception" % ( + f, + start_context, + LoggingContext.current_context(), + ) + print(err, file=sys.stderr) + raise Exception(err) + raise + + if not isinstance(res, Deferred) or res.called: + if LoggingContext.current_context() != start_context: + for err in changes: + print(err, file=sys.stderr) + + err = "Completed %s changed context from %s to %s" % ( + f, + start_context, + LoggingContext.current_context(), + ) + # print the error to stderr because otherwise all we + # see in travis-ci is the 500 error + print(err, file=sys.stderr) + raise Exception(err) + return res + + if LoggingContext.current_context() != LoggingContext.sentinel: + err = ( + "%s returned incomplete deferred in non-sentinel context " + "%s (start was %s)" + ) % (f, LoggingContext.current_context(), start_context) + print(err, file=sys.stderr) + raise Exception(err) + + def check_ctx(r): + if LoggingContext.current_context() != start_context: + for err in changes: + print(err, file=sys.stderr) + err = "%s completion of %s changed context from %s to %s" % ( + "Failure" if isinstance(r, Failure) else "Success", + f, + start_context, + LoggingContext.current_context(), + ) + print(err, file=sys.stderr) + raise Exception(err) + return r + + res.addBoth(check_ctx) + return res + + return wrapped + + defer.inlineCallbacks = new_inline_callbacks + new_inline_callbacks.patched_by_synapse = True + + +def _check_yield_points(f, changes, start_context): + """Wraps a generator that is about to be passed to defer.inlineCallbacks + checking that after every yield the log contexts are correct. + """ + + from synapse.logging.context import LoggingContext + + @functools.wraps(f) + def check_yield_points_inner(*args, **kwargs): + expected_context = start_context + + gen = f(*args, **kwargs) + + last_yield_line_no = 1 + result = None + while True: + try: + isFailure = isinstance(result, Failure) + if isFailure: + d = result.throwExceptionIntoGenerator(gen) + else: + d = gen.send(result) + except (StopIteration, defer._DefGen_Return) as e: + if LoggingContext.current_context() != expected_context: + # This happens when the context is lost sometime *after* the + # final yield and returning. E.g. we forgot to yield on a + # function that returns a deferred. + err = ( + "Function %r returned and changed context from %s to %s," + " in %s between %d and end of func" + % ( + f.__qualname__, + start_context, + LoggingContext.current_context(), + f.__code__.co_filename, + last_yield_line_no, + ) + ) + changes.append(err) + # raise Exception(err) + return getattr(e, "value", None) + + try: + result = yield d + except Exception as e: + result = Failure(e) + + frame = gen.gi_frame + + if LoggingContext.current_context() != expected_context: + # This happens because the context is lost sometime *after* the + # previous yield and *after* the current yield. E.g. the + # deferred we waited on didn't follow the rules, or we forgot to + # yield on a function between the two yield points. + err = ( + "%s changed context from %s to %s, happened between lines %d and %d in %s" + % ( + frame.f_code.co_name, + start_context, + LoggingContext.current_context(), + last_yield_line_no, + frame.f_lineno, + frame.f_code.co_filename, + ) + ) + changes.append(err) + # raise Exception(err) + + expected_context = LoggingContext.current_context() + + last_yield_line_no = frame.f_lineno + + return check_yield_points_inner -- cgit 1.4.1 From 3e4272961a4cb659513bccd981cbd42f4e506362 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 10:58:32 +0100 Subject: Test for sentinel commit --- synapse/util/patch_inline_callbacks.py | 21 +++++++++++++++++++-- 1 file changed, 19 insertions(+), 2 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 4fb49b0b2b..4a45824f52 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -146,13 +146,30 @@ def _check_yield_points(f, changes, start_context): # raise Exception(err) return getattr(e, "value", None) + frame = gen.gi_frame + + if isinstance(d, defer.Deferred): + # This happens if we yield on a deferred that doesn't follow + # the log context rules without wrappin in a `make_deferred_yieldable` + if LoggingContext.current_context() != LoggingContext.Sentinel: + err = ( + "%s yielded with context %s rather than Sentinel," + " yielded on line %d in %s" + % ( + frame.f_code.co_name, + start_context, + LoggingContext.current_context(), + frame.f_lineno, + frame.f_code.co_filename, + ) + ) + changes.append(err) + try: result = yield d except Exception as e: result = Failure(e) - frame = gen.gi_frame - if LoggingContext.current_context() != expected_context: # This happens because the context is lost sometime *after* the # previous yield and *after* the current yield. E.g. the -- cgit 1.4.1 From ec0596f2ab4502c9a6183813a7e5dc2a5bfedd48 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 10:59:07 +0100 Subject: Log correct context --- synapse/util/patch_inline_callbacks.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 4a45824f52..5ef7190b14 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -117,7 +117,7 @@ def _check_yield_points(f, changes, start_context): gen = f(*args, **kwargs) - last_yield_line_no = 1 + last_yield_line_no = gen.gi_frame.f_lineno result = None while True: try: @@ -136,7 +136,7 @@ def _check_yield_points(f, changes, start_context): " in %s between %d and end of func" % ( f.__qualname__, - start_context, + expected_context, LoggingContext.current_context(), f.__code__.co_filename, last_yield_line_no, @@ -148,22 +148,22 @@ def _check_yield_points(f, changes, start_context): frame = gen.gi_frame - if isinstance(d, defer.Deferred): + if isinstance(d, defer.Deferred) and not d.called: # This happens if we yield on a deferred that doesn't follow # the log context rules without wrappin in a `make_deferred_yieldable` - if LoggingContext.current_context() != LoggingContext.Sentinel: + if LoggingContext.current_context() is not LoggingContext.sentinel: err = ( - "%s yielded with context %s rather than Sentinel," + "%s yielded with context %s rather than sentinel," " yielded on line %d in %s" % ( frame.f_code.co_name, - start_context, LoggingContext.current_context(), frame.f_lineno, frame.f_code.co_filename, ) ) changes.append(err) + # raise Exception(err) try: result = yield d -- cgit 1.4.1 From 791a8c559bf4ea984637c047fad7d6097e34ce99 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 11:53:57 +0100 Subject: Add coments --- synapse/util/patch_inline_callbacks.py | 30 +++++++++++++++++++++++++----- 1 file changed, 25 insertions(+), 5 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 5ef7190b14..b518dae256 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -107,6 +107,19 @@ def do_patch(): def _check_yield_points(f, changes, start_context): """Wraps a generator that is about to be passed to defer.inlineCallbacks checking that after every yield the log contexts are correct. + + Its perfectly valid for log contexts to change within a function, e.g. due + to new Measure blocks, so such changes are added to the given `changes` + list instead of triggering an exception. + + Args: + f: generator function to wrap + changes (list[str]): A list of strings detailing how the contexts + changed within a function. + start_context (LoggingContext): The initial context we're expecting + + Returns: + function """ from synapse.logging.context import LoggingContext @@ -131,6 +144,10 @@ def _check_yield_points(f, changes, start_context): # This happens when the context is lost sometime *after* the # final yield and returning. E.g. we forgot to yield on a # function that returns a deferred. + # + # We don't raise here as its perfectly valid for contexts to + # change in a function, as long as it sets the correct context + # on resolving (which is checked separately). err = ( "Function %r returned and changed context from %s to %s," " in %s between %d and end of func" @@ -143,14 +160,14 @@ def _check_yield_points(f, changes, start_context): ) ) changes.append(err) - # raise Exception(err) return getattr(e, "value", None) frame = gen.gi_frame if isinstance(d, defer.Deferred) and not d.called: # This happens if we yield on a deferred that doesn't follow - # the log context rules without wrappin in a `make_deferred_yieldable` + # the log context rules without wrappin in a `make_deferred_yieldable`. + # We raise here as this should never happen. if LoggingContext.current_context() is not LoggingContext.sentinel: err = ( "%s yielded with context %s rather than sentinel," @@ -162,8 +179,7 @@ def _check_yield_points(f, changes, start_context): frame.f_code.co_filename, ) ) - changes.append(err) - # raise Exception(err) + raise Exception(err) try: result = yield d @@ -171,10 +187,15 @@ def _check_yield_points(f, changes, start_context): result = Failure(e) if LoggingContext.current_context() != expected_context: + # This happens because the context is lost sometime *after* the # previous yield and *after* the current yield. E.g. the # deferred we waited on didn't follow the rules, or we forgot to # yield on a function between the two yield points. + # + # We don't raise here as its perfectly valid for contexts to + # change in a function, as long as it sets the correct context + # on resolving (which is checked separately). err = ( "%s changed context from %s to %s, happened between lines %d and %d in %s" % ( @@ -187,7 +208,6 @@ def _check_yield_points(f, changes, start_context): ) ) changes.append(err) - # raise Exception(err) expected_context = LoggingContext.current_context() -- cgit 1.4.1 From 941edad58355a829b49b0a43d382bbb0bf9ba021 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 12:15:17 +0100 Subject: Appease mypy --- synapse/util/patch_inline_callbacks.py | 31 ++++++++++++++++++------------- 1 file changed, 18 insertions(+), 13 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index b518dae256..64a2c891c3 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -18,11 +18,17 @@ from __future__ import print_function import functools import sys +from typing import List, Callable, Any + from twisted.internet import defer from twisted.internet.defer import Deferred from twisted.python.failure import Failure +# Tracks if we've already patched inlineCallbacks +_already_patched = False + + def do_patch(): """ Patch defer.inlineCallbacks so that it checks the state of the logcontext on exit @@ -30,16 +36,18 @@ def do_patch(): from synapse.logging.context import LoggingContext + global _already_patched + orig_inline_callbacks = defer.inlineCallbacks - if hasattr(orig_inline_callbacks, "patched_by_synapse"): + if _already_patched: return def new_inline_callbacks(f): @functools.wraps(f) def wrapped(*args, **kwargs): start_context = LoggingContext.current_context() - changes = [] - orig = orig_inline_callbacks(_check_yield_points(f, changes, start_context)) + changes: List[str] = [] + orig = orig_inline_callbacks(_check_yield_points(f, changes)) try: res = orig(*args, **kwargs) @@ -101,10 +109,10 @@ def do_patch(): return wrapped defer.inlineCallbacks = new_inline_callbacks - new_inline_callbacks.patched_by_synapse = True + _already_patched = True -def _check_yield_points(f, changes, start_context): +def _check_yield_points(f: Callable, changes: List[str]): """Wraps a generator that is about to be passed to defer.inlineCallbacks checking that after every yield the log contexts are correct. @@ -114,9 +122,8 @@ def _check_yield_points(f, changes, start_context): Args: f: generator function to wrap - changes (list[str]): A list of strings detailing how the contexts + changes: A list of strings detailing how the contexts changed within a function. - start_context (LoggingContext): The initial context we're expecting Returns: function @@ -126,13 +133,13 @@ def _check_yield_points(f, changes, start_context): @functools.wraps(f) def check_yield_points_inner(*args, **kwargs): - expected_context = start_context - gen = f(*args, **kwargs) last_yield_line_no = gen.gi_frame.f_lineno - result = None + result: Any = None while True: + expected_context = LoggingContext.current_context() + try: isFailure = isinstance(result, Failure) if isFailure: @@ -200,7 +207,7 @@ def _check_yield_points(f, changes, start_context): "%s changed context from %s to %s, happened between lines %d and %d in %s" % ( frame.f_code.co_name, - start_context, + expected_context, LoggingContext.current_context(), last_yield_line_no, frame.f_lineno, @@ -209,8 +216,6 @@ def _check_yield_points(f, changes, start_context): ) changes.append(err) - expected_context = LoggingContext.current_context() - last_yield_line_no = frame.f_lineno return check_yield_points_inner -- cgit 1.4.1 From f735aeec65a5117c71cf0f1e5f61cb900683533a Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 12:20:29 +0100 Subject: sort --- synapse/util/patch_inline_callbacks.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 64a2c891c3..3b78451dc0 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -17,14 +17,12 @@ from __future__ import print_function import functools import sys - -from typing import List, Callable, Any +from typing import Any, Callable, List from twisted.internet import defer from twisted.internet.defer import Deferred from twisted.python.failure import Failure - # Tracks if we've already patched inlineCallbacks _already_patched = False -- cgit 1.4.1 From c349e3ebafbe044022b93ca5c04d8b2fcb640c0a Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 12:29:38 +0100 Subject: Fix py3.5 --- synapse/util/patch_inline_callbacks.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 3b78451dc0..812dc88835 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -44,7 +44,7 @@ def do_patch(): @functools.wraps(f) def wrapped(*args, **kwargs): start_context = LoggingContext.current_context() - changes: List[str] = [] + changes = [] # type: List[str] orig = orig_inline_callbacks(_check_yield_points(f, changes)) try: -- cgit 1.4.1 From 59e0ed83065874775be350e25bb9f87da67b87c2 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 12:47:07 +0100 Subject: Fix py3.5 --- synapse/util/patch_inline_callbacks.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 812dc88835..66c3d47519 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -134,7 +134,7 @@ def _check_yield_points(f: Callable, changes: List[str]): gen = f(*args, **kwargs) last_yield_line_no = gen.gi_frame.f_lineno - result: Any = None + result = None # type: Any while True: expected_context = LoggingContext.current_context() -- cgit 1.4.1 From fe1c1e6c28e09f88b30e0587161f9b1dbd6e8acf Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 10 Oct 2019 13:17:19 +0100 Subject: Fixup comments Co-Authored-By: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> --- synapse/util/patch_inline_callbacks.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'synapse/util') diff --git a/synapse/util/patch_inline_callbacks.py b/synapse/util/patch_inline_callbacks.py index 66c3d47519..3925927f9f 100644 --- a/synapse/util/patch_inline_callbacks.py +++ b/synapse/util/patch_inline_callbacks.py @@ -114,7 +114,7 @@ def _check_yield_points(f: Callable, changes: List[str]): """Wraps a generator that is about to be passed to defer.inlineCallbacks checking that after every yield the log contexts are correct. - Its perfectly valid for log contexts to change within a function, e.g. due + It's perfectly valid for log contexts to change within a function, e.g. due to new Measure blocks, so such changes are added to the given `changes` list instead of triggering an exception. @@ -150,7 +150,7 @@ def _check_yield_points(f: Callable, changes: List[str]): # final yield and returning. E.g. we forgot to yield on a # function that returns a deferred. # - # We don't raise here as its perfectly valid for contexts to + # We don't raise here as it's perfectly valid for contexts to # change in a function, as long as it sets the correct context # on resolving (which is checked separately). err = ( @@ -171,7 +171,7 @@ def _check_yield_points(f: Callable, changes: List[str]): if isinstance(d, defer.Deferred) and not d.called: # This happens if we yield on a deferred that doesn't follow - # the log context rules without wrappin in a `make_deferred_yieldable`. + # the log context rules without wrapping in a `make_deferred_yieldable`. # We raise here as this should never happen. if LoggingContext.current_context() is not LoggingContext.sentinel: err = ( -- cgit 1.4.1