diff options
| -rw-r--r-- | changelog.d/11870.misc | 1 | ||||
| -rw-r--r-- | synapse/federation/transport/server/_base.py | 67 | ||||
| -rw-r--r-- | synapse/logging/opentracing.py | 12 |
3 files changed, 61 insertions, 19 deletions
diff --git a/changelog.d/11870.misc b/changelog.d/11870.misc new file mode 100644 index 0000000000..2cb0efdb45 --- /dev/null +++ b/changelog.d/11870.misc @@ -0,0 +1 @@ +Improve opentracing for incoming federation requests. diff --git a/synapse/federation/transport/server/_base.py b/synapse/federation/transport/server/_base.py index 2ca7c05835..dff2b68359 100644 --- a/synapse/federation/transport/server/_base.py +++ b/synapse/federation/transport/server/_base.py @@ -15,6 +15,7 @@ import functools import logging import re +import time from typing import TYPE_CHECKING, Any, Awaitable, Callable, Optional, Tuple, cast from synapse.api.errors import Codes, FederationDeniedError, SynapseError @@ -24,8 +25,10 @@ from synapse.http.servlet import parse_json_object_from_request from synapse.http.site import SynapseRequest from synapse.logging.context import run_in_background from synapse.logging.opentracing import ( + active_span, set_tag, span_context_from_request, + start_active_span, start_active_span_follows_from, whitelisted_homeserver, ) @@ -265,9 +268,10 @@ class BaseFederationServlet: content = parse_json_object_from_request(request) try: - origin: Optional[str] = await authenticator.authenticate_request( - request, content - ) + with start_active_span("authenticate_request"): + origin: Optional[str] = await authenticator.authenticate_request( + request, content + ) except NoAuthenticationError: origin = None if self.REQUIRE_AUTH: @@ -282,32 +286,57 @@ class BaseFederationServlet: # update the active opentracing span with the authenticated entity set_tag("authenticated_entity", origin) - # if the origin is authenticated and whitelisted, link to its span context + # if the origin is authenticated and whitelisted, use its span context + # as the parent. context = None if origin and whitelisted_homeserver(origin): context = span_context_from_request(request) - scope = start_active_span_follows_from( - "incoming-federation-request", contexts=(context,) if context else () - ) + if context: + servlet_span = active_span() + # a scope which uses the origin's context as a parent + processing_start_time = time.time() + scope = start_active_span_follows_from( + "incoming-federation-request", + child_of=context, + contexts=(servlet_span,), + start_time=processing_start_time, + ) - with scope: - if origin and self.RATELIMIT: - with ratelimiter.ratelimit(origin) as d: - await d - if request._disconnected: - logger.warning( - "client disconnected before we started processing " - "request" + else: + # just use our context as a parent + scope = start_active_span( + "incoming-federation-request", + ) + + try: + with scope: + if origin and self.RATELIMIT: + with ratelimiter.ratelimit(origin) as d: + await d + if request._disconnected: + logger.warning( + "client disconnected before we started processing " + "request" + ) + return None + response = await func( + origin, content, request.args, *args, **kwargs ) - return None + else: response = await func( origin, content, request.args, *args, **kwargs ) - else: - response = await func( - origin, content, request.args, *args, **kwargs + finally: + # if we used the origin's context as the parent, add a new span using + # the servlet span as a parent, so that we have a link + if context: + scope2 = start_active_span_follows_from( + "process-federation_request", + contexts=(scope.span,), + start_time=processing_start_time, ) + scope2.close() return response diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index d25f25ecb5..3ebed5c161 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -478,6 +478,8 @@ def start_active_span( def start_active_span_follows_from( operation_name: str, contexts: Collection, + child_of=None, + start_time: Optional[float] = None, *, inherit_force_tracing=False, tracer=None, @@ -487,6 +489,14 @@ def start_active_span_follows_from( Args: operation_name: name of the operation represented by the new span contexts: the previous spans to inherit from + + child_of: optionally override the parent span. If unset, the currently active + span will be the parent. (If there is no currently active span, the first + span in `contexts` will be the parent.) + + start_time: optional override for the start time of the created span. Seconds + since the epoch. + inherit_force_tracing: if set, and any of the previous contexts have had tracing forced, the new span will also have tracing forced. tracer: override the opentracing tracer. By default the global tracer is used. @@ -497,7 +507,9 @@ def start_active_span_follows_from( references = [opentracing.follows_from(context) for context in contexts] scope = start_active_span( operation_name, + child_of=child_of, references=references, + start_time=start_time, tracer=tracer, ) |