From 7639c3d9e53cdb6222df6a8e1b12bc2a40612367 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 13 Oct 2015 17:13:04 +0100 Subject: [PATCH 1/4] Bounce all deferreds through the reactor to make debugging easier. If all deferreds wait a reactor tick before resolving then there is always a chance to add an errback to the deferred so that stacktraces get reported, rather than being discarded. --- synapse/app/homeserver.py | 2 ++ synapse/util/debug.py | 68 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 70 insertions(+) create mode 100644 synapse/util/debug.py diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index af53acb369..1c84242aa3 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -33,6 +33,8 @@ if __name__ == '__main__': sys.stderr.writelines(message) sys.exit(1) + from synapse.util.debug import debug_deferreds + debug_deferreds() from synapse.storage.engines import create_engine, IncorrectDatabaseSetup from synapse.storage import are_all_users_on_domain diff --git a/synapse/util/debug.py b/synapse/util/debug.py new file mode 100644 index 0000000000..66ac12c291 --- /dev/null +++ b/synapse/util/debug.py @@ -0,0 +1,68 @@ +# -*- 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 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 + +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.""" + + # 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__ + From 32d66738b0229aa7f011d203d0cb7963f950bb95 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 13 Oct 2015 17:18:29 +0100 Subject: [PATCH 2/4] Fix pep8 warnings. --- synapse/util/debug.py | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/synapse/util/debug.py b/synapse/util/debug.py index 66ac12c291..f6a5a841a4 100644 --- a/synapse/util/debug.py +++ b/synapse/util/debug.py @@ -17,13 +17,6 @@ from twisted.internet import defer, reactor from functools import wraps from synapse.util.logcontext import LoggingContext, PreserveLoggingContext -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 def debug_deferreds(): """Cause all deferreds to wait for a reactor tick before running their @@ -31,6 +24,18 @@ def debug_deferreds(): 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__ @@ -65,4 +70,3 @@ def debug_deferreds(): self.addCallbacks(bounce_callback, bounce_errback) defer.Deferred.__init__ = new__init__ - From 9020860479a9f70ae4d05ddcdc231d7e336474e3 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 13 Oct 2015 17:50:44 +0100 Subject: [PATCH 3/4] Only turn on the twisted deferred debugging if full_twisted_stacktraces is set in the config --- synapse/app/homeserver.py | 3 --- synapse/config/logger.py | 8 ++++++++ 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index 1c84242aa3..cf2fa221dc 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -33,9 +33,6 @@ if __name__ == '__main__': sys.stderr.writelines(message) sys.exit(1) - from synapse.util.debug import debug_deferreds - debug_deferreds() - 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): From 1941eb315d692c44b0e21fb3fbf1b95eed138d53 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 13 Oct 2015 18:00:02 +0100 Subject: [PATCH 4/4] Enable stack traces for the demo scripts --- demo/start.sh | 3 +++ 1 file changed, 3 insertions(+) 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 \