From 17e1e807264ce13774d9b343c96406795ea24c27 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 12 Aug 2019 15:39:14 +0100 Subject: [PATCH 1/2] Retry well-known lookup before expiry. This gives a bit of a grace period where we can attempt to refetch a remote `well-known`, while still using the cached result if that fails. Hopefully this will make the well-known resolution a bit more torelant of failures, rather than it immediately treating failures as "no result" and caching that for an hour. --- .../http/federation/well_known_resolver.py | 82 ++++++++++++++----- synapse/util/caches/ttlcache.py | 8 +- .../test_matrix_federation_agent.py | 69 ++++++++++++++++ tests/util/caches/test_ttlcache.py | 4 +- 4 files changed, 136 insertions(+), 27 deletions(-) diff --git a/synapse/http/federation/well_known_resolver.py b/synapse/http/federation/well_known_resolver.py index d2866ff67da9..bb250c69221b 100644 --- a/synapse/http/federation/well_known_resolver.py +++ b/synapse/http/federation/well_known_resolver.py @@ -44,6 +44,12 @@ # lower bound for .well-known cache period WELL_KNOWN_MIN_CACHE_PERIOD = 5 * 60 +# Attempt to refetch a cached well-known N% of the TTL before it expires. +# e.g. if set to 0.2 and we have a cached entry with a TTL of 5mins, then +# we'll start trying to refetch 1 minute before it expires. +WELL_KNOWN_GRACE_PERIOD_FACTOR = 0.2 + + logger = logging.getLogger(__name__) @@ -80,15 +86,38 @@ def get_well_known(self, server_name): Deferred[WellKnownLookupResult]: The result of the lookup """ try: - result = self._well_known_cache[server_name] + prev_result, expiry, ttl = self._well_known_cache.get_with_expiry( + server_name + ) + + now = self._clock.time() + if now < expiry - WELL_KNOWN_GRACE_PERIOD_FACTOR * ttl: + return WellKnownLookupResult(delegated_server=prev_result) except KeyError: - # TODO: should we linearise so that we don't end up doing two .well-known - # requests for the same server in parallel? + prev_result = None + + # TODO: should we linearise so that we don't end up doing two .well-known + # requests for the same server in parallel? + try: with Measure(self._clock, "get_well_known"): result, cache_period = yield self._do_get_well_known(server_name) - if cache_period > 0: - self._well_known_cache.set(server_name, result, cache_period) + except _FetchWellKnownFailure as e: + if prev_result and e.temporary: + # This is a temporary failure and we have a still valid cached + # result, so lets return that. Hopefully the next time we ask + # the remote will be back up again. + return WellKnownLookupResult(delegated_server=prev_result) + + result = None + + # add some randomness to the TTL to avoid a stampeding herd every hour + # after startup + cache_period = WELL_KNOWN_INVALID_CACHE_PERIOD + cache_period += random.uniform(0, WELL_KNOWN_DEFAULT_CACHE_PERIOD_JITTER) + + if cache_period > 0: + self._well_known_cache.set(server_name, result, cache_period) return WellKnownLookupResult(delegated_server=result) @@ -99,40 +128,42 @@ def _do_get_well_known(self, server_name): Args: server_name (bytes): name of the server, from the requested url + Raises: + _FetchWellKnownFailure if we fail to lookup a result + Returns: - Deferred[Tuple[bytes|None|object],int]: - result, cache period, where result is one of: - - the new server name from the .well-known (as a `bytes`) - - None if there was no .well-known file. - - INVALID_WELL_KNOWN if the .well-known was invalid + Deferred[Tuple[bytes,int]]: The lookup result and cache period. """ uri = b"https://%s/.well-known/matrix/server" % (server_name,) uri_str = uri.decode("ascii") logger.info("Fetching %s", uri_str) + + # We do this in two steps to differentiate between possibly transient + # errors (e.g. can't connect to host, 503 response) and more permenant + # errors (such as getting a 404 response). try: response = yield make_deferred_yieldable( self._well_known_agent.request(b"GET", uri) ) body = yield make_deferred_yieldable(readBody(response)) + + if 500 <= response.code < 600: + raise Exception("Non-200 response %s" % (response.code,)) + except Exception as e: + logger.info("Error fetching %s: %s", uri_str, e) + raise _FetchWellKnownFailure(temporary=True) + + try: if response.code != 200: raise Exception("Non-200 response %s" % (response.code,)) parsed_body = json.loads(body.decode("utf-8")) logger.info("Response from .well-known: %s", parsed_body) - if not isinstance(parsed_body, dict): - raise Exception("not a dict") - if "m.server" not in parsed_body: - raise Exception("Missing key 'm.server'") + + result = parsed_body["m.server"].encode("ascii") except Exception as e: logger.info("Error fetching %s: %s", uri_str, e) - - # add some randomness to the TTL to avoid a stampeding herd every hour - # after startup - cache_period = WELL_KNOWN_INVALID_CACHE_PERIOD - cache_period += random.uniform(0, WELL_KNOWN_DEFAULT_CACHE_PERIOD_JITTER) - return (None, cache_period) - - result = parsed_body["m.server"].encode("ascii") + raise _FetchWellKnownFailure(temporary=False) cache_period = _cache_period_from_headers( response.headers, time_now=self._reactor.seconds @@ -185,3 +216,10 @@ def _parse_cache_control(headers): v = splits[1] if len(splits) > 1 else None cache_controls[k] = v return cache_controls + + +@attr.s() +class _FetchWellKnownFailure(Exception): + # True if we didn't get a non-5xx HTTP response, i.e. this may or may not be + # a temporary failure. + temporary = attr.ib() diff --git a/synapse/util/caches/ttlcache.py b/synapse/util/caches/ttlcache.py index 2af8ca43b123..99646c7cf09b 100644 --- a/synapse/util/caches/ttlcache.py +++ b/synapse/util/caches/ttlcache.py @@ -55,7 +55,7 @@ def set(self, key, value, ttl): if e != SENTINEL: self._expiry_list.remove(e) - entry = _CacheEntry(expiry_time=expiry, key=key, value=value) + entry = _CacheEntry(expiry_time=expiry, ttl=ttl, key=key, value=value) self._data[key] = entry self._expiry_list.add(entry) @@ -87,7 +87,8 @@ def get_with_expiry(self, key): key: key to look up Returns: - Tuple[Any, float]: the value from the cache, and the expiry time + Tuple[Any, float, float]: the value from the cache, the expiry time + and the TTL Raises: KeyError if the entry is not found @@ -99,7 +100,7 @@ def get_with_expiry(self, key): self._metrics.inc_misses() raise self._metrics.inc_hits() - return e.value, e.expiry_time + return e.value, e.expiry_time, e.ttl def pop(self, key, default=SENTINEL): """Remove a value from the cache @@ -158,5 +159,6 @@ class _CacheEntry(object): # expiry_time is the first attribute, so that entries are sorted by expiry. expiry_time = attr.ib() + ttl = attr.ib() key = attr.ib() value = attr.ib() diff --git a/tests/http/federation/test_matrix_federation_agent.py b/tests/http/federation/test_matrix_federation_agent.py index 1435baede26a..2c568788b306 100644 --- a/tests/http/federation/test_matrix_federation_agent.py +++ b/tests/http/federation/test_matrix_federation_agent.py @@ -987,6 +987,75 @@ def test_well_known_cache(self): r = self.successResultOf(fetch_d) self.assertEqual(r.delegated_server, b"other-server") + def test_well_known_cache_with_temp_failure(self): + """Test that we refetch well-known before the cache expires, and that + it ignores transient errors. + """ + + well_known_resolver = WellKnownResolver( + self.reactor, + Agent(self.reactor, contextFactory=self.tls_factory), + well_known_cache=self.well_known_cache, + ) + + self.reactor.lookups["testserv"] = "1.2.3.4" + + fetch_d = well_known_resolver.get_well_known(b"testserv") + + # there should be an attempt to connect on port 443 for the .well-known + clients = self.reactor.tcpClients + self.assertEqual(len(clients), 1) + (host, port, client_factory, _timeout, _bindAddress) = clients.pop(0) + self.assertEqual(host, "1.2.3.4") + self.assertEqual(port, 443) + + well_known_server = self._handle_well_known_connection( + client_factory, + expected_sni=b"testserv", + response_headers={b"Cache-Control": b"max-age=1000"}, + content=b'{ "m.server": "target-server" }', + ) + + r = self.successResultOf(fetch_d) + self.assertEqual(r.delegated_server, b"target-server") + + # close the tcp connection + well_known_server.loseConnection() + + # Get close to the cache expiry, this will cause the resolver to do + # another lookup. + self.reactor.pump((900.0,)) + + fetch_d = well_known_resolver.get_well_known(b"testserv") + clients = self.reactor.tcpClients + (host, port, client_factory, _timeout, _bindAddress) = clients.pop(0) + + # fonx the connection attempt, this will be treated as a temporary + # failure. + client_factory.clientConnectionFailed(None, Exception("nope")) + + # attemptdelay on the hostnameendpoint is 0.3, so takes that long before the + # .well-known request fails. + self.reactor.pump((0.4,)) + + # Resolver should return cached value, despite the lookup failing. + r = self.successResultOf(fetch_d) + self.assertEqual(r.delegated_server, b"target-server") + + # Expire the cache and repeat the request + self.reactor.pump((100.0,)) + + # Repated the request, this time it should fail if the lookup fails. + fetch_d = well_known_resolver.get_well_known(b"testserv") + + clients = self.reactor.tcpClients + (host, port, client_factory, _timeout, _bindAddress) = clients.pop(0) + client_factory.clientConnectionFailed(None, Exception("nope")) + self.reactor.pump((0.4,)) + + r = self.successResultOf(fetch_d) + self.assertEqual(r.delegated_server, None) + class TestCachePeriodFromHeaders(TestCase): def test_cache_control(self): diff --git a/tests/util/caches/test_ttlcache.py b/tests/util/caches/test_ttlcache.py index c94cbb662bd5..816795c13659 100644 --- a/tests/util/caches/test_ttlcache.py +++ b/tests/util/caches/test_ttlcache.py @@ -36,7 +36,7 @@ def test_get(self): self.assertTrue("one" in self.cache) self.assertEqual(self.cache.get("one"), "1") self.assertEqual(self.cache["one"], "1") - self.assertEqual(self.cache.get_with_expiry("one"), ("1", 110)) + self.assertEqual(self.cache.get_with_expiry("one"), ("1", 110, 10)) self.assertEqual(self.cache._metrics.hits, 3) self.assertEqual(self.cache._metrics.misses, 0) @@ -77,7 +77,7 @@ def test_expiry(self): self.assertEqual(self.cache["two"], "2") self.assertEqual(self.cache["three"], "3") - self.assertEqual(self.cache.get_with_expiry("two"), ("2", 120)) + self.assertEqual(self.cache.get_with_expiry("two"), ("2", 120, 20)) self.assertEqual(self.cache._metrics.hits, 5) self.assertEqual(self.cache._metrics.misses, 0) From aedfec3ad75f9986e03ecd64dee2ce6f9af0ee13 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 13 Aug 2019 12:40:09 +0100 Subject: [PATCH 2/2] Newsfile --- changelog.d/5844.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/5844.misc diff --git a/changelog.d/5844.misc b/changelog.d/5844.misc new file mode 100644 index 000000000000..a0826af0d2c3 --- /dev/null +++ b/changelog.d/5844.misc @@ -0,0 +1 @@ +Retry well-known lookup before the cache expires, giving a grace period where the remote well-known can be down but we still use the old result.