From 26f034f9d0e597b46d309290944eadab85e07d31 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 15:22:26 +0100 Subject: [PATCH 1/6] Trace send time. --- synapse/replication/http/_base.py | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/synapse/replication/http/_base.py b/synapse/replication/http/_base.py index c4be9273f655..d6e1371c2f97 100644 --- a/synapse/replication/http/_base.py +++ b/synapse/replication/http/_base.py @@ -22,7 +22,12 @@ from twisted.internet import defer -import synapse.logging.opentracing as opentracing +from synapse.logging.opentracing import ( + trace, + inject_active_span_byte_dict, + trace_servlet, +) + from synapse.api.errors import ( CodeMessageException, HttpResponseException, @@ -129,6 +134,7 @@ def make_client(cls, hs): client = hs.get_simple_http_client() + @trace @defer.inlineCallbacks def send_request(**kwargs): data = yield cls._serialize_payload(**kwargs) @@ -167,9 +173,7 @@ def send_request(**kwargs): # 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 @@ -213,9 +217,7 @@ def register(self, http_server): http_server.register_paths( method, [pattern], - opentracing.trace_servlet(self.__class__.__name__, extract_context=True)( - handler - ), + trace_servlet(self.__class__.__name__, extract_context=True)(handler), self.__class__.__name__, ) From d779256e03da579cf334b6886720de48a3e317a5 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 15:35:50 +0100 Subject: [PATCH 2/6] newsfile --- changelog.d/5986.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/5986.feature diff --git a/changelog.d/5986.feature b/changelog.d/5986.feature new file mode 100644 index 000000000000..f56aec1b32a0 --- /dev/null +++ b/changelog.d/5986.feature @@ -0,0 +1 @@ +Trace replication send times. From 4b221182d38d20649ce48ad790455c700d2b651b Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:19:02 +0100 Subject: [PATCH 3/6] isort --- synapse/replication/http/_base.py | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/synapse/replication/http/_base.py b/synapse/replication/http/_base.py index d6e1371c2f97..fed2f5120fad 100644 --- a/synapse/replication/http/_base.py +++ b/synapse/replication/http/_base.py @@ -22,18 +22,17 @@ from twisted.internet import defer -from synapse.logging.opentracing import ( - trace, - inject_active_span_byte_dict, - trace_servlet, -) - from synapse.api.errors import ( CodeMessageException, HttpResponseException, RequestSendFailed, SynapseError, ) +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 From a184636fe16c7b3e4445652ccd91ab66cc99116f Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:35:06 +0100 Subject: [PATCH 4/6] Trace client send time --- synapse/http/client.py | 87 +++++++++++++++++++++++++----------------- 1 file changed, 51 insertions(+), 36 deletions(-) diff --git a/synapse/http/client.py b/synapse/http/client.py index 0ae6db8ea777..51765ae3c0ad 100644 --- a/synapse/http/client.py +++ b/synapse/http/client.py @@ -46,6 +46,7 @@ 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 @@ def request(self, method, uri, data=None, headers=None): # 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): From 42302dda373dd8bc94cadc7ca95df917bd3154b3 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:35:20 +0100 Subject: [PATCH 5/6] Outdated comment --- synapse/http/matrixfederationclient.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 4326e98a28f1..3f7c93ffcbfc 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -345,7 +345,6 @@ def _send_request( else: query_bytes = b"" - # Retreive current span scope = start_active_span( "outgoing-federation-request", tags={ From d78a0a11e33943c765aded6c6b55c353c47960b8 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:35:50 +0100 Subject: [PATCH 6/6] Nicer replication send trace name --- synapse/replication/http/_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/replication/http/_base.py b/synapse/replication/http/_base.py index fed2f5120fad..64f012f5b804 100644 --- a/synapse/replication/http/_base.py +++ b/synapse/replication/http/_base.py @@ -133,7 +133,7 @@ def make_client(cls, hs): client = hs.get_simple_http_client() - @trace + @trace(opname="outgoing_replication_request") @defer.inlineCallbacks def send_request(**kwargs): data = yield cls._serialize_payload(**kwargs)