From f7199e873448794ffc88a08a9d7c01f1be0dfca1 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 5 Oct 2018 11:23:08 +0100 Subject: [PATCH 1/4] Log looping call exceptions If a looping call function errors, then it kills the loop entirely. Currently it throws away the exception logs, so we should make it actually log them. Fixes #3929 --- synapse/util/__init__.py | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py index 680ea928c..c237d003b 100644 --- a/synapse/util/__init__.py +++ b/synapse/util/__init__.py @@ -13,6 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import functools import logging from itertools import islice @@ -66,7 +67,7 @@ class Clock(object): f(function): The function to call repeatedly. msec(float): How long to wait between calls in milliseconds. """ - call = task.LoopingCall(f) + call = task.LoopingCall(_log_exception_wrapper(f)) call.clock = self._reactor call.start(msec / 1000.0, now=False) return call @@ -109,3 +110,19 @@ def batch_iter(iterable, size): sourceiter = iter(iterable) # call islice until it returns an empty tuple return iter(lambda: tuple(islice(sourceiter, size)), ()) + + +def _log_exception_wrapper(f): + """Used to wrap looping calls to log loudly if they get killed + """ + + @functools.wraps(f) + def wrap(*args, **kwargs): + try: + logger.info("Running looping call") + return f(*args, **kwargs) + except: # noqa: E722, as we reraise the exception this is fine. + logger.exception("Looping called died") + raise + + return wrap From 8164f6daf362b7039d6dcc8b645f306cfd5c49a8 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 5 Oct 2018 11:25:09 +0100 Subject: [PATCH 2/4] Newsfile --- changelog.d/4008.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/4008.misc diff --git a/changelog.d/4008.misc b/changelog.d/4008.misc new file mode 100644 index 000000000..573021005 --- /dev/null +++ b/changelog.d/4008.misc @@ -0,0 +1 @@ +Log exceptions in looping calls From 8a1817f0d29308a233783d43cbf1ad27891120c1 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 8 Oct 2018 13:26:54 +0100 Subject: [PATCH 3/4] Use errback pattern and catch async failures --- synapse/handlers/appservice.py | 7 +++++- synapse/util/__init__.py | 43 +++++++++++++++++++++++----------- 2 files changed, 35 insertions(+), 15 deletions(-) diff --git a/synapse/handlers/appservice.py b/synapse/handlers/appservice.py index f0f89af7d..16b897eb1 100644 --- a/synapse/handlers/appservice.py +++ b/synapse/handlers/appservice.py @@ -28,6 +28,7 @@ from synapse.metrics import ( event_processing_loop_room_count, ) from synapse.metrics.background_process_metrics import run_as_background_process +from synapse.util import make_log_failure_errback from synapse.util.logcontext import make_deferred_yieldable, run_in_background from synapse.util.metrics import Measure @@ -112,7 +113,11 @@ class ApplicationServicesHandler(object): if not self.started_scheduler: def start_scheduler(): - return self.scheduler.start().addErrback(log_failure) + return self.scheduler.start().addErrback( + make_log_failure_errback( + "Application Services Failure", + ) + ) run_as_background_process("as_scheduler", start_scheduler) self.started_scheduler = True diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py index c237d003b..964078aed 100644 --- a/synapse/util/__init__.py +++ b/synapse/util/__init__.py @@ -13,7 +13,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -import functools import logging from itertools import islice @@ -67,9 +66,12 @@ class Clock(object): f(function): The function to call repeatedly. msec(float): How long to wait between calls in milliseconds. """ - call = task.LoopingCall(_log_exception_wrapper(f)) + call = task.LoopingCall(f) call.clock = self._reactor - call.start(msec / 1000.0, now=False) + d = call.start(msec / 1000.0, now=False) + d.addErrback(make_log_failure_errback( + "Looping call died", consumeErrors=False, + )) return call def call_later(self, delay, callback, *args, **kwargs): @@ -112,17 +114,30 @@ def batch_iter(iterable, size): return iter(lambda: tuple(islice(sourceiter, size)), ()) -def _log_exception_wrapper(f): - """Used to wrap looping calls to log loudly if they get killed +def make_log_failure_errback(msg, consumeErrors=True): + """Creates a function suitable for passing to `Deferred.addErrback` that + logs any failures that occur. + + Args: + msg (str): Message to log + consumeErrors (bool): If true consumes the failure, otherwise passes + on down the callback chain + + Returns: + func(Failure) """ - @functools.wraps(f) - def wrap(*args, **kwargs): - try: - logger.info("Running looping call") - return f(*args, **kwargs) - except: # noqa: E722, as we reraise the exception this is fine. - logger.exception("Looping called died") - raise + def log_failure(failure): + logger.error( + msg, + exc_info=( + failure.type, + failure.value, + failure.getTracebackObject() + ) + ) - return wrap + if not consumeErrors: + return failure + + return log_failure From 69823205722662a72e4203ec304ff595a0f6ecf7 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 8 Oct 2018 14:06:19 +0100 Subject: [PATCH 4/4] Remove unnecessary extra function call layer --- synapse/handlers/appservice.py | 18 +++--------------- synapse/util/__init__.py | 29 +++++++++++++---------------- 2 files changed, 16 insertions(+), 31 deletions(-) diff --git a/synapse/handlers/appservice.py b/synapse/handlers/appservice.py index 16b897eb1..17eedf4db 100644 --- a/synapse/handlers/appservice.py +++ b/synapse/handlers/appservice.py @@ -28,7 +28,7 @@ from synapse.metrics import ( event_processing_loop_room_count, ) from synapse.metrics.background_process_metrics import run_as_background_process -from synapse.util import make_log_failure_errback +from synapse.util import log_failure from synapse.util.logcontext import make_deferred_yieldable, run_in_background from synapse.util.metrics import Measure @@ -37,17 +37,6 @@ logger = logging.getLogger(__name__) events_processed_counter = Counter("synapse_handlers_appservice_events_processed", "") -def log_failure(failure): - logger.error( - "Application Services Failure", - exc_info=( - failure.type, - failure.value, - failure.getTracebackObject() - ) - ) - - class ApplicationServicesHandler(object): def __init__(self, hs): @@ -114,10 +103,9 @@ class ApplicationServicesHandler(object): if not self.started_scheduler: def start_scheduler(): return self.scheduler.start().addErrback( - make_log_failure_errback( - "Application Services Failure", - ) + log_failure, "Application Services Failure", ) + run_as_background_process("as_scheduler", start_scheduler) self.started_scheduler = True diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py index 964078aed..9a8fae049 100644 --- a/synapse/util/__init__.py +++ b/synapse/util/__init__.py @@ -69,9 +69,9 @@ class Clock(object): call = task.LoopingCall(f) call.clock = self._reactor d = call.start(msec / 1000.0, now=False) - d.addErrback(make_log_failure_errback( - "Looping call died", consumeErrors=False, - )) + d.addErrback( + log_failure, "Looping call died", consumeErrors=False, + ) return call def call_later(self, delay, callback, *args, **kwargs): @@ -114,7 +114,7 @@ def batch_iter(iterable, size): return iter(lambda: tuple(islice(sourceiter, size)), ()) -def make_log_failure_errback(msg, consumeErrors=True): +def log_failure(failure, msg, consumeErrors=True): """Creates a function suitable for passing to `Deferred.addErrback` that logs any failures that occur. @@ -127,17 +127,14 @@ def make_log_failure_errback(msg, consumeErrors=True): func(Failure) """ - def log_failure(failure): - logger.error( - msg, - exc_info=( - failure.type, - failure.value, - failure.getTracebackObject() - ) + logger.error( + msg, + exc_info=( + failure.type, + failure.value, + failure.getTracebackObject() ) + ) - if not consumeErrors: - return failure - - return log_failure + if not consumeErrors: + return failure