From 14b8c0476f93ea2ed3134e75733e45aa0ab6f5a5 Mon Sep 17 00:00:00 2001 From: Sean Quah <8349537+squahtx@users.noreply.github.com> Date: Tue, 14 Sep 2021 13:01:30 +0100 Subject: [PATCH] Prevent logging context going missing on federation request timeout (#10810) In `MatrixFederationHttpClient._send_request()`, we make a HTTP request using an `Agent`, wrap that request in a timeout and await the resulting `Deferred`. On its own, the `Agent` performing the HTTP request correctly stashes and restores the logging context while waiting. The addition of the timeout introduces a path where the logging context is not restored when execution resumes. To address this, we wrap the timeout `Deferred` in a `make_deferred_yieldable()` to stash the logging context and restore it on completion of the `await`. However this is not sufficient, since by the time we construct the timeout `Deferred`, the `Agent` has already stashed and cleared the logging context when using `make_deferred_yieldable()` to produce its `Deferred` for the request. Hence, we wrap the `Agent` request in a `run_in_background()` to "fork" and preserve the logging context so that we can stash and restore it when `await`ing the timeout `Deferred`. This approach is similar to the one used with `defer.gatherResults`. Note that the code is still not fully correct. When a timeout occurs, the request remains running in the background (existing behavior which is nothing to do with the new call to `run_in_background`) and may re-start the logging context after it has finished. --- changelog.d/10810.bugfix | 1 + synapse/http/matrixfederationclient.py | 17 +++++++++++++---- 2 files changed, 14 insertions(+), 4 deletions(-) create mode 100644 changelog.d/10810.bugfix diff --git a/changelog.d/10810.bugfix b/changelog.d/10810.bugfix new file mode 100644 index 0000000000..43e91f1f51 --- /dev/null +++ b/changelog.d/10810.bugfix @@ -0,0 +1 @@ +Fix a case where logging contexts would go missing when federation requests time out. diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 2e9898997c..ef10ec0937 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -66,7 +66,7 @@ from synapse.http.client import ( ) from synapse.http.federation.matrix_federation_agent import MatrixFederationAgent from synapse.logging import opentracing -from synapse.logging.context import make_deferred_yieldable +from synapse.logging.context import make_deferred_yieldable, run_in_background from synapse.logging.opentracing import set_tag, start_active_span, tags from synapse.types import JsonDict from synapse.util import json_decoder @@ -553,20 +553,29 @@ class MatrixFederationHttpClient: with Measure(self.clock, "outbound_request"): # we don't want all the fancy cookie and redirect handling # that treq.request gives: just use the raw Agent. - request_deferred = self.agent.request( + + # To preserve the logging context, the timeout is treated + # in a similar way to `defer.gatherResults`: + # * Each logging context-preserving fork is wrapped in + # `run_in_background`. In this case there is only one, + # since the timeout fork is not logging-context aware. + # * The `Deferred` that joins the forks back together is + # wrapped in `make_deferred_yieldable` to restore the + # logging context regardless of the path taken. + request_deferred = run_in_background( + self.agent.request, method_bytes, url_bytes, headers=Headers(headers_dict), bodyProducer=producer, ) - request_deferred = timeout_deferred( request_deferred, timeout=_sec_timeout, reactor=self.reactor, ) - response = await request_deferred + response = await make_deferred_yieldable(request_deferred) except DNSLookupError as e: raise RequestSendFailed(e, can_retry=retry_on_dns_fail) from e except Exception as e: