diff --git a/synapse/__init__.py b/synapse/__init__.py
index 2d52d26af5..1055f54e00 100644
--- a/synapse/__init__.py
+++ b/synapse/__init__.py
@@ -17,8 +17,11 @@
""" This is a reference implementation of a Matrix home server.
"""
+import os
import sys
+from tests.patch_inline_callbacks import do_patch
+
# Check that we're not running on an unsupported Python version.
if sys.version_info < (3, 5):
print("Synapse requires Python 3.5 or above.")
@@ -36,3 +39,6 @@ except ImportError:
pass
__version__ = "1.4.0"
+
+if bool(os.environ.get("SYNAPSE_TEST_PATCH_LOG_CONTEXTS", False)):
+ do_patch()
diff --git a/synapse/handlers/room_member.py b/synapse/handlers/room_member.py
index 95a244d86c..1edc657f8a 100644
--- a/synapse/handlers/room_member.py
+++ b/synapse/handlers/room_member.py
@@ -213,7 +213,7 @@ class RoomMemberHandler(object):
if predecessor:
# It is an upgraded room. Copy over old tags
- self.copy_room_tags_and_direct_to_room(
+ yield self.copy_room_tags_and_direct_to_room(
predecessor["room_id"], room_id, user_id
)
# Copy over push rules
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index abe16334ec..06cc14fcd1 100644
--- a/synapse/storage/_base.py
+++ b/synapse/storage/_base.py
@@ -30,7 +30,7 @@ from prometheus_client import Histogram
from twisted.internet import defer
from synapse.api.errors import StoreError
-from synapse.logging.context import LoggingContext, PreserveLoggingContext
+from synapse.logging.context import LoggingContext, make_deferred_yieldable
from synapse.metrics.background_process_metrics import run_as_background_process
from synapse.storage.engines import PostgresEngine, Sqlite3Engine
from synapse.types import get_domain_from_id
@@ -550,8 +550,9 @@ class SQLBaseStore(object):
return func(conn, *args, **kwargs)
- with PreserveLoggingContext():
- result = yield self._db_pool.runWithConnection(inner_func, *args, **kwargs)
+ result = yield make_deferred_yieldable(
+ self._db_pool.runWithConnection(inner_func, *args, **kwargs)
+ )
return result
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
|
