Merge pull request #303 from matrix-org/markjh/twisted_debugging

Bounce all deferreds through the reactor to make debugging easier.

4 files changed, 83 insertions, 1 deletions

diff --git a/demo/start.sh b/demo/start.sh
index a90561488d..d90115ec97 100755
--- a/demo/start.sh
+++ b/demo/start.sh
@@ -38,6 +38,9 @@ for port in 8080 8081 8082; do
 
     perl -p -i -e 's/^enable_registration:.*/enable_registration: true/g' $DIR/etc/$port.config
 
+    echo "full_twisted_stacktraces: true" >> $DIR/etc/$port.config
+    echo "report_stats: false" >> $DIR/etc/$port.config
+
     python -m synapse.app.homeserver \
         --config-path "$DIR/etc/$port.config" \
         -D \
diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index af53acb369..cf2fa221dc 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -33,7 +33,6 @@ if __name__ == '__main__':
         sys.stderr.writelines(message)
         sys.exit(1)
 
-
 from synapse.storage.engines import create_engine, IncorrectDatabaseSetup
 from synapse.storage import are_all_users_on_domain
 from synapse.storage.prepare_database import UpgradeDatabaseException
diff --git a/synapse/config/logger.py b/synapse/config/logger.py
index bd0c17c861..a13dc170c4 100644
--- a/synapse/config/logger.py
+++ b/synapse/config/logger.py
@@ -22,6 +22,7 @@ import yaml
 from string import Template
 import os
 import signal
+from synapse.util.debug import debug_deferreds
 
 
 DEFAULT_LOG_CONFIG = Template("""
@@ -69,6 +70,8 @@ class LoggingConfig(Config):
         self.verbosity = config.get("verbose", 0)
         self.log_config = self.abspath(config.get("log_config"))
         self.log_file = self.abspath(config.get("log_file"))
+        if config.get("full_twisted_stacktraces"):
+            debug_deferreds()
 
     def default_config(self, config_dir_path, server_name, **kwargs):
         log_file = self.abspath("homeserver.log")
@@ -84,6 +87,11 @@ class LoggingConfig(Config):
 
         # A yaml python logging config file
         log_config: "%(log_config)s"
+
+        # Stop twisted from discarding the stack traces of exceptions in
+        # deferreds by waiting a reactor tick before running a deferred's
+        # callbacks.
+        # full_twisted_stacktraces: true
         """ % locals()
 
     def read_arguments(self, args):
diff --git a/synapse/util/debug.py b/synapse/util/debug.py
new file mode 100644
index 0000000000..f6a5a841a4
--- /dev/null
+++ b/synapse/util/debug.py
@@ -0,0 +1,72 @@
+# -*- coding: utf-8 -*-
+# Copyright 2015 OpenMarket 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 twisted.internet import defer, reactor
+from functools import wraps
+from synapse.util.logcontext import LoggingContext, PreserveLoggingContext
+
+
+def debug_deferreds():
+    """Cause all deferreds to wait for a reactor tick before running their
+    callbacks. This increases the chance of getting a stack trace out of
+    a defer.inlineCallback since the code waiting on the deferred will get
+    a chance to add an errback before the deferred runs."""
+
+    # Helper method for retrieving and restoring the current logging context
+    # around a callback.
+    def with_logging_context(fn):
+        context = LoggingContext.current_context()
+
+        def restore_context_callback(x):
+            with PreserveLoggingContext():
+                LoggingContext.thread_local.current_context = context
+                return fn(x)
+
+        return restore_context_callback
+
+    # We are going to modify the __init__ method of defer.Deferred so we
+    # need to get a copy of the old method so we can still call it.
+    old__init__ = defer.Deferred.__init__
+
+    # We need to create a deferred to bounce the callbacks through the reactor
+    # but we don't want to add a callback when we create that deferred so we
+    # we create a new type of deferred that uses the old __init__ method.
+    # This is safe as long as the old __init__ method doesn't invoke an
+    # __init__ using super.
+    class Bouncer(defer.Deferred):
+        __init__ = old__init__
+
+    # We'll add this as a callback to all Deferreds. Twisted will wait until
+    # the bouncer deferred resolves before calling the callbacks of the
+    # original deferred.
+    def bounce_callback(x):
+        bouncer = Bouncer()
+        reactor.callLater(0, with_logging_context(bouncer.callback), x)
+        return bouncer
+
+    # We'll add this as an errback to all Deferreds. Twisted will wait until
+    # the bouncer deferred resolves before calling the errbacks of the
+    # original deferred.
+    def bounce_errback(x):
+        bouncer = Bouncer()
+        reactor.callLater(0, with_logging_context(bouncer.errback), x)
+        return bouncer
+
+    @wraps(old__init__)
+    def new__init__(self, *args, **kargs):
+        old__init__(self, *args, **kargs)
+        self.addCallbacks(bounce_callback, bounce_errback)
+
+    defer.Deferred.__init__ = new__init__