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.
This commit is contained in:
Sean Quah 2021-09-14 13:01:30 +01:00 committed by GitHub
parent 51e1b96d04
commit 14b8c0476f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 14 additions and 4 deletions

1
changelog.d/10810.bugfix Normal file
View File

@ -0,0 +1 @@
Fix a case where logging contexts would go missing when federation requests time out.

View File

@ -66,7 +66,7 @@ from synapse.http.client import (
) )
from synapse.http.federation.matrix_federation_agent import MatrixFederationAgent from synapse.http.federation.matrix_federation_agent import MatrixFederationAgent
from synapse.logging import opentracing 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.logging.opentracing import set_tag, start_active_span, tags
from synapse.types import JsonDict from synapse.types import JsonDict
from synapse.util import json_decoder from synapse.util import json_decoder
@ -553,20 +553,29 @@ class MatrixFederationHttpClient:
with Measure(self.clock, "outbound_request"): with Measure(self.clock, "outbound_request"):
# we don't want all the fancy cookie and redirect handling # we don't want all the fancy cookie and redirect handling
# that treq.request gives: just use the raw Agent. # 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, method_bytes,
url_bytes, url_bytes,
headers=Headers(headers_dict), headers=Headers(headers_dict),
bodyProducer=producer, bodyProducer=producer,
) )
request_deferred = timeout_deferred( request_deferred = timeout_deferred(
request_deferred, request_deferred,
timeout=_sec_timeout, timeout=_sec_timeout,
reactor=self.reactor, reactor=self.reactor,
) )
response = await request_deferred response = await make_deferred_yieldable(request_deferred)
except DNSLookupError as e: except DNSLookupError as e:
raise RequestSendFailed(e, can_retry=retry_on_dns_fail) from e raise RequestSendFailed(e, can_retry=retry_on_dns_fail) from e
except Exception as e: except Exception as e: