From 6d6e7288fe0200353740e03e6218a2781342f3e4 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Mon, 21 May 2018 16:49:59 +0100 Subject: [PATCH 1/2] Stop the transaction cache caching failures The transaction cache has some code which tries to stop it caching failures, but if the callback function failed straight away, then things would happen backwards and we'd end up with the failure stuck in the cache. --- synapse/rest/client/transactions.py | 22 ++++++----- tests/rest/client/test_transactions.py | 54 ++++++++++++++++++++++++++ 2 files changed, 67 insertions(+), 9 deletions(-) diff --git a/synapse/rest/client/transactions.py b/synapse/rest/client/transactions.py index fceca2ede..93ce0f534 100644 --- a/synapse/rest/client/transactions.py +++ b/synapse/rest/client/transactions.py @@ -87,19 +87,23 @@ class HttpTransactionCache(object): deferred = fn(*args, **kwargs) - # if the request fails with a Twisted failure, remove it - # from the transaction map. This is done to ensure that we don't - # cache transient errors like rate-limiting errors, etc. + observable = ObservableDeferred(deferred, consumeErrors=False) + self.transactions[txn_key] = (observable, self.clock.time_msec()) + + # if the request fails with an exception, remove it from the + # transaction map. This is done to ensure that we don't cache + # transient errors like rate-limiting errors, etc. + # + # (make sure we add this errback *after* adding the key above, in case + # the deferred has already failed and is running errbacks + # synchronously) def remove_from_map(err): self.transactions.pop(txn_key, None) - return err + # we deliberately do not propagate the error any further, as we + # expect the observers to have reported it. + deferred.addErrback(remove_from_map) - # We don't add any other errbacks to the raw deferred, so we ask - # ObservableDeferred to swallow the error. This is fine as the error will - # still be reported to the observers. - observable = ObservableDeferred(deferred, consumeErrors=True) - self.transactions[txn_key] = (observable, self.clock.time_msec()) return observable.observe() def _cleanup(self): diff --git a/tests/rest/client/test_transactions.py b/tests/rest/client/test_transactions.py index d7cea3026..b650a7772 100644 --- a/tests/rest/client/test_transactions.py +++ b/tests/rest/client/test_transactions.py @@ -2,6 +2,8 @@ from synapse.rest.client.transactions import HttpTransactionCache from synapse.rest.client.transactions import CLEANUP_PERIOD_MS from twisted.internet import defer from mock import Mock, call + +from synapse.util.logcontext import LoggingContext from tests import unittest from tests.utils import MockClock @@ -39,6 +41,58 @@ class HttpTransactionCacheTestCase(unittest.TestCase): # expect only a single call to do the work cb.assert_called_once_with("some_arg", keyword="arg", changing_args=0) + @defer.inlineCallbacks + def test_does_not_cache_exceptions(self): + """Checks that, if the callback throws an exception, it is called again + for the next request. + """ + called = [False] + + def cb(): + if called[0]: + # return a valid result the second time + return defer.succeed(self.mock_http_response) + + called[0] = True + raise Exception("boo") + + with LoggingContext("test") as test_context: + try: + yield self.cache.fetch_or_execute(self.mock_key, cb) + except Exception as e: + self.assertEqual(e.message, "boo") + self.assertIs(LoggingContext.current_context(), test_context) + + res = yield self.cache.fetch_or_execute(self.mock_key, cb) + self.assertEqual(res, self.mock_http_response) + self.assertIs(LoggingContext.current_context(), test_context) + + @defer.inlineCallbacks + def test_does_not_cache_failures(self): + """Checks that, if the callback returns a failure, it is called again + for the next request. + """ + called = [False] + + def cb(): + if called[0]: + # return a valid result the second time + return defer.succeed(self.mock_http_response) + + called[0] = True + return defer.fail(Exception("boo")) + + with LoggingContext("test") as test_context: + try: + yield self.cache.fetch_or_execute(self.mock_key, cb) + except Exception as e: + self.assertEqual(e.message, "boo") + self.assertIs(LoggingContext.current_context(), test_context) + + res = yield self.cache.fetch_or_execute(self.mock_key, cb) + self.assertEqual(res, self.mock_http_response) + self.assertIs(LoggingContext.current_context(), test_context) + @defer.inlineCallbacks def test_cleans_up(self): cb = Mock( From 6e1cb54a05df3dd614acb022a665458cc1c9698f Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Mon, 21 May 2018 16:58:20 +0100 Subject: [PATCH 2/2] Fix logcontext leak in HttpTransactionCache ONE DAY I WILL PURGE THE WORLD OF THIS EVIL --- synapse/rest/client/transactions.py | 38 ++++++++++++-------------- tests/rest/client/test_transactions.py | 21 ++++++++++++++ 2 files changed, 38 insertions(+), 21 deletions(-) diff --git a/synapse/rest/client/transactions.py b/synapse/rest/client/transactions.py index 93ce0f534..20fa6678e 100644 --- a/synapse/rest/client/transactions.py +++ b/synapse/rest/client/transactions.py @@ -19,6 +19,7 @@ import logging from synapse.api.auth import get_access_token_from_request from synapse.util.async import ObservableDeferred +from synapse.util.logcontext import make_deferred_yieldable, run_in_background logger = logging.getLogger(__name__) @@ -80,31 +81,26 @@ class HttpTransactionCache(object): Returns: Deferred which resolves to a tuple of (response_code, response_dict). """ - try: - return self.transactions[txn_key][0].observe() - except (KeyError, IndexError): - pass # execute the function instead. + if txn_key in self.transactions: + observable = self.transactions[txn_key][0] + else: + # execute the function instead. + deferred = run_in_background(fn, *args, **kwargs) - deferred = fn(*args, **kwargs) + observable = ObservableDeferred(deferred) + self.transactions[txn_key] = (observable, self.clock.time_msec()) - observable = ObservableDeferred(deferred, consumeErrors=False) - self.transactions[txn_key] = (observable, self.clock.time_msec()) + # if the request fails with an exception, remove it + # from the transaction map. This is done to ensure that we don't + # cache transient errors like rate-limiting errors, etc. + def remove_from_map(err): + self.transactions.pop(txn_key, None) + # we deliberately do not propagate the error any further, as we + # expect the observers to have reported it. - # if the request fails with an exception, remove it from the - # transaction map. This is done to ensure that we don't cache - # transient errors like rate-limiting errors, etc. - # - # (make sure we add this errback *after* adding the key above, in case - # the deferred has already failed and is running errbacks - # synchronously) - def remove_from_map(err): - self.transactions.pop(txn_key, None) - # we deliberately do not propagate the error any further, as we - # expect the observers to have reported it. + deferred.addErrback(remove_from_map) - deferred.addErrback(remove_from_map) - - return observable.observe() + return make_deferred_yieldable(observable.observe()) def _cleanup(self): now = self.clock.time_msec() diff --git a/tests/rest/client/test_transactions.py b/tests/rest/client/test_transactions.py index b650a7772..b5bc2fa25 100644 --- a/tests/rest/client/test_transactions.py +++ b/tests/rest/client/test_transactions.py @@ -3,6 +3,7 @@ from synapse.rest.client.transactions import CLEANUP_PERIOD_MS from twisted.internet import defer from mock import Mock, call +from synapse.util import async from synapse.util.logcontext import LoggingContext from tests import unittest from tests.utils import MockClock @@ -41,6 +42,26 @@ class HttpTransactionCacheTestCase(unittest.TestCase): # expect only a single call to do the work cb.assert_called_once_with("some_arg", keyword="arg", changing_args=0) + @defer.inlineCallbacks + def test_logcontexts_with_async_result(self): + @defer.inlineCallbacks + def cb(): + yield async.sleep(0) + defer.returnValue("yay") + + @defer.inlineCallbacks + def test(): + with LoggingContext("c") as c1: + res = yield self.cache.fetch_or_execute(self.mock_key, cb) + self.assertIs(LoggingContext.current_context(), c1) + self.assertEqual(res, "yay") + + # run the test twice in parallel + d = defer.gatherResults([test(), test()]) + self.assertIs(LoggingContext.current_context(), LoggingContext.sentinel) + yield d + self.assertIs(LoggingContext.current_context(), LoggingContext.sentinel) + @defer.inlineCallbacks def test_does_not_cache_exceptions(self): """Checks that, if the callback throws an exception, it is called again