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__