diff --git a/tests/patch_inline_callbacks.py b/tests/patch_inline_callbacks.py
index 220884311c..a35a1d3305 100644
--- a/tests/patch_inline_callbacks.py
+++ b/tests/patch_inline_callbacks.py
@@ -31,19 +31,23 @@ def do_patch():
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):
-
- orig = orig_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,
@@ -55,7 +59,10 @@ def do_patch():
if not isinstance(res, Deferred) or res.called:
if LoggingContext.current_context() != start_context:
- err = "%s changed context from %s to %s" % (
+ for err in changes:
+ print(err, file=sys.stderr)
+
+ err = "Completed %s changed context from %s to %s" % (
f,
start_context,
LoggingContext.current_context(),
@@ -76,6 +83,8 @@ def do_patch():
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,
@@ -92,3 +101,79 @@ def do_patch():
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 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
|
