From 812ed6b0d5b2c682d8032fc83e3041a9da93f670 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 22 Aug 2019 18:08:07 +0100 Subject: Opentracing across workers (#5771) Propagate opentracing contexts across workers Also includes some Convenience modifications to opentracing for servlets, notably: - Add boolean to skip the whitelisting check on inject extract methods. - useful when injecting into carriers locally. Otherwise we'd always have to include our own servername and whitelist our servername - start_active_span_from_request instead of header - Add boolean to decide whether to extract context from a request to a servlet --- synapse/replication/http/_base.py | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) (limited to 'synapse/replication/http/_base.py') diff --git a/synapse/replication/http/_base.py b/synapse/replication/http/_base.py index 2e0594e581..c4be9273f6 100644 --- a/synapse/replication/http/_base.py +++ b/synapse/replication/http/_base.py @@ -22,6 +22,7 @@ from six.moves import urllib from twisted.internet import defer +import synapse.logging.opentracing as opentracing from synapse.api.errors import ( CodeMessageException, HttpResponseException, @@ -165,8 +166,12 @@ class ReplicationEndpoint(object): # have a good idea that the request has either succeeded or failed on # the master, and so whether we should clean up or not. while True: + headers = {} + opentracing.inject_active_span_byte_dict( + headers, None, check_destination=False + ) try: - result = yield request_func(uri, data) + result = yield request_func(uri, data, headers=headers) break except CodeMessageException as e: if e.code != 504 or not cls.RETRY_ON_TIMEOUT: @@ -205,7 +210,14 @@ class ReplicationEndpoint(object): args = "/".join("(?P<%s>[^/]+)" % (arg,) for arg in url_args) pattern = re.compile("^/_synapse/replication/%s/%s$" % (self.NAME, args)) - http_server.register_paths(method, [pattern], handler, self.__class__.__name__) + http_server.register_paths( + method, + [pattern], + opentracing.trace_servlet(self.__class__.__name__, extract_context=True)( + handler + ), + self.__class__.__name__, + ) def _cached_handler(self, request, txn_id, **kwargs): """Called on new incoming requests when caching is enabled. Checks -- cgit 1.5.1 From 909827b422eb3396f905a1fb7ad1732f9727d500 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 14:46:04 +0100 Subject: Add opentracing to all client servlets (#5983) --- changelog.d/5983.feature | 1 + synapse/federation/transport/server.py | 6 +++++- synapse/http/server.py | 13 ++++++++++++- synapse/http/servlet.py | 6 +----- synapse/logging/opentracing.py | 2 +- synapse/replication/http/_base.py | 16 ++++++---------- 6 files changed, 26 insertions(+), 18 deletions(-) create mode 100644 changelog.d/5983.feature (limited to 'synapse/replication/http/_base.py') diff --git a/changelog.d/5983.feature b/changelog.d/5983.feature new file mode 100644 index 0000000000..aa23ee6dcd --- /dev/null +++ b/changelog.d/5983.feature @@ -0,0 +1 @@ +Add minimum opentracing for client servlets. diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index f9930b6460..132a8fb5e6 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -342,7 +342,11 @@ class BaseFederationServlet(object): continue server.register_paths( - method, (pattern,), self._wrap(code), self.__class__.__name__ + method, + (pattern,), + self._wrap(code), + self.__class__.__name__, + trace=False, ) diff --git a/synapse/http/server.py b/synapse/http/server.py index e6f351ba3b..cb9158fe1b 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -40,6 +40,7 @@ from synapse.api.errors import ( UnrecognizedRequestError, ) from synapse.logging.context import preserve_fn +from synapse.logging.opentracing import trace_servlet from synapse.util.caches import intern_dict logger = logging.getLogger(__name__) @@ -257,7 +258,9 @@ class JsonResource(HttpServer, resource.Resource): self.path_regexs = {} self.hs = hs - def register_paths(self, method, path_patterns, callback, servlet_classname): + def register_paths( + self, method, path_patterns, callback, servlet_classname, trace=True + ): """ Registers a request handler against a regular expression. Later request URLs are checked against these regular expressions in order to identify an appropriate @@ -273,8 +276,16 @@ class JsonResource(HttpServer, resource.Resource): servlet_classname (str): The name of the handler to be used in prometheus and opentracing logs. + + trace (bool): Whether we should start a span to trace the servlet. """ method = method.encode("utf-8") # method is bytes on py3 + + if trace: + # We don't extract the context from the servlet because we can't + # trust the sender + callback = trace_servlet(servlet_classname)(callback) + for path_pattern in path_patterns: logger.debug("Registering for %s %s", method, path_pattern.pattern) self.path_regexs.setdefault(method, []).append( diff --git a/synapse/http/servlet.py b/synapse/http/servlet.py index c186b31f59..274c1a6a87 100644 --- a/synapse/http/servlet.py +++ b/synapse/http/servlet.py @@ -20,7 +20,6 @@ import logging from canonicaljson import json from synapse.api.errors import Codes, SynapseError -from synapse.logging.opentracing import trace_servlet logger = logging.getLogger(__name__) @@ -298,10 +297,7 @@ class RestServlet(object): servlet_classname = self.__class__.__name__ method_handler = getattr(self, "on_%s" % (method,)) http_server.register_paths( - method, - patterns, - trace_servlet(servlet_classname)(method_handler), - servlet_classname, + method, patterns, method_handler, servlet_classname ) else: diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index dbf80e2024..2c34b54702 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -319,7 +319,7 @@ def whitelisted_homeserver(destination): Args: destination (str) """ - _homeserver_whitelist + if _homeserver_whitelist: return _homeserver_whitelist.match(destination) return False diff --git a/synapse/replication/http/_base.py b/synapse/replication/http/_base.py index c4be9273f6..afc9a8ff29 100644 --- a/synapse/replication/http/_base.py +++ b/synapse/replication/http/_base.py @@ -22,13 +22,13 @@ from six.moves import urllib from twisted.internet import defer -import synapse.logging.opentracing as opentracing from synapse.api.errors import ( CodeMessageException, HttpResponseException, RequestSendFailed, SynapseError, ) +from synapse.logging.opentracing import inject_active_span_byte_dict, trace_servlet from synapse.util.caches.response_cache import ResponseCache from synapse.util.stringutils import random_string @@ -167,9 +167,7 @@ class ReplicationEndpoint(object): # the master, and so whether we should clean up or not. while True: headers = {} - opentracing.inject_active_span_byte_dict( - headers, None, check_destination=False - ) + inject_active_span_byte_dict(headers, None, check_destination=False) try: result = yield request_func(uri, data, headers=headers) break @@ -210,13 +208,11 @@ class ReplicationEndpoint(object): args = "/".join("(?P<%s>[^/]+)" % (arg,) for arg in url_args) pattern = re.compile("^/_synapse/replication/%s/%s$" % (self.NAME, args)) + handler = trace_servlet(self.__class__.__name__, extract_context=True)(handler) + # We don't let register paths trace this servlet using the default tracing + # options because we wish to extract the context explicitly. http_server.register_paths( - method, - [pattern], - opentracing.trace_servlet(self.__class__.__name__, extract_context=True)( - handler - ), - self.__class__.__name__, + method, [pattern], handler, self.__class__.__name__, trace=False ) def _cached_handler(self, request, txn_id, **kwargs): -- cgit 1.5.1 From f7c873a64355506221648d55d64023c83d43f618 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 17:44:55 +0100 Subject: Trace how long it takes for the send trasaction to complete, including retrys (#5986) --- changelog.d/5986.feature | 1 + synapse/http/client.py | 87 ++++++++++++++++++++-------------- synapse/http/matrixfederationclient.py | 1 - synapse/replication/http/_base.py | 7 ++- 4 files changed, 58 insertions(+), 38 deletions(-) create mode 100644 changelog.d/5986.feature (limited to 'synapse/replication/http/_base.py') diff --git a/changelog.d/5986.feature b/changelog.d/5986.feature new file mode 100644 index 0000000000..f56aec1b32 --- /dev/null +++ b/changelog.d/5986.feature @@ -0,0 +1 @@ +Trace replication send times. diff --git a/synapse/http/client.py b/synapse/http/client.py index 0ae6db8ea7..51765ae3c0 100644 --- a/synapse/http/client.py +++ b/synapse/http/client.py @@ -46,6 +46,7 @@ from synapse.http import ( redact_uri, ) from synapse.logging.context import make_deferred_yieldable +from synapse.logging.opentracing import set_tag, start_active_span, tags from synapse.util.async_helpers import timeout_deferred from synapse.util.caches import CACHE_SIZE_FACTOR @@ -269,42 +270,56 @@ class SimpleHttpClient(object): # log request but strip `access_token` (AS requests for example include this) logger.info("Sending request %s %s", method, redact_uri(uri)) - try: - body_producer = None - if data is not None: - body_producer = QuieterFileBodyProducer(BytesIO(data)) - - request_deferred = treq.request( - method, - uri, - agent=self.agent, - data=body_producer, - headers=headers, - **self._extra_treq_args - ) - request_deferred = timeout_deferred( - request_deferred, - 60, - self.hs.get_reactor(), - cancelled_to_request_timed_out_error, - ) - response = yield make_deferred_yieldable(request_deferred) - - incoming_responses_counter.labels(method, response.code).inc() - logger.info( - "Received response to %s %s: %s", method, redact_uri(uri), response.code - ) - return response - except Exception as e: - incoming_responses_counter.labels(method, "ERR").inc() - logger.info( - "Error sending request to %s %s: %s %s", - method, - redact_uri(uri), - type(e).__name__, - e.args[0], - ) - raise + with start_active_span( + "outgoing-client-request", + tags={ + tags.SPAN_KIND: tags.SPAN_KIND_RPC_CLIENT, + tags.HTTP_METHOD: method, + tags.HTTP_URL: uri, + }, + finish_on_close=True, + ): + try: + body_producer = None + if data is not None: + body_producer = QuieterFileBodyProducer(BytesIO(data)) + + request_deferred = treq.request( + method, + uri, + agent=self.agent, + data=body_producer, + headers=headers, + **self._extra_treq_args + ) + request_deferred = timeout_deferred( + request_deferred, + 60, + self.hs.get_reactor(), + cancelled_to_request_timed_out_error, + ) + response = yield make_deferred_yieldable(request_deferred) + + incoming_responses_counter.labels(method, response.code).inc() + logger.info( + "Received response to %s %s: %s", + method, + redact_uri(uri), + response.code, + ) + return response + except Exception as e: + incoming_responses_counter.labels(method, "ERR").inc() + logger.info( + "Error sending request to %s %s: %s %s", + method, + redact_uri(uri), + type(e).__name__, + e.args[0], + ) + set_tag(tags.ERROR, True) + set_tag("error_reason", e.args[0]) + raise @defer.inlineCallbacks def post_urlencoded_get_json(self, uri, args={}, headers=None): diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 4326e98a28..3f7c93ffcb 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -345,7 +345,6 @@ class MatrixFederationHttpClient(object): else: query_bytes = b"" - # Retreive current span scope = start_active_span( "outgoing-federation-request", tags={ diff --git a/synapse/replication/http/_base.py b/synapse/replication/http/_base.py index afc9a8ff29..03560c1f0e 100644 --- a/synapse/replication/http/_base.py +++ b/synapse/replication/http/_base.py @@ -28,7 +28,11 @@ from synapse.api.errors import ( RequestSendFailed, SynapseError, ) -from synapse.logging.opentracing import inject_active_span_byte_dict, trace_servlet +from synapse.logging.opentracing import ( + inject_active_span_byte_dict, + trace, + trace_servlet, +) from synapse.util.caches.response_cache import ResponseCache from synapse.util.stringutils import random_string @@ -129,6 +133,7 @@ class ReplicationEndpoint(object): client = hs.get_simple_http_client() + @trace(opname="outgoing_replication_request") @defer.inlineCallbacks def send_request(**kwargs): data = yield cls._serialize_payload(**kwargs) -- cgit 1.5.1