From 5afd89a546e8fb0d118b61bcb1153a4d0b250502 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 21 Jun 2019 11:53:14 +0100 Subject: [PATCH 01/69] Configure and initialise tracer Includes config options for the tracer and sets up JaegerClient. --- synapse/app/_base.py | 3 ++ synapse/config/homeserver.py | 2 + synapse/config/tracer.py | 80 ++++++++++++++++++++++++++++++++++++ 3 files changed, 85 insertions(+) create mode 100644 synapse/config/tracer.py diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 8cc990399f8f..2559a6c3f8ca 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -278,6 +278,9 @@ def handle_sighup(*args, **kwargs): # Load the certificate from disk. refresh_certificate(hs) + # Start the tracer + synapse.config.tracer.init_tracing(hs.config) + # It is now safe to start your Synapse. hs.start_listening(listeners) hs.get_datastore().start_profiling() diff --git a/synapse/config/homeserver.py b/synapse/config/homeserver.py index acadef4fd316..72acad4f1895 100644 --- a/synapse/config/homeserver.py +++ b/synapse/config/homeserver.py @@ -40,6 +40,7 @@ from .stats import StatsConfig from .third_party_event_rules import ThirdPartyRulesConfig from .tls import TlsConfig +from .tracer import TracerConfig from .user_directory import UserDirectoryConfig from .voip import VoipConfig from .workers import WorkerConfig @@ -75,5 +76,6 @@ class HomeServerConfig( ServerNoticesConfig, RoomDirectoryConfig, ThirdPartyRulesConfig, + TracerConfig, ): pass diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py new file mode 100644 index 000000000000..fc6227ad197e --- /dev/null +++ b/synapse/config/tracer.py @@ -0,0 +1,80 @@ +# -*- coding: utf-8 -*- +# Copyright 2018 New Vector Ltd +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from ._base import Config +from jaeger_client import Config as JaegerConfig +from synapse.util.scopecontextmanager import LogContextScopeManager + +import logging +logger = logging.getLogger(__name__) + +class TracerConfig(Config): + def read_config(self, config): + self.tracer_config = config.get("tracer") + + if self.tracer_config is None: + # If the tracer is not configured we assume it is disabled + self.tracer_config = { + "tracer_enabled": False, + } + + if not self.tracer_config.get("tracer_enabled", False): + # The tracer is enabled so sanitize the config + # If no whitelists are given + self.tracer_config.setdefault("user_whitelist", ["*"]) + self.tracer_config.setdefault("homeserver_whitelist", ["*"]) + + if type(self.tracer_config.get("user_whitelist")) != list: + raise RuntimeError("Tracer user_whitelist config is malformed") + if type(self.tracer_config.get("homeserver_whitelist")) != list: + raise RuntimeError("Tracer homesererver_whitelist config is malformed") + + def default_config(self, **kwargs): + return """\ + ## Tracert ## + + tracer: + # The list of users who's requests will be traced + # The list is a list of regex which is matched against the user_id + user_whitelist: + - "*" + # The list of homeservers we wish to trace across + # The list is a list of regex which is matched against the homeserver name + homeserver_whitelist: + - "*" + """ + +def init_tracing(config): + """Initialise the JaegerClient tracer + + Args: + config (Config) + The config used by the homserver. Here it's used to set the service + name to the homeserver's. + """ + + jaeger_config = JaegerConfig( + config={ + 'sampler': { + 'type': 'const', + 'param': 1, + }, + 'logging': True, + }, + service_name=config.server_name + "_new", + scope_manager=LogContextScopeManager(config), + ) + + return jaeger_config.initialize_tracer() \ No newline at end of file From b43e3af7449dcfdc61d0f3fd1e72f750cd187af4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 21 Jun 2019 12:10:20 +0100 Subject: [PATCH 02/69] Scope manager using LogContexts We piggy-back our tracer scopes by using log context. The current log context gives us the current scope. If new scope is created we create a stack of scopes in the context. --- synapse/util/logcontext.py | 8 ++- synapse/util/scopecontextmanager.py | 87 +++++++++++++++++++++++++++++ 2 files changed, 93 insertions(+), 2 deletions(-) create mode 100644 synapse/util/scopecontextmanager.py diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index fe412355d858..62ffc36f60e9 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -164,6 +164,7 @@ class LoggingContext(object): "usage_start", "main_thread", "alive", "request", "tag", + "active_scope" ] thread_local = threading.local() @@ -215,6 +216,7 @@ def __init__(self, name=None, parent_context=None, request=None): self.request = None self.tag = "" self.alive = True + self.active_scope = None self.parent_context = parent_context @@ -299,10 +301,12 @@ def copy_to(self, record): another LoggingContext """ - # 'request' is the only field we currently use in the logger, so that's - # all we need to copy + # we track the current request record.request = self.request + # we also track the current active_scope: + record.active_scope = self.active_scope + def start(self): if threading.current_thread() is not self.main_thread: logger.warning("Started logcontext %s on different thread", self) diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py new file mode 100644 index 000000000000..370210eb4442 --- /dev/null +++ b/synapse/util/scopecontextmanager.py @@ -0,0 +1,87 @@ +from .logcontext import LoggingContext +from opentracing import ScopeManager, Scope +import logging + +logger = logging.getLogger(__name__) + +class LogContextScopeManager(ScopeManager): + + _homeserver_whitelist = ["*"] + _user_whitelist = ["*"] + + def __init__(self, config): + # Set the whitelists + logger.info(config.tracer_config) + _homeserver_whitelist = config.tracer_config["homeserver_whitelist"] + _user_whitelist = config.tracer_config["user_whitelist"] + + @property + def active(self): + """ + Returns the currently active Scope which can be used to access the + currently active Scope.span. + If there is a non-null Scope, its wrapped Span + becomes an implicit parent of any newly-created Span at + Tracer.start_active_span() time. + + Return: + (Scope) : the Scope that is active, or None if not + available. + """ + ctx = LoggingContext.current_context() + if ctx is LoggingContext.sentinel or ctx.active_scope is None: + return None + else: + return ctx.active_scope + + def activate(self, span, finish_on_close): + """ + Makes a Span active. + Args + span (Span): the span that should become active. + finish_on_close (Boolean): whether Span should be automatically + finished when Scope.close() is called. + + Return: + Scope to control the end of the active period for + *span*. It is a programming error to neglect to call + Scope.close() on the returned instance. + """ + logger.info("activating scope") + ctx = LoggingContext.current_context() + if ctx is LoggingContext.sentinel: + # We don't want this scope to affect. + logger.warning("Tried to activate scope outside of loggingcontext") + return Scope(None, span) + + scope = _LogContextScope(self, span, finish_on_close) + self._set_logcontext_scope(scope, ctx) + return scope + + def _set_logcontext_scope(self, scope, ctx=None): + if ctx is None: + ctx = LoggingContext.current_context() + + ctx.active_scope = scope + + def request_from_whitelisted_homeserver(self, request): + pass + + def user_whitelisted(self, request): + pass + +class _LogContextScope(Scope): + def __init__(self, manager, span, finish_on_close): + super(_LogContextScope, self).__init__(manager, span) + self._finish_on_close = finish_on_close + self._to_restore = manager.active + + def close(self): + if self.manager.active is not self: + logger.warning("Tried to close a none active scope!") + return + + self.manager._set_logcontext_scope(self._to_restore) + + if self._finish_on_close: + self.span.finish() \ No newline at end of file From 297c5fe0a2dfff582eee47ee542af32dcef391b8 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 21 Jun 2019 12:11:15 +0100 Subject: [PATCH 03/69] jaeger is a dependency now --- synapse/python_dependencies.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/synapse/python_dependencies.py b/synapse/python_dependencies.py index 11ace2bfb17f..4b697b0b2b61 100644 --- a/synapse/python_dependencies.py +++ b/synapse/python_dependencies.py @@ -77,6 +77,9 @@ "attrs>=17.4.0", "netaddr>=0.7.18", + + # Opentracing + "jaeger-client>=4.0.0", ] CONDITIONAL_REQUIREMENTS = { From 45d412e67dc1713e26f58d45595311afc1633fbd Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 21 Jun 2019 12:11:53 +0100 Subject: [PATCH 04/69] Carrier inject and extraction for Twisted Headers --- synapse/util/tracerutils.py | 47 +++++++++++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+) create mode 100644 synapse/util/tracerutils.py diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py new file mode 100644 index 000000000000..14b54e46c309 --- /dev/null +++ b/synapse/util/tracerutils.py @@ -0,0 +1,47 @@ +from opentracing.propagation import Format +import opentracing + +from .logcontext import LoggingContext + +def extract_span_context(headers): + """ + Extracts a span context from Twisted Headers. + args: + headers (twisted.web.http_headers.Headers) + returns: + span_context (opentracing.span.SpanContext) + """ + # Twisted encodes the values as lists whereas opentracing doesn't. + # So, we take the first item in the list. + # Also, twisted uses byte arrays while opentracing expects strings. + header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} + return opentracing.tracer.extract(Format.HTTP_HEADERS, header_dict) + + +def inject_span_context(headers, span): + """ + Injects a span context into twisted headers inplace + args: + headers (twisted.web.http_headers.Headers) + span (opentracing.Span) + + note: + The headers set by the tracer are custom to the tracer implementation which + should be unique enough that they don't interfere with any headers set by + synapse or twisted. If we're still using jaeger these headers would be those + here: + https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py + """ + carrier = {} + carrier = opentracing.tracer.inject(span, Format.HTTP_HEADERS, {}) + + for key, value in carrier: + headers.addRawHeaders(key, value) + +# TODO: Implement whitelisting +def request_from_whitelisted_homeserver(request): + pass + +# TODO: Implement whitelisting +def user_whitelisted(request): + pass \ No newline at end of file From fc069fee9c3a909597a2b529670d6be121ca458a Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 21 Jun 2019 12:18:51 +0100 Subject: [PATCH 05/69] Trace federation requests on the way in and out. The span is created in _started_processing and closed in _finished_processing because we need a meaningful log context. --- synapse/http/matrixfederationclient.py | 35 +++++++++++++++++++++----- synapse/http/site.py | 29 ++++++++++++++++++++- 2 files changed, 57 insertions(+), 7 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 663ea72a7a3a..5f546ba27cdb 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -52,6 +52,9 @@ from synapse.util.logcontext import make_deferred_yieldable from synapse.util.metrics import Measure +import opentracing +from opentracing.propagation import Format + logger = logging.getLogger(__name__) outgoing_requests_counter = Counter("synapse_http_matrixfederationclient_requests", @@ -350,11 +353,26 @@ def _send_request( else: query_bytes = b"" - headers_dict = { - b"User-Agent": [self.version_string_bytes], - } - - with limiter: + # Retreive current span + scope = opentracing.tracer.start_active_span( + "outgoing-federation-request", + tags={ + "span.kind": "client", # With respect to this request's role in an rpc + "peer.address": request.destination, + "http.method": request.method, + "http.url": request.path, + }, + finish_on_close=True + ) + + # Inject the span into the headers + headers_dict = {} + opentracing.tracer.inject(scope.span, Format.HTTP_HEADERS, headers_dict) + headers_dict = {k.encode(): [v.encode()] for k, v in headers_dict.items()} + + headers_dict[b"User-Agent"] = [self.version_string_bytes] + + with limiter, scope: # XXX: Would be much nicer to retry only at the transaction-layer # (once we have reliable transactions in place) if long_retries: @@ -433,6 +451,9 @@ def _send_request( response.phrase.decode('ascii', errors='replace'), ) + logger.info("Setting response code on span {} *********".format(opentracing.tracer.active_span)) + scope.span.set_tag( + "http.status_code", response.code) if 200 <= response.code < 300: pass else: @@ -516,9 +537,11 @@ def _send_request( url_str, _flatten_response_never_received(e), ) + logger.info("Setting response code on span {} *********".format(opentracing.tracer.active_span)) + #scope.span.set_tag("error", True) raise - defer.returnValue(response) + defer.returnValue(response) def build_auth_headers( self, destination, method, url_bytes, content=None, destination_is=None, diff --git a/synapse/http/site.py b/synapse/http/site.py index e508c0bd4f2d..104f992fcfbd 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -14,12 +14,14 @@ import contextlib import logging import time +import opentracing from twisted.web.server import Request, Site from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext +from synapse.util.tracerutils import extract_span_context logger = logging.getLogger(__name__) @@ -211,6 +213,7 @@ def _started_processing(self, servlet_name): This will log the request's arrival. Once the request completes, be sure to call finished_processing. + It will also start a span for this request. Args: servlet_name (str): the name of the servlet which will be @@ -233,6 +236,20 @@ def _started_processing(self, servlet_name): self.get_redacted_uri() ) + # Start a span + span_context = extract_span_context(self.requestHeaders) + opentracing.tracer.start_active_span( + "incoming-federation-request", + tags={ + "request_id": self.get_request_id(), + "span.kind": "server", + "http.method": self.get_method(), + "http.url": self.get_redacted_uri(), + "peer.ipv6": self.getClientIP(), + }, + child_of=span_context + ) + def _finished_processing(self): """Log the completion of this request and update the metrics """ @@ -252,7 +269,7 @@ def _finished_processing(self): # the time between receiving the request and the request handler finishing processing_time = self._processing_finished_time - self.start_time - # the time between the request handler finishing and the response being sent + # the time between the reb'\x80\x03ctwisted.web.http_headers\nHeaders\nq\x00)\x81q\x01}q\x02X\x0b\x00\x00\x00_rawHeadersq\x03}q\x04(C\x04hostq\x05]q\x06C\x0elocalhost:8081q\x07aC\nuser-agentq\x08]q\tCLMozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:67.0) Gecko/20100101 Firefox/67.0q\naC\x06acceptq\x0b]q\x0cC\x10application/jsonq\raC\x0faccept-languageq\x0e]q\x0fC\x0een-GB,en;q=0.5q\x10aC\x0faccept-encodingq\x11]q\x12C\rgzip, deflateq\x13aC\x06originq\x14]q\x15C\x04nullq\x16aC\nconnectionq\x17]q\x18C\nkeep-aliveq\x19ausb.'quest handler finishing and the response being sent # to the client (nb may be negative) response_send_time = self.finish_time - self._processing_finished_time @@ -302,6 +319,16 @@ def _finished_processing(self): usage.evt_db_fetch_count, ) + scope = opentracing.tracer.scope_manager.active + if scope is not None: + # TODO: Remove this, it's just for debug and relies on implementation + # specific details of the jaeger_tracer + tags = {t.key: t.vStr for t in scope.span.tags} + assert(tags['request_id'] == self.get_request_id()) + # finish the span if it's there. + scope.span.set_tag("peer.address", authenticated_entity) + scope.close() + try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) except Exception as e: From 227447dc7effe8de95ceba410844b6d60b3d15d4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 21 Jun 2019 15:41:28 +0100 Subject: [PATCH 06/69] Create logcontext for new scope. Instead of having a stack of scopes in a logcontext we create a new context for a new scope if the current logcontext already has a scope. --- synapse/util/logcontext.py | 8 +++--- synapse/util/scopecontextmanager.py | 39 ++++++++++++++++------------- 2 files changed, 26 insertions(+), 21 deletions(-) diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 62ffc36f60e9..e40e2825e0a1 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -164,7 +164,7 @@ class LoggingContext(object): "usage_start", "main_thread", "alive", "request", "tag", - "active_scope" + "scope" ] thread_local = threading.local() @@ -216,7 +216,7 @@ def __init__(self, name=None, parent_context=None, request=None): self.request = None self.tag = "" self.alive = True - self.active_scope = None + self.scope = None self.parent_context = parent_context @@ -304,8 +304,8 @@ def copy_to(self, record): # we track the current request record.request = self.request - # we also track the current active_scope: - record.active_scope = self.active_scope + # we also track the current scope: + record.scope = self.scope def start(self): if threading.current_thread() is not self.main_thread: diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 370210eb4442..2b5b491f309e 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -1,4 +1,4 @@ -from .logcontext import LoggingContext +from .logcontext import LoggingContext, nested_logging_context from opentracing import ScopeManager, Scope import logging @@ -29,10 +29,10 @@ def active(self): available. """ ctx = LoggingContext.current_context() - if ctx is LoggingContext.sentinel or ctx.active_scope is None: + if ctx is LoggingContext.sentinel: return None else: - return ctx.active_scope + return ctx.scope def activate(self, span, finish_on_close): """ @@ -47,23 +47,20 @@ def activate(self, span, finish_on_close): *span*. It is a programming error to neglect to call Scope.close() on the returned instance. """ - logger.info("activating scope") + + enter_logcontext = False ctx = LoggingContext.current_context() if ctx is LoggingContext.sentinel: # We don't want this scope to affect. logger.warning("Tried to activate scope outside of loggingcontext") return Scope(None, span) - - scope = _LogContextScope(self, span, finish_on_close) - self._set_logcontext_scope(scope, ctx) + elif ctx.scope is not None: + ctx = nested_logging_context("scope") + enter_logcontext = True + scope = _LogContextScope(self, span, ctx, enter_logcontext, finish_on_close) + ctx.scope = scope return scope - def _set_logcontext_scope(self, scope, ctx=None): - if ctx is None: - ctx = LoggingContext.current_context() - - ctx.active_scope = scope - def request_from_whitelisted_homeserver(self, request): pass @@ -71,17 +68,25 @@ def user_whitelisted(self, request): pass class _LogContextScope(Scope): - def __init__(self, manager, span, finish_on_close): + def __init__(self, manager, span, logcontext, enter_logcontext, finish_on_close): super(_LogContextScope, self).__init__(manager, span) + self.logcontext = logcontext self._finish_on_close = finish_on_close - self._to_restore = manager.active + self._enter_logcontext = enter_logcontext + + def __enter__(self): + if self._enter_logcontext: + self.logcontext.__enter__() + + def __exit__(self, type, value, traceback): + super(_LogContextScope, self).__exit__(type, value, traceback) + if self._enter_logcontext: + self.logcontext.__exit__(type, value, traceback) def close(self): if self.manager.active is not self: logger.warning("Tried to close a none active scope!") return - self.manager._set_logcontext_scope(self._to_restore) - if self._finish_on_close: self.span.finish() \ No newline at end of file From f35bde389207743568a08af814d11ca5f165191a Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:01:33 +0100 Subject: [PATCH 07/69] Remove scope from logcontext if logcontext is top level --- synapse/http/site.py | 4 ++-- synapse/util/scopecontextmanager.py | 8 +++++++- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 104f992fcfbd..656299198f4a 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -238,7 +238,7 @@ def _started_processing(self, servlet_name): # Start a span span_context = extract_span_context(self.requestHeaders) - opentracing.tracer.start_active_span( + span = opentracing.tracer.start_active_span( "incoming-federation-request", tags={ "request_id": self.get_request_id(), @@ -327,7 +327,7 @@ def _finished_processing(self): assert(tags['request_id'] == self.get_request_id()) # finish the span if it's there. scope.span.set_tag("peer.address", authenticated_entity) - scope.close() + scope.__exit__(None, None, None) try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 2b5b491f309e..a4fbd28e1932 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -50,13 +50,17 @@ def activate(self, span, finish_on_close): enter_logcontext = False ctx = LoggingContext.current_context() + if ctx is LoggingContext.sentinel: # We don't want this scope to affect. logger.warning("Tried to activate scope outside of loggingcontext") return Scope(None, span) elif ctx.scope is not None: - ctx = nested_logging_context("scope") + # We want the logging scope to look exactly the same so we give it + # a blank suffix + ctx = nested_logging_context("") enter_logcontext = True + scope = _LogContextScope(self, span, ctx, enter_logcontext, finish_on_close) ctx.scope = scope return scope @@ -82,6 +86,8 @@ def __exit__(self, type, value, traceback): super(_LogContextScope, self).__exit__(type, value, traceback) if self._enter_logcontext: self.logcontext.__exit__(type, value, traceback) + else: # the logcontext existed before the creation of the scope + self.logcontext.scope = None def close(self): if self.manager.active is not self: From 7d9c3d341fc4f8ff8ee1825645de9d5432a15a14 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:13:46 +0100 Subject: [PATCH 08/69] Disable tracer if not configured --- synapse/config/tracer.py | 30 ++++++++++++++++++++---------- 1 file changed, 20 insertions(+), 10 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index fc6227ad197e..388dbfa1362b 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -65,16 +65,26 @@ def init_tracing(config): name to the homeserver's. """ - jaeger_config = JaegerConfig( - config={ - 'sampler': { - 'type': 'const', - 'param': 1, + if config.tracer_config.get("tracer_enabled", False): + jaeger_config = JaegerConfig( + config={ + 'sampler': { + 'type': 'const', + 'param': 1, + }, + 'logging': True, }, - 'logging': True, - }, - service_name=config.server_name + "_new", - scope_manager=LogContextScopeManager(config), - ) + service_name=config.server_name + "_new", + scope_manager=LogContextScopeManager(config), + ) + else: # The tracer is not configured so we instantiate a noop tracer + jaeger_config = JaegerConfig( + config={ + 'sampler': { + 'type': 'const', + 'param': 0, + } + } + ) return jaeger_config.initialize_tracer() \ No newline at end of file From 37607eb5ad6db25d15657472bb5dd1efddcde030 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:19:16 +0100 Subject: [PATCH 09/69] typo --- synapse/config/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 388dbfa1362b..9c60b43f9bb5 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -43,7 +43,7 @@ def read_config(self, config): def default_config(self, **kwargs): return """\ - ## Tracert ## + ## Tracer ## tracer: # The list of users who's requests will be traced From ee2f21f09a7413fbf37e73aac8c177d8caacc3e3 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:42:39 +0100 Subject: [PATCH 10/69] Remove dependence on jaeger internals --- synapse/http/site.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 656299198f4a..4ab117aa4bce 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -321,10 +321,6 @@ def _finished_processing(self): scope = opentracing.tracer.scope_manager.active if scope is not None: - # TODO: Remove this, it's just for debug and relies on implementation - # specific details of the jaeger_tracer - tags = {t.key: t.vStr for t in scope.span.tags} - assert(tags['request_id'] == self.get_request_id()) # finish the span if it's there. scope.span.set_tag("peer.address", authenticated_entity) scope.__exit__(None, None, None) From ed5d00f280b573d90a3942d64f82986fe8b9ca06 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:44:32 +0100 Subject: [PATCH 11/69] bools --- synapse/config/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 9c60b43f9bb5..aea8823b5eb9 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -30,7 +30,7 @@ def read_config(self, config): "tracer_enabled": False, } - if not self.tracer_config.get("tracer_enabled", False): + if self.tracer_config.get("tracer_enabled", False): # The tracer is enabled so sanitize the config # If no whitelists are given self.tracer_config.setdefault("user_whitelist", ["*"]) From a69e6aad77f97ecb11a9b61272ec4efa9ce0d7f0 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:44:47 +0100 Subject: [PATCH 12/69] Set service name --- synapse/config/tracer.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index aea8823b5eb9..b17bc7fddd57 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -74,7 +74,7 @@ def init_tracing(config): }, 'logging': True, }, - service_name=config.server_name + "_new", + service_name=config.server_name, scope_manager=LogContextScopeManager(config), ) else: # The tracer is not configured so we instantiate a noop tracer @@ -84,7 +84,8 @@ def init_tracing(config): 'type': 'const', 'param': 0, } - } + }, + service_name=config.server_name ) return jaeger_config.initialize_tracer() \ No newline at end of file From 6a6f97add9ade90c4d70a3e8e4b207e3fe81c626 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 24 Jun 2019 16:50:01 +0100 Subject: [PATCH 13/69] :Explicitely state that the tracer is disabled --- synapse/config/tracer.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index b17bc7fddd57..b4262af6f9bf 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -46,6 +46,8 @@ def default_config(self, **kwargs): ## Tracer ## tracer: + # Enable / disable tracer + tracer_enabled: false # The list of users who's requests will be traced # The list is a list of regex which is matched against the user_id user_whitelist: From 98c8038bcf4cad9fd167809857ccb218b068b0ce Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 10:21:16 +0100 Subject: [PATCH 14/69] Black is the new black --- synapse/config/tracer.py | 38 ++++++++++---------------- synapse/http/matrixfederationclient.py | 5 ++-- synapse/http/site.py | 5 ++-- synapse/util/scopecontextmanager.py | 12 +++++--- synapse/util/tracerutils.py | 13 +++++---- 5 files changed, 36 insertions(+), 37 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index b4262af6f9bf..dbcc691d6969 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -13,26 +13,28 @@ # See the License for the specific language governing permissions and # limitations under the License. -from ._base import Config +import logging + from jaeger_client import Config as JaegerConfig + from synapse.util.scopecontextmanager import LogContextScopeManager -import logging +from ._base import Config + logger = logging.getLogger(__name__) + class TracerConfig(Config): def read_config(self, config): self.tracer_config = config.get("tracer") if self.tracer_config is None: # If the tracer is not configured we assume it is disabled - self.tracer_config = { - "tracer_enabled": False, - } - + self.tracer_config = {"tracer_enabled": False} + if self.tracer_config.get("tracer_enabled", False): # The tracer is enabled so sanitize the config - # If no whitelists are given + # If no whitelists are given self.tracer_config.setdefault("user_whitelist", ["*"]) self.tracer_config.setdefault("homeserver_whitelist", ["*"]) @@ -58,6 +60,7 @@ def default_config(self, **kwargs): - "*" """ + def init_tracing(config): """Initialise the JaegerClient tracer @@ -69,25 +72,14 @@ def init_tracing(config): if config.tracer_config.get("tracer_enabled", False): jaeger_config = JaegerConfig( - config={ - 'sampler': { - 'type': 'const', - 'param': 1, - }, - 'logging': True, - }, + config={"sampler": {"type": "const", "param": 1}, "logging": True}, service_name=config.server_name, scope_manager=LogContextScopeManager(config), ) - else: # The tracer is not configured so we instantiate a noop tracer + else: # The tracer is not configured so we instantiate a noop tracer jaeger_config = JaegerConfig( - config={ - 'sampler': { - 'type': 'const', - 'param': 0, - } - }, - service_name=config.server_name + config={"sampler": {"type": "const", "param": 0}}, + service_name=config.server_name, ) - return jaeger_config.initialize_tracer() \ No newline at end of file + return jaeger_config.initialize_tracer() diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 51afb358910a..afaa8178e480 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -23,8 +23,10 @@ from six.moves import urllib import attr +import opentracing import treq from canonicaljson import encode_canonical_json +from opentracing.propagation import Format from prometheus_client import Counter from signedjson.sign import sign_json from zope.interface import implementer @@ -52,9 +54,6 @@ from synapse.util.logcontext import make_deferred_yieldable from synapse.util.metrics import Measure -import opentracing -from opentracing.propagation import Format - logger = logging.getLogger(__name__) outgoing_requests_counter = Counter( diff --git a/synapse/http/site.py b/synapse/http/site.py index 775cc02f4217..7ed8ca819c31 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -14,6 +14,7 @@ import contextlib import logging import time + import opentracing from twisted.web.server import Request, Site @@ -21,7 +22,7 @@ from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext -from synapse.util.tracerutils import extract_span_context +from synapse.util.tracerutils import extract_span_context logger = logging.getLogger(__name__) @@ -247,7 +248,7 @@ def _started_processing(self, servlet_name): "http.url": self.get_redacted_uri(), "peer.ipv6": self.getClientIP(), }, - child_of=span_context + child_of=span_context, ) def _finished_processing(self): diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index a4fbd28e1932..177eda204668 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -1,9 +1,12 @@ -from .logcontext import LoggingContext, nested_logging_context -from opentracing import ScopeManager, Scope import logging +from opentracing import Scope, ScopeManager + +from .logcontext import LoggingContext, nested_logging_context + logger = logging.getLogger(__name__) + class LogContextScopeManager(ScopeManager): _homeserver_whitelist = ["*"] @@ -71,6 +74,7 @@ def request_from_whitelisted_homeserver(self, request): def user_whitelisted(self, request): pass + class _LogContextScope(Scope): def __init__(self, manager, span, logcontext, enter_logcontext, finish_on_close): super(_LogContextScope, self).__init__(manager, span) @@ -86,7 +90,7 @@ def __exit__(self, type, value, traceback): super(_LogContextScope, self).__exit__(type, value, traceback) if self._enter_logcontext: self.logcontext.__exit__(type, value, traceback) - else: # the logcontext existed before the creation of the scope + else: # the logcontext existed before the creation of the scope self.logcontext.scope = None def close(self): @@ -95,4 +99,4 @@ def close(self): return if self._finish_on_close: - self.span.finish() \ No newline at end of file + self.span.finish() diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 14b54e46c309..93f305e13eb0 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -1,8 +1,9 @@ -from opentracing.propagation import Format import opentracing +from opentracing.propagation import Format from .logcontext import LoggingContext + def extract_span_context(headers): """ Extracts a span context from Twisted Headers. @@ -13,10 +14,10 @@ def extract_span_context(headers): """ # Twisted encodes the values as lists whereas opentracing doesn't. # So, we take the first item in the list. - # Also, twisted uses byte arrays while opentracing expects strings. + # Also, twisted uses byte arrays while opentracing expects strings. header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} return opentracing.tracer.extract(Format.HTTP_HEADERS, header_dict) - + def inject_span_context(headers, span): """ @@ -34,14 +35,16 @@ def inject_span_context(headers, span): """ carrier = {} carrier = opentracing.tracer.inject(span, Format.HTTP_HEADERS, {}) - + for key, value in carrier: headers.addRawHeaders(key, value) + # TODO: Implement whitelisting def request_from_whitelisted_homeserver(request): pass + # TODO: Implement whitelisting def user_whitelisted(request): - pass \ No newline at end of file + pass From 889afc11a092e1b6a943ae1ef4af76fcbf7269cc Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 10:22:53 +0100 Subject: [PATCH 15/69] Newsfile --- changelog.d/5544.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/5544.misc diff --git a/changelog.d/5544.misc b/changelog.d/5544.misc new file mode 100644 index 000000000000..81d6f74c31c8 --- /dev/null +++ b/changelog.d/5544.misc @@ -0,0 +1 @@ +Added opentracing and configuration options. From db10eeb26708d44d6fe20c6013743dfe4fe598ad Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 10:28:46 +0100 Subject: [PATCH 16/69] Code style --- synapse/config/tracer.py | 2 +- synapse/http/site.py | 2 +- synapse/util/scopecontextmanager.py | 10 +++++----- synapse/util/tracerutils.py | 4 +--- 4 files changed, 8 insertions(+), 10 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index dbcc691d6969..84253d5d89e9 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -54,7 +54,7 @@ def default_config(self, **kwargs): # The list is a list of regex which is matched against the user_id user_whitelist: - "*" - # The list of homeservers we wish to trace across + # The list of homeservers we wish to trace across # The list is a list of regex which is matched against the homeserver name homeserver_whitelist: - "*" diff --git a/synapse/http/site.py b/synapse/http/site.py index 7ed8ca819c31..887b7701adde 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -239,7 +239,7 @@ def _started_processing(self, servlet_name): # Start a span span_context = extract_span_context(self.requestHeaders) - span = opentracing.tracer.start_active_span( + opentracing.tracer.start_active_span( "incoming-federation-request", tags={ "request_id": self.get_request_id(), diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 177eda204668..905a1b319bc3 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -15,8 +15,8 @@ class LogContextScopeManager(ScopeManager): def __init__(self, config): # Set the whitelists logger.info(config.tracer_config) - _homeserver_whitelist = config.tracer_config["homeserver_whitelist"] - _user_whitelist = config.tracer_config["user_whitelist"] + self._homeserver_whitelist = config.tracer_config["homeserver_whitelist"] + self._user_whitelist = config.tracer_config["user_whitelist"] @property def active(self): @@ -27,7 +27,7 @@ def active(self): becomes an implicit parent of any newly-created Span at Tracer.start_active_span() time. - Return: + Return: (Scope) : the Scope that is active, or None if not available. """ @@ -44,8 +44,8 @@ def activate(self, span, finish_on_close): span (Span): the span that should become active. finish_on_close (Boolean): whether Span should be automatically finished when Scope.close() is called. - - Return: + + Return: Scope to control the end of the active period for *span*. It is a programming error to neglect to call Scope.close() on the returned instance. diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 93f305e13eb0..f4fc96b445c3 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -1,8 +1,6 @@ import opentracing from opentracing.propagation import Format -from .logcontext import LoggingContext - def extract_span_context(headers): """ @@ -30,7 +28,7 @@ def inject_span_context(headers, span): The headers set by the tracer are custom to the tracer implementation which should be unique enough that they don't interfere with any headers set by synapse or twisted. If we're still using jaeger these headers would be those - here: + here: https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ carrier = {} From 4e1eaf2b470b4687b0d7390ef882b9d385c017bd Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 11:03:24 +0100 Subject: [PATCH 17/69] Use the new config setup. --- synapse/config/tracer.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 84253d5d89e9..5eab97ef8ae0 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -25,7 +25,7 @@ class TracerConfig(Config): - def read_config(self, config): + def read_config(self, config, **kwargs): self.tracer_config = config.get("tracer") if self.tracer_config is None: @@ -43,7 +43,7 @@ def read_config(self, config): if type(self.tracer_config.get("homeserver_whitelist")) != list: raise RuntimeError("Tracer homesererver_whitelist config is malformed") - def default_config(self, **kwargs): + def generate_config_section(cls, **kwargs): return """\ ## Tracer ## From 8ca185d818d086816fd6a4b86d1cf392374680cf Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 13:59:52 +0100 Subject: [PATCH 18/69] Generate config. --- docs/sample_config.yaml | 15 +++++++++++++++ synapse/config/tracer.py | 22 +++++++++++----------- 2 files changed, 26 insertions(+), 11 deletions(-) diff --git a/docs/sample_config.yaml b/docs/sample_config.yaml index da10788e96c3..5861861c616c 100644 --- a/docs/sample_config.yaml +++ b/docs/sample_config.yaml @@ -1352,3 +1352,18 @@ password_config: # module: "my_custom_project.SuperRulesSet" # config: # example_option: 'things' + + +## Tracer ## + +#tracer: +# # Enable / disable tracer +# tracer_enabled: false +# # The list of users who's requests will be traced +# # The list is a list of regex which is matched against the user_id +# user_whitelist: +# - "*" +# # The list of homeservers we wish to trace across +# # The list is a list of regex which is matched against the homeserver name +# homeserver_whitelist: +# - "*" diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 5eab97ef8ae0..9df9f9c64e11 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -47,17 +47,17 @@ def generate_config_section(cls, **kwargs): return """\ ## Tracer ## - tracer: - # Enable / disable tracer - tracer_enabled: false - # The list of users who's requests will be traced - # The list is a list of regex which is matched against the user_id - user_whitelist: - - "*" - # The list of homeservers we wish to trace across - # The list is a list of regex which is matched against the homeserver name - homeserver_whitelist: - - "*" + #tracer: + # # Enable / disable tracer + # tracer_enabled: false + # # The list of users who's requests will be traced + # # The list is a list of regex which is matched against the user_id + # user_whitelist: + # - "*" + # # The list of homeservers we wish to trace across + # # The list is a list of regex which is matched against the homeserver name + # homeserver_whitelist: + # - "*" """ From 0009fdd3adbcd52ef5628800e3f8a04ca4c9b9d2 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 14:19:39 +0100 Subject: [PATCH 19/69] Copyright --- synapse/config/tracer.py | 2 +- synapse/util/scopecontextmanager.py | 15 +++++++++++++++ synapse/util/tracerutils.py | 15 +++++++++++++++ 3 files changed, 31 insertions(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 9df9f9c64e11..f05c44aa7bf6 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -1,5 +1,5 @@ # -*- coding: utf-8 -*- -# Copyright 2018 New Vector Ltd +# Copyright 2019 The Matrix.org Foundation C.I.C.d # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 905a1b319bc3..abcabf0fca3c 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -1,3 +1,18 @@ +# -*- coding: utf-8 -*- +# Copyright 2019 The Matrix.org Foundation C.I.C.d +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License.import logging + import logging from opentracing import Scope, ScopeManager diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index f4fc96b445c3..5ba4cfe38a53 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -1,3 +1,18 @@ +# -*- coding: utf-8 -*- +# Copyright 2019 The Matrix.org Foundation C.I.C.d +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License.import opentracing + import opentracing from opentracing.propagation import Format From e90bfa72fa926f021ff9b6acd3e9d733c0a81c1b Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:14:08 +0100 Subject: [PATCH 20/69] Rename config to opentracing --- synapse/config/tracer.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index f05c44aa7bf6..dac37a4e4a3b 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -26,7 +26,7 @@ class TracerConfig(Config): def read_config(self, config, **kwargs): - self.tracer_config = config.get("tracer") + self.tracer_config = config.get("opentracing") if self.tracer_config is None: # If the tracer is not configured we assume it is disabled @@ -45,9 +45,9 @@ def read_config(self, config, **kwargs): def generate_config_section(cls, **kwargs): return """\ - ## Tracer ## + ## Opentracing ## - #tracer: + #opentracing: # # Enable / disable tracer # tracer_enabled: false # # The list of users who's requests will be traced From 640381e8814b467ae006361cd52b681b8051491f Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:17:02 +0100 Subject: [PATCH 21/69] Remove user whitelisting --- synapse/config/tracer.py | 7 ------- synapse/util/scopecontextmanager.py | 5 ----- 2 files changed, 12 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index dac37a4e4a3b..b948317edc1c 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -35,11 +35,8 @@ def read_config(self, config, **kwargs): if self.tracer_config.get("tracer_enabled", False): # The tracer is enabled so sanitize the config # If no whitelists are given - self.tracer_config.setdefault("user_whitelist", ["*"]) self.tracer_config.setdefault("homeserver_whitelist", ["*"]) - if type(self.tracer_config.get("user_whitelist")) != list: - raise RuntimeError("Tracer user_whitelist config is malformed") if type(self.tracer_config.get("homeserver_whitelist")) != list: raise RuntimeError("Tracer homesererver_whitelist config is malformed") @@ -50,10 +47,6 @@ def generate_config_section(cls, **kwargs): #opentracing: # # Enable / disable tracer # tracer_enabled: false - # # The list of users who's requests will be traced - # # The list is a list of regex which is matched against the user_id - # user_whitelist: - # - "*" # # The list of homeservers we wish to trace across # # The list is a list of regex which is matched against the homeserver name # homeserver_whitelist: diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index abcabf0fca3c..dd226df272c5 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -25,13 +25,11 @@ class LogContextScopeManager(ScopeManager): _homeserver_whitelist = ["*"] - _user_whitelist = ["*"] def __init__(self, config): # Set the whitelists logger.info(config.tracer_config) self._homeserver_whitelist = config.tracer_config["homeserver_whitelist"] - self._user_whitelist = config.tracer_config["user_whitelist"] @property def active(self): @@ -86,9 +84,6 @@ def activate(self, span, finish_on_close): def request_from_whitelisted_homeserver(self, request): pass - def user_whitelisted(self, request): - pass - class _LogContextScope(Scope): def __init__(self, manager, span, logcontext, enter_logcontext, finish_on_close): From 0f57aac732eb3993b22e7785d5212c9504ba4fce Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:18:16 +0100 Subject: [PATCH 22/69] Empty whitelist by default --- synapse/config/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index b948317edc1c..01c180726f9d 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -35,7 +35,7 @@ def read_config(self, config, **kwargs): if self.tracer_config.get("tracer_enabled", False): # The tracer is enabled so sanitize the config # If no whitelists are given - self.tracer_config.setdefault("homeserver_whitelist", ["*"]) + self.tracer_config.setdefault("homeserver_whitelist", []) if type(self.tracer_config.get("homeserver_whitelist")) != list: raise RuntimeError("Tracer homesererver_whitelist config is malformed") From dd2f06d4d97a989116cca36a567b4d28a1a90a7b Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:27:35 +0100 Subject: [PATCH 23/69] User ConfigError instead of RuntimeError --- synapse/config/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 01c180726f9d..84bcee972260 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -38,7 +38,7 @@ def read_config(self, config, **kwargs): self.tracer_config.setdefault("homeserver_whitelist", []) if type(self.tracer_config.get("homeserver_whitelist")) != list: - raise RuntimeError("Tracer homesererver_whitelist config is malformed") + raise ConfigError("Tracer homesererver_whitelist config is malformed") def generate_config_section(cls, **kwargs): return """\ From bae3b5b8fb81597b404fe8d94fb26d3bcb58a7fb Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:34:59 +0100 Subject: [PATCH 24/69] Use isinstance --- synapse/config/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 84bcee972260..93aa81c41ef1 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -37,7 +37,7 @@ def read_config(self, config, **kwargs): # If no whitelists are given self.tracer_config.setdefault("homeserver_whitelist", []) - if type(self.tracer_config.get("homeserver_whitelist")) != list: + if isinstance(self.tracer_config.get("homeserver_whitelist"), list) raise ConfigError("Tracer homesererver_whitelist config is malformed") def generate_config_section(cls, **kwargs): From 9c39f0e4ad9538a766b69378e6b5506c43928ad4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:44:42 +0100 Subject: [PATCH 25/69] Use tag constants for opentracing. --- synapse/http/matrixfederationclient.py | 11 ++++++----- synapse/http/site.py | 9 +++++---- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index afaa8178e480..ce7a84744bb0 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -24,6 +24,7 @@ import attr import opentracing +from opentracing import tags import treq from canonicaljson import encode_canonical_json from opentracing.propagation import Format @@ -345,10 +346,10 @@ def _send_request( scope = opentracing.tracer.start_active_span( "outgoing-federation-request", tags={ - "span.kind": "client", # With respect to this request's role in an rpc - "peer.address": request.destination, - "http.method": request.method, - "http.url": request.path, + tags.SPAN_KIND: tags.SPAN_KIND_RPC_CLIENT + tags.PEER_ADDRESS: request.destination, + tags.HTTP_METHOD: request.method, + tags.HTTP_URL: request.path, }, finish_on_close=True, ) @@ -443,7 +444,7 @@ def _send_request( opentracing.tracer.active_span ) ) - scope.span.set_tag("http.status_code", response.code) + scope.span.set_tag(opentracing.tags.HTTP_STATUS_CODE response.code) if 200 <= response.code < 300: pass else: diff --git a/synapse/http/site.py b/synapse/http/site.py index 887b7701adde..b1d7bf0cbb2b 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -16,6 +16,7 @@ import time import opentracing +from opentracing import tags from twisted.web.server import Request, Site @@ -243,10 +244,10 @@ def _started_processing(self, servlet_name): "incoming-federation-request", tags={ "request_id": self.get_request_id(), - "span.kind": "server", - "http.method": self.get_method(), - "http.url": self.get_redacted_uri(), - "peer.ipv6": self.getClientIP(), + tags.SPAN_KIND: tags.SPAN_KIND_RPC_SERVER, + tags.HTTP_METHOD: self.get_method(), + tags.HTTP_URL: self.get_redacted_uri(), + tags.PEER_HOST_IPV6: self.getClientIP(), }, child_of=span_context, ) From bae63e92f597b98c591e952ffb3385c7b639ab01 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:50:48 +0100 Subject: [PATCH 26/69] Remove debug comment and no need to explicitely record error --- synapse/http/matrixfederationclient.py | 6 ------ 1 file changed, 6 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index ce7a84744bb0..40e58ad8729b 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -524,12 +524,6 @@ def _send_request( url_str, _flatten_response_never_received(e), ) - logger.info( - "Setting response code on span {} *********".format( - opentracing.tracer.active_span - ) - ) - # scope.span.set_tag("error", True) raise defer.returnValue(response) From 4925558f3fa935e4ada4ae05cf5eefa4f12e8dd4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 15:52:32 +0100 Subject: [PATCH 27/69] Typo?... --- synapse/http/site.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index b1d7bf0cbb2b..082ada57c6a9 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -271,7 +271,7 @@ def _finished_processing(self): # the time between receiving the request and the request handler finishing processing_time = self._processing_finished_time - self.start_time - # the time between the reb'\x80\x03ctwisted.web.http_headers\nHeaders\nq\x00)\x81q\x01}q\x02X\x0b\x00\x00\x00_rawHeadersq\x03}q\x04(C\x04hostq\x05]q\x06C\x0elocalhost:8081q\x07aC\nuser-agentq\x08]q\tCLMozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:67.0) Gecko/20100101 Firefox/67.0q\naC\x06acceptq\x0b]q\x0cC\x10application/jsonq\raC\x0faccept-languageq\x0e]q\x0fC\x0een-GB,en;q=0.5q\x10aC\x0faccept-encodingq\x11]q\x12C\rgzip, deflateq\x13aC\x06originq\x14]q\x15C\x04nullq\x16aC\nconnectionq\x17]q\x18C\nkeep-aliveq\x19ausb.'quest handler finishing and the response being sent + # the time between the request handler finishing and the response being sent # to the client (nb may be negative) response_send_time = self.finish_time - self._processing_finished_time From 810477915f6908429014bf9657f590d2f4709ece Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 16:06:54 +0100 Subject: [PATCH 28/69] Two errors a "s(c)entry" --- synapse/util/scopecontextmanager.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index dd226df272c5..d60724c45939 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -69,7 +69,7 @@ def activate(self, span, finish_on_close): if ctx is LoggingContext.sentinel: # We don't want this scope to affect. - logger.warning("Tried to activate scope outside of loggingcontext") + logger.error("Tried to activate scope outside of loggingcontext") return Scope(None, span) elif ctx.scope is not None: # We want the logging scope to look exactly the same so we give it @@ -105,7 +105,7 @@ def __exit__(self, type, value, traceback): def close(self): if self.manager.active is not self: - logger.warning("Tried to close a none active scope!") + logger.error("Tried to close a none active scope!") return if self._finish_on_close: From 609d97b8a999b56c61171f50a8f1bcf57244e29d Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 16:23:53 +0100 Subject: [PATCH 29/69] Docstrings! --- synapse/util/scopecontextmanager.py | 32 ++++++++++++++++++++++++++--- 1 file changed, 29 insertions(+), 3 deletions(-) diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index d60724c45939..91893ebe40ff 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -23,8 +23,13 @@ class LogContextScopeManager(ScopeManager): - - _homeserver_whitelist = ["*"] + """ + The LogContextScopeManager tracks the active scope in opentracing + by using the log contexts which are native to synapse. This is so + that the basic opentracing api can be used across twisted defereds. + (I would love to break logcontexts and this into an OS package. but + let's wait for twisted's contexts to be released.) + """ def __init__(self, config): # Set the whitelists @@ -58,7 +63,7 @@ def activate(self, span, finish_on_close): finish_on_close (Boolean): whether Span should be automatically finished when Scope.close() is called. - Return: + Returns: Scope to control the end of the active period for *span*. It is a programming error to neglect to call Scope.close() on the returned instance. @@ -86,7 +91,28 @@ def request_from_whitelisted_homeserver(self, request): class _LogContextScope(Scope): + """ + A custom opentracing scope. The only significant difference is that it will + close the log context it's related to if the logcontext was created specifically + for this scope. + """ + def __init__(self, manager, span, logcontext, enter_logcontext, finish_on_close): + """ + Args: + manager (LogContextScopeManager): + the manager that is responsible for this scope. + span (Span): + the opentracing span which this scope represents the local + lifetime for. + logcontext (LogContext): + the logcontext to which this scope is attached. + enter_logcontext (Boolean): + if True the logcontext will be entered and exited when the scope + is entered and exited respectively + finish_on_close (Boolean): + if True finish the span when the scope is closed + """ super(_LogContextScope, self).__init__(manager, span) self.logcontext = logcontext self._finish_on_close = finish_on_close From 04781e93a22ba9c859e76448a3374460e8609037 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 16:36:48 +0100 Subject: [PATCH 30/69] typos --- synapse/config/tracer.py | 4 ++-- synapse/http/matrixfederationclient.py | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 93aa81c41ef1..252550396486 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -19,7 +19,7 @@ from synapse.util.scopecontextmanager import LogContextScopeManager -from ._base import Config +from ._base import Config, ConfigError logger = logging.getLogger(__name__) @@ -37,7 +37,7 @@ def read_config(self, config, **kwargs): # If no whitelists are given self.tracer_config.setdefault("homeserver_whitelist", []) - if isinstance(self.tracer_config.get("homeserver_whitelist"), list) + if isinstance(self.tracer_config.get("homeserver_whitelist"), list): raise ConfigError("Tracer homesererver_whitelist config is malformed") def generate_config_section(cls, **kwargs): diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 40e58ad8729b..37cc086a94ef 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -346,7 +346,7 @@ def _send_request( scope = opentracing.tracer.start_active_span( "outgoing-federation-request", tags={ - tags.SPAN_KIND: tags.SPAN_KIND_RPC_CLIENT + tags.SPAN_KIND: tags.SPAN_KIND_RPC_CLIENT, tags.PEER_ADDRESS: request.destination, tags.HTTP_METHOD: request.method, tags.HTTP_URL: request.path, @@ -444,7 +444,7 @@ def _send_request( opentracing.tracer.active_span ) ) - scope.span.set_tag(opentracing.tags.HTTP_STATUS_CODE response.code) + scope.span.set_tag(opentracing.tags.HTTP_STATUS_CODE, response.code) if 200 <= response.code < 300: pass else: From 088176e5b298ebe05de89aa892e3299bb7fd843e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 17:04:32 +0100 Subject: [PATCH 31/69] Remove debugging brainslip --- synapse/http/matrixfederationclient.py | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 37cc086a94ef..aa14e269c69b 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -439,12 +439,8 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - logger.info( - "Setting response code on span {} *********".format( - opentracing.tracer.active_span - ) - ) scope.span.set_tag(opentracing.tags.HTTP_STATUS_CODE, response.code) + if 200 <= response.code < 300: pass else: From dde461814da1b1140e0ba3434f32bfbfaff776c1 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 18:16:48 +0100 Subject: [PATCH 32/69] Homeserver Whitlisting --- synapse/config/tracer.py | 8 +- synapse/http/matrixfederationclient.py | 11 +- synapse/http/site.py | 4 +- synapse/util/scopecontextmanager.py | 3 - synapse/util/tracerutils.py | 147 +++++++++++++++++-------- 5 files changed, 118 insertions(+), 55 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 252550396486..506b2afae732 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -18,6 +18,7 @@ from jaeger_client import Config as JaegerConfig from synapse.util.scopecontextmanager import LogContextScopeManager +from synapse.util.tracerutils import TracerUtil from ._base import Config, ConfigError @@ -37,7 +38,7 @@ def read_config(self, config, **kwargs): # If no whitelists are given self.tracer_config.setdefault("homeserver_whitelist", []) - if isinstance(self.tracer_config.get("homeserver_whitelist"), list): + if not isinstance(self.tracer_config.get("homeserver_whitelist"), list): raise ConfigError("Tracer homesererver_whitelist config is malformed") def generate_config_section(cls, **kwargs): @@ -55,7 +56,7 @@ def generate_config_section(cls, **kwargs): def init_tracing(config): - """Initialise the JaegerClient tracer + """Set the whitelists and initialise the JaegerClient tracer Args: config (Config) @@ -64,6 +65,9 @@ def init_tracing(config): """ if config.tracer_config.get("tracer_enabled", False): + TracerUtil.set_homeserver_whitelist( + config.tracer_config["homeserver_whitelist"] + ) jaeger_config = JaegerConfig( config={"sampler": {"type": "const", "param": 1}, "logging": True}, service_name=config.server_name, diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index aa14e269c69b..4bc5ceeeeedc 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -23,8 +23,6 @@ from six.moves import urllib import attr -import opentracing -from opentracing import tags import treq from canonicaljson import encode_canonical_json from opentracing.propagation import Format @@ -39,6 +37,10 @@ from twisted.web._newclient import ResponseDone from twisted.web.http_headers import Headers +import opentracing +from opentracing import tags +from synapse.util.tracerutils import TracerUtil + import synapse.metrics import synapse.util.retryutils from synapse.api.errors import ( @@ -356,8 +358,9 @@ def _send_request( # Inject the span into the headers headers_dict = {} - opentracing.tracer.inject(scope.span, Format.HTTP_HEADERS, headers_dict) - headers_dict = {k.encode(): [v.encode()] for k, v in headers_dict.items()} + TracerUtil.inject_span_context_byte_dict( + headers_dict, scope.span, request.destination + ) headers_dict[b"User-Agent"] = [self.version_string_bytes] diff --git a/synapse/http/site.py b/synapse/http/site.py index 082ada57c6a9..e093ec1c0e40 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -23,7 +23,7 @@ from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext -from synapse.util.tracerutils import extract_span_context +from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) @@ -239,7 +239,7 @@ def _started_processing(self, servlet_name): ) # Start a span - span_context = extract_span_context(self.requestHeaders) + span_context = TracerUtil.extract_span_context(self.requestHeaders) opentracing.tracer.start_active_span( "incoming-federation-request", tags={ diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 91893ebe40ff..6e0acab42e7d 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -86,9 +86,6 @@ def activate(self, span, finish_on_close): ctx.scope = scope return scope - def request_from_whitelisted_homeserver(self, request): - pass - class _LogContextScope(Scope): """ diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 5ba4cfe38a53..e2337d654f02 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -13,51 +13,110 @@ # See the License for the specific language governing permissions and # limitations under the License.import opentracing +import logging + +logger = logging.getLogger(__name__) + import opentracing from opentracing.propagation import Format +import re + +# block everything by default + + +class TracerUtil: + _homeserver_whitelist = None + + @staticmethod + def set_homeserver_whitelist(homeserver_whitelist): + """Sets the whitelist + + Args: + homeserver_whitelist (iterable of strings): regex of whitelisted homeservers + """ + if homeserver_whitelist: + # Makes a single regex which accepts all passed in regexes in the list + TracerUtil._homeserver_whitelist = re.compile( + "({})".format(")|(".join(homeserver_whitelist)) + ) + logger.info("Set whitelist to {}".format(TracerUtil._homeserver_whitelist)) + + @staticmethod + def whitelisted_homeserver(destination): + if TracerUtil._homeserver_whitelist: + return TracerUtil._homeserver_whitelist.match(destination) + return False + + @staticmethod + def extract_span_context(headers): + """ + Extracts a span context from Twisted Headers. + args: + headers (twisted.web.http_headers.Headers) + returns: + span_context (opentracing.span.SpanContext) + """ + # Twisted encodes the values as lists whereas opentracing doesn't. + # So, we take the first item in the list. + # Also, twisted uses byte arrays while opentracing expects strings. + header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} + return opentracing.tracer.extract(Format.HTTP_HEADERS, header_dict) + + @staticmethod + def inject_span_context(headers, span, destination): + """ + Injects a span context into twisted headers inplace + + Args: + headers (twisted.web.http_headers.Headers) + span (opentracing.Span) + + Returns: + Inplace modification of headers + + Note: + The headers set by the tracer are custom to the tracer implementation which + should be unique enough that they don't interfere with any headers set by + synapse or twisted. If we're still using jaeger these headers would be those + here: + https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py + """ + + if not TracerUtil.whitelisted_homeserver(destination): + return + carrier = {} + opentracing.tracer.inject(span, Format.HTTP_HEADERS, carrier) + + for key, value in carrier.items(): + headers.addRawHeaders(key, value) + + @staticmethod + def inject_span_context_byte_dict(headers, span, destination): + """ + Injects a span context into a dict where the headers are encoded as byte + strings + + Args: + headers (dict) + span (opentracing.Span) + + Returns: + Inplace modification of headers + + Note: + The headers set by the tracer are custom to the tracer implementation which + should be unique enough that they don't interfere with any headers set by + synapse or twisted. If we're still using jaeger these headers would be those + here: + https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py + """ + if not TracerUtil.whitelisted_homeserver(destination): + logger.info("{}".format(TracerUtil._homeserver_whitelist)) + return + + carrier = {} + opentracing.tracer.inject(span, Format.HTTP_HEADERS, carrier) -def extract_span_context(headers): - """ - Extracts a span context from Twisted Headers. - args: - headers (twisted.web.http_headers.Headers) - returns: - span_context (opentracing.span.SpanContext) - """ - # Twisted encodes the values as lists whereas opentracing doesn't. - # So, we take the first item in the list. - # Also, twisted uses byte arrays while opentracing expects strings. - header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} - return opentracing.tracer.extract(Format.HTTP_HEADERS, header_dict) - - -def inject_span_context(headers, span): - """ - Injects a span context into twisted headers inplace - args: - headers (twisted.web.http_headers.Headers) - span (opentracing.Span) - - note: - The headers set by the tracer are custom to the tracer implementation which - should be unique enough that they don't interfere with any headers set by - synapse or twisted. If we're still using jaeger these headers would be those - here: - https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py - """ - carrier = {} - carrier = opentracing.tracer.inject(span, Format.HTTP_HEADERS, {}) - - for key, value in carrier: - headers.addRawHeaders(key, value) - - -# TODO: Implement whitelisting -def request_from_whitelisted_homeserver(request): - pass - - -# TODO: Implement whitelisting -def user_whitelisted(request): - pass + for key, value in carrier.items(): + headers[key.encode()] = [value.encode()] From 34235a45e43489c3f3f744589c1c7e6dd7c410b0 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 18:24:38 +0100 Subject: [PATCH 33/69] Better opentracing config comment --- docs/sample_config.yaml | 22 ++++++++++++---------- synapse/config/tracer.py | 12 +++++++++--- 2 files changed, 21 insertions(+), 13 deletions(-) diff --git a/docs/sample_config.yaml b/docs/sample_config.yaml index 5861861c616c..6fb9313db30d 100644 --- a/docs/sample_config.yaml +++ b/docs/sample_config.yaml @@ -1354,16 +1354,18 @@ password_config: # example_option: 'things' -## Tracer ## - -#tracer: +## Opentracing ## +# These settings enable opentracing which implements distributed tracing +# This allows you to observe the causal chain of events across servers +# including requests, key lookups etc. across any server running +# synapse or any other other services which supports opentracing. +# (specifically those implemented with jaeger) + +#opentracing: # # Enable / disable tracer # tracer_enabled: false -# # The list of users who's requests will be traced -# # The list is a list of regex which is matched against the user_id -# user_whitelist: -# - "*" -# # The list of homeservers we wish to trace across -# # The list is a list of regex which is matched against the homeserver name +# # The list of homeservers we wish to expose our current traces to. +# # The list is a list of regexes which are matched against the +# # servername of the homeserver # homeserver_whitelist: -# - "*" +# - ".*" diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 506b2afae732..76fa5b8920c9 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -44,14 +44,20 @@ def read_config(self, config, **kwargs): def generate_config_section(cls, **kwargs): return """\ ## Opentracing ## + # These settings enable opentracing which implements distributed tracing + # This allows you to observe the causal chain of events across servers + # including requests, key lookups etc. across any server running + # synapse or any other other services which supports opentracing. + # (specifically those implemented with jaeger) #opentracing: # # Enable / disable tracer # tracer_enabled: false - # # The list of homeservers we wish to trace across - # # The list is a list of regex which is matched against the homeserver name + # # The list of homeservers we wish to expose our current traces to. + # # The list is a list of regexes which are matched against the + # # servername of the homeserver # homeserver_whitelist: - # - "*" + # - ".*" """ From 1d591afba4859aea09e5ffb6fa7fb1a1559d4d47 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 25 Jun 2019 18:36:37 +0100 Subject: [PATCH 34/69] linting --- docs/sample_config.yaml | 2 +- synapse/config/tracer.py | 6 +----- synapse/http/matrixfederationclient.py | 8 +++----- synapse/util/scopecontextmanager.py | 2 +- synapse/util/tracerutils.py | 10 ++-------- 5 files changed, 8 insertions(+), 20 deletions(-) diff --git a/docs/sample_config.yaml b/docs/sample_config.yaml index 6fb9313db30d..8976d48ff023 100644 --- a/docs/sample_config.yaml +++ b/docs/sample_config.yaml @@ -1356,7 +1356,7 @@ password_config: ## Opentracing ## # These settings enable opentracing which implements distributed tracing -# This allows you to observe the causal chain of events across servers +# This allows you to observe the causal chain of events across servers # including requests, key lookups etc. across any server running # synapse or any other other services which supports opentracing. # (specifically those implemented with jaeger) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 76fa5b8920c9..3c14196b9273 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -13,8 +13,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -import logging - from jaeger_client import Config as JaegerConfig from synapse.util.scopecontextmanager import LogContextScopeManager @@ -22,8 +20,6 @@ from ._base import Config, ConfigError -logger = logging.getLogger(__name__) - class TracerConfig(Config): def read_config(self, config, **kwargs): @@ -45,7 +41,7 @@ def generate_config_section(cls, **kwargs): return """\ ## Opentracing ## # These settings enable opentracing which implements distributed tracing - # This allows you to observe the causal chain of events across servers + # This allows you to observe the causal chain of events across servers # including requests, key lookups etc. across any server running # synapse or any other other services which supports opentracing. # (specifically those implemented with jaeger) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 4bc5ceeeeedc..8d806c949b1f 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -23,9 +23,10 @@ from six.moves import urllib import attr +import opentracing import treq from canonicaljson import encode_canonical_json -from opentracing.propagation import Format +from opentracing import tags from prometheus_client import Counter from signedjson.sign import sign_json from zope.interface import implementer @@ -37,10 +38,6 @@ from twisted.web._newclient import ResponseDone from twisted.web.http_headers import Headers -import opentracing -from opentracing import tags -from synapse.util.tracerutils import TracerUtil - import synapse.metrics import synapse.util.retryutils from synapse.api.errors import ( @@ -56,6 +53,7 @@ from synapse.util.async_helpers import timeout_deferred from synapse.util.logcontext import make_deferred_yieldable from synapse.util.metrics import Measure +from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 6e0acab42e7d..85a06bf5b46d 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -100,7 +100,7 @@ def __init__(self, manager, span, logcontext, enter_logcontext, finish_on_close) manager (LogContextScopeManager): the manager that is responsible for this scope. span (Span): - the opentracing span which this scope represents the local + the opentracing span which this scope represents the local lifetime for. logcontext (LogContext): the logcontext to which this scope is attached. diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index e2337d654f02..5a2e96e1cb2a 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -13,15 +13,11 @@ # See the License for the specific language governing permissions and # limitations under the License.import opentracing -import logging - -logger = logging.getLogger(__name__) +import re import opentracing from opentracing.propagation import Format -import re - # block everything by default @@ -40,7 +36,6 @@ def set_homeserver_whitelist(homeserver_whitelist): TracerUtil._homeserver_whitelist = re.compile( "({})".format(")|(".join(homeserver_whitelist)) ) - logger.info("Set whitelist to {}".format(TracerUtil._homeserver_whitelist)) @staticmethod def whitelisted_homeserver(destination): @@ -94,7 +89,7 @@ def inject_span_context(headers, span, destination): @staticmethod def inject_span_context_byte_dict(headers, span, destination): """ - Injects a span context into a dict where the headers are encoded as byte + Injects a span context into a dict where the headers are encoded as byte strings Args: @@ -112,7 +107,6 @@ def inject_span_context_byte_dict(headers, span, destination): https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ if not TracerUtil.whitelisted_homeserver(destination): - logger.info("{}".format(TracerUtil._homeserver_whitelist)) return carrier = {} From 37a650c27060d24e8ea6a3423b0c89d765f82c30 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 26 Jun 2019 11:18:48 +0100 Subject: [PATCH 35/69] Inclue worker name in service_name --- synapse/config/tracer.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 3c14196b9273..cc22e68dea63 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -66,13 +66,15 @@ def init_tracing(config): name to the homeserver's. """ + name = config.worker_name if config.worker_name else "master" + if config.tracer_config.get("tracer_enabled", False): TracerUtil.set_homeserver_whitelist( config.tracer_config["homeserver_whitelist"] ) jaeger_config = JaegerConfig( config={"sampler": {"type": "const", "param": 1}, "logging": True}, - service_name=config.server_name, + service_name="{} {}".format(config.server_name, name), scope_manager=LogContextScopeManager(config), ) else: # The tracer is not configured so we instantiate a noop tracer From 4bf9e1188f17f844c2c54f710a474e7af5daa2c8 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 26 Jun 2019 19:09:36 +0100 Subject: [PATCH 36/69] Make opentracing an optional dependency --- synapse/app/_base.py | 2 +- synapse/config/tracer.py | 34 ---- synapse/http/matrixfederationclient.py | 22 +-- synapse/http/site.py | 24 +-- synapse/python_dependencies.py | 2 +- synapse/util/tracerutils.py | 233 ++++++++++++++++++++++--- 6 files changed, 233 insertions(+), 84 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 5434f999c9fe..13a2af291d86 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -241,7 +241,7 @@ def handle_sighup(*args, **kwargs): refresh_certificate(hs) # Start the tracer - synapse.config.tracer.init_tracing(hs.config) + synapse.util.tracerutils.TracerUtil.init_tracer(hs.config) # It is now safe to start your Synapse. hs.start_listening(listeners) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index cc22e68dea63..8cfbc8d85c03 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -13,11 +13,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -from jaeger_client import Config as JaegerConfig - -from synapse.util.scopecontextmanager import LogContextScopeManager -from synapse.util.tracerutils import TracerUtil - from ._base import Config, ConfigError @@ -55,32 +50,3 @@ def generate_config_section(cls, **kwargs): # homeserver_whitelist: # - ".*" """ - - -def init_tracing(config): - """Set the whitelists and initialise the JaegerClient tracer - - Args: - config (Config) - The config used by the homserver. Here it's used to set the service - name to the homeserver's. - """ - - name = config.worker_name if config.worker_name else "master" - - if config.tracer_config.get("tracer_enabled", False): - TracerUtil.set_homeserver_whitelist( - config.tracer_config["homeserver_whitelist"] - ) - jaeger_config = JaegerConfig( - config={"sampler": {"type": "const", "param": 1}, "logging": True}, - service_name="{} {}".format(config.server_name, name), - scope_manager=LogContextScopeManager(config), - ) - else: # The tracer is not configured so we instantiate a noop tracer - jaeger_config = JaegerConfig( - config={"sampler": {"type": "const", "param": 0}}, - service_name=config.server_name, - ) - - return jaeger_config.initialize_tracer() diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 8d806c949b1f..7e84582a7a03 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -23,10 +23,8 @@ from six.moves import urllib import attr -import opentracing import treq from canonicaljson import encode_canonical_json -from opentracing import tags from prometheus_client import Counter from signedjson.sign import sign_json from zope.interface import implementer @@ -343,26 +341,24 @@ def _send_request( query_bytes = b"" # Retreive current span - scope = opentracing.tracer.start_active_span( + TracerUtil.start_active_span( "outgoing-federation-request", tags={ - tags.SPAN_KIND: tags.SPAN_KIND_RPC_CLIENT, - tags.PEER_ADDRESS: request.destination, - tags.HTTP_METHOD: request.method, - tags.HTTP_URL: request.path, + TracerUtil.Tags.SPAN_KIND: TracerUtil.Tags.SPAN_KIND_RPC_CLIENT, + TracerUtil.Tags.PEER_ADDRESS: request.destination, + TracerUtil.Tags.HTTP_METHOD: request.method, + TracerUtil.Tags.HTTP_URL: request.path, }, finish_on_close=True, ) # Inject the span into the headers headers_dict = {} - TracerUtil.inject_span_context_byte_dict( - headers_dict, scope.span, request.destination - ) + TracerUtil.inject_active_span_byte_dict(headers_dict, request.destination) headers_dict[b"User-Agent"] = [self.version_string_bytes] - with limiter, scope: + with limiter: # XXX: Would be much nicer to retry only at the transaction-layer # (once we have reliable transactions in place) if long_retries: @@ -440,7 +436,7 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - scope.span.set_tag(opentracing.tags.HTTP_STATUS_CODE, response.code) + TracerUtil.set_tag(TracerUtil.Tags.HTTP_STATUS_CODE, response.code) if 200 <= response.code < 300: pass @@ -522,7 +518,7 @@ def _send_request( _flatten_response_never_received(e), ) raise - + TracerUtil.close_active_span() defer.returnValue(response) def build_auth_headers( diff --git a/synapse/http/site.py b/synapse/http/site.py index e093ec1c0e40..313320a88c8e 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -15,9 +15,6 @@ import logging import time -import opentracing -from opentracing import tags - from twisted.web.server import Request, Site from synapse.http import redact_uri @@ -239,17 +236,16 @@ def _started_processing(self, servlet_name): ) # Start a span - span_context = TracerUtil.extract_span_context(self.requestHeaders) - opentracing.tracer.start_active_span( + TracerUtil.start_active_span_from_context( + self.requestHeaders, "incoming-federation-request", tags={ "request_id": self.get_request_id(), - tags.SPAN_KIND: tags.SPAN_KIND_RPC_SERVER, - tags.HTTP_METHOD: self.get_method(), - tags.HTTP_URL: self.get_redacted_uri(), - tags.PEER_HOST_IPV6: self.getClientIP(), + TracerUtil.Tags.SPAN_KIND: TracerUtil.Tags.SPAN_KIND_RPC_SERVER, + TracerUtil.Tags.HTTP_METHOD: self.get_method(), + TracerUtil.Tags.HTTP_URL: self.get_redacted_uri(), + TracerUtil.Tags.PEER_HOST_IPV6: self.getClientIP(), }, - child_of=span_context, ) def _finished_processing(self): @@ -321,11 +317,9 @@ def _finished_processing(self): usage.evt_db_fetch_count, ) - scope = opentracing.tracer.scope_manager.active - if scope is not None: - # finish the span if it's there. - scope.span.set_tag("peer.address", authenticated_entity) - scope.__exit__(None, None, None) + # finish the span if it's there. + TracerUtil.set_tag("peer.address", authenticated_entity) + TracerUtil.close_active_span() try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) diff --git a/synapse/python_dependencies.py b/synapse/python_dependencies.py index 41ffecff4cc2..51205c98e536 100644 --- a/synapse/python_dependencies.py +++ b/synapse/python_dependencies.py @@ -72,7 +72,6 @@ # Twisted 18.7.0 requires attrs>=17.4.0 "attrs>=17.4.0", "netaddr>=0.7.18", - "jaeger-client>=4.0.0", "Jinja2>=2.9", "bleach>=1.4.3", ] @@ -96,6 +95,7 @@ "url_preview": ["lxml>=3.5.0"], "test": ["mock>=2.0", "parameterized"], "sentry": ["sentry-sdk>=0.7.2"], + "opentracing": ["jaeger-client>=4.0.0", "opentracing>=2.2.0"], } ALL_OPTIONAL_REQUIREMENTS = set() diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 5a2e96e1cb2a..799766ea366f 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -13,19 +13,179 @@ # See the License for the specific language governing permissions and # limitations under the License.import opentracing +import logging import re +from functools import wraps -import opentracing -from opentracing.propagation import Format +logger = logging.getLogger(__name__) -# block everything by default +def only_if_tracing(func): + """Executes the function only if we're tracing. Otherwise return. + Assumes the function wrapped may return None""" -class TracerUtil: + @wraps(func) + def f(cls, *args, **kwargs): + if cls._opentracing: + return func(cls, *args, **kwargs) + else: + return + + return f + + +class TracerUtil(object): + _opentracing = None + _opentracing_formats = None + + # Block everything by default _homeserver_whitelist = None - @staticmethod - def set_homeserver_whitelist(homeserver_whitelist): + @classmethod + def init_tracer(cls, config): + """Set the whitelists and initialise the JaegerClient tracer + + Args: + config (Config) + The config used by the homserver. Here it's used to set the service + name to the homeserver's. + """ + if not config.tracer_config.get("tracer_enabled", False): + # We don't have a tracer + return + + cls.import_opentracing() + cls.set_tags() + cls.setup_tracing(config) + + @classmethod + def import_opentracing(cls): + try: + # Try to import the tracer. If it's not there we want to throw an eror + import opentracing + except ImportError as e: + logger.error( + "The server has been configure to use opentracing but " + "the {} module has not been installed.".format(e.name) + ) + raise + + cls._opentracing = opentracing + cls.set_tags() + + @classmethod + def setup_tracing(cls, config): + try: + from jaeger_client import Config as JaegerConfig + from synapse.util.scopecontextmanager import LogContextScopeManager + except ImportError as e: + logger.error( + "The server has been configure to use opentracing but " + "the {} module has not been installed.".format(e.name) + ) + raise + + # Include the worker name + name = config.worker_name if config.worker_name else "master" + + cls.set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) + jaeger_config = JaegerConfig( + config={"sampler": {"type": "const", "param": 1}, "logging": True}, + service_name="{} {}".format(config.server_name, name), + scope_manager=LogContextScopeManager(config), + ) + jaeger_config.initialize_tracer() + + class Tags(object): + """wrapper of opentracings tags. We need to have them if we + want to reference them without opentracing around. Clearly they + should never actually show up in a trace. `set_tags` overwrites + these with the correct ones.""" + + COMPONENT = "invlalid-tag" + DATABASE_INSTANCE = "invlalid-tag" + DATABASE_STATEMENT = "invlalid-tag" + DATABASE_TYPE = "invlalid-tag" + DATABASE_USER = "invlalid-tag" + ERROR = "invlalid-tag" + HTTP_METHOD = "invlalid-tag" + HTTP_STATUS_CODE = "invlalid-tag" + HTTP_URL = "invlalid-tag" + MESSAGE_BUS_DESTINATION = "invlalid-tag" + PEER_ADDRESS = "invlalid-tag" + PEER_HOSTNAME = "invlalid-tag" + PEER_HOST_IPV4 = "invlalid-tag" + PEER_HOST_IPV6 = "invlalid-tag" + PEER_PORT = "invlalid-tag" + PEER_SERVICE = "invlalid-tag" + SAMPLING_PRIORITY = "invlalid-tag" + SERVICE = "invlalid-tag" + SPAN_KIND = "invlalid-tag" + SPAN_KIND_CONSUMER = "invlalid-tag" + SPAN_KIND_PRODUCER = "invlalid-tag" + SPAN_KIND_RPC_CLIENT = "invlalid-tag" + SPAN_KIND_RPC_SERVER = "invlalid-tag" + + @classmethod + @only_if_tracing + def set_tags(cls): + cls.Tags = cls._opentracing.tags + + # Could use kwargs but I want these to be explicit + @classmethod + @only_if_tracing + def start_active_span( + cls, + operation_name, + child_of=None, + references=None, + tags=None, + start_time=None, + ignore_active_span=False, + finish_on_close=True, + ): + # We need to enter the scope here for the logcontext to become active + cls._opentracing.tracer.start_active_span( + operation_name, + child_of=child_of, + references=references, + tags=tags, + start_time=start_time, + ignore_active_span=ignore_active_span, + finish_on_close=finish_on_close, + ).__enter__() + + @classmethod + @only_if_tracing + def close_active_span(cls): + cls._opentracing.tracer.scope_manager.active.__exit__(None, None, None) + + @classmethod + @only_if_tracing + def set_tag(cls, key, value): + cls._opentracing.tracer.active_span.set_tag(key, value) + + @classmethod + @only_if_tracing + def log_kv(cls, key_values, timestamp=None): + cls._opentracing.tracer.active_span.log_kv(key_values, timestamp) + + # Note: we don't have a get baggage items because we're trying to hide all + # scope and span state from synapse. I think this method may also be useless + # as a result + @classmethod + @only_if_tracing + def set_baggage_item(cls, key, value): + cls._opentracing.tracer.active_span.set_baggage_item(key, value) + + @classmethod + @only_if_tracing + def set_operation_name(cls, operation_name): + cls._opentracing.tracer.active_span.set_operation_name(operation_name) + + @classmethod + @only_if_tracing + def set_homeserver_whitelist(cls, homeserver_whitelist): """Sets the whitelist Args: @@ -33,18 +193,29 @@ def set_homeserver_whitelist(homeserver_whitelist): """ if homeserver_whitelist: # Makes a single regex which accepts all passed in regexes in the list - TracerUtil._homeserver_whitelist = re.compile( + cls._homeserver_whitelist = re.compile( "({})".format(")|(".join(homeserver_whitelist)) ) - @staticmethod - def whitelisted_homeserver(destination): - if TracerUtil._homeserver_whitelist: - return TracerUtil._homeserver_whitelist.match(destination) + @classmethod + @only_if_tracing + def whitelisted_homeserver(cls, destination): + if cls._homeserver_whitelist: + return cls._homeserver_whitelist.match(destination) return False - @staticmethod - def extract_span_context(headers): + @classmethod + @only_if_tracing + def start_active_span_from_context( + cls, + headers, + operation_name, + references=None, + tags=None, + start_time=None, + ignore_active_span=False, + finish_on_close=True, + ): """ Extracts a span context from Twisted Headers. args: @@ -56,10 +227,23 @@ def extract_span_context(headers): # So, we take the first item in the list. # Also, twisted uses byte arrays while opentracing expects strings. header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} - return opentracing.tracer.extract(Format.HTTP_HEADERS, header_dict) + context = cls._opentracing.tracer.extract( + cls._opentracing.Format.HTTP_HEADERS, header_dict + ) - @staticmethod - def inject_span_context(headers, span, destination): + cls._opentracing.tracer.start_active_span( + operation_name, + child_of=context, + references=references, + tags=tags, + start_time=start_time, + ignore_active_span=ignore_active_span, + finish_on_close=finish_on_close, + ) + + @classmethod + @only_if_tracing + def inject_active_span_twisted_headers(cls, headers, destination): """ Injects a span context into twisted headers inplace @@ -80,14 +264,19 @@ def inject_span_context(headers, span, destination): if not TracerUtil.whitelisted_homeserver(destination): return + + span = cls._opentracing.tracer.active_span carrier = {} - opentracing.tracer.inject(span, Format.HTTP_HEADERS, carrier) + cls._opentracing.tracer.inject( + span, cls._opentracing.Format.HTTP_HEADERS, carrier + ) for key, value in carrier.items(): headers.addRawHeaders(key, value) - @staticmethod - def inject_span_context_byte_dict(headers, span, destination): + @classmethod + @only_if_tracing + def inject_active_span_byte_dict(cls, headers, destination): """ Injects a span context into a dict where the headers are encoded as byte strings @@ -109,8 +298,12 @@ def inject_span_context_byte_dict(headers, span, destination): if not TracerUtil.whitelisted_homeserver(destination): return + span = cls._opentracing.tracer.active_span + carrier = {} - opentracing.tracer.inject(span, Format.HTTP_HEADERS, carrier) + cls._opentracing.tracer.inject( + span, cls._opentracing.Format.HTTP_HEADERS, carrier + ) for key, value in carrier.items(): headers[key.encode()] = [value.encode()] From 941b655e40dbab61b0b27c7511d71f3be19aeee2 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 09:03:42 +0100 Subject: [PATCH 37/69] Neater config retreival --- synapse/config/tracer.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/synapse/config/tracer.py b/synapse/config/tracer.py index 8cfbc8d85c03..63a637984aa8 100644 --- a/synapse/config/tracer.py +++ b/synapse/config/tracer.py @@ -20,9 +20,7 @@ class TracerConfig(Config): def read_config(self, config, **kwargs): self.tracer_config = config.get("opentracing") - if self.tracer_config is None: - # If the tracer is not configured we assume it is disabled - self.tracer_config = {"tracer_enabled": False} + self.tracer_config = config.get("opentracing", {"tracer_enabled": False}) if self.tracer_config.get("tracer_enabled", False): # The tracer is enabled so sanitize the config From 965427760bcc68804c098f2edd6663e3d3e24c4e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 09:05:05 +0100 Subject: [PATCH 38/69] Typoed --- synapse/util/scopecontextmanager.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/util/scopecontextmanager.py b/synapse/util/scopecontextmanager.py index 85a06bf5b46d..e041f786c3bf 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/util/scopecontextmanager.py @@ -1,5 +1,5 @@ # -*- coding: utf-8 -*- -# Copyright 2019 The Matrix.org Foundation C.I.C.d +# Copyright 2019 The Matrix.org Foundation C.I.C. # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. From 9ce4a3d9067bf9889b86c360c05ac88618b85c4f Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 09:22:28 +0100 Subject: [PATCH 39/69] Clean up dummy tags --- synapse/http/matrixfederationclient.py | 10 ++-- synapse/http/site.py | 8 +-- synapse/util/tracerutils.py | 71 ++++++++++++++------------ 3 files changed, 46 insertions(+), 43 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 7e84582a7a03..c242f1c9c57d 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -344,10 +344,10 @@ def _send_request( TracerUtil.start_active_span( "outgoing-federation-request", tags={ - TracerUtil.Tags.SPAN_KIND: TracerUtil.Tags.SPAN_KIND_RPC_CLIENT, - TracerUtil.Tags.PEER_ADDRESS: request.destination, - TracerUtil.Tags.HTTP_METHOD: request.method, - TracerUtil.Tags.HTTP_URL: request.path, + TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_CLIENT, + TracerUtil.tags.PEER_ADDRESS: request.destination, + TracerUtil.tags.HTTP_METHOD: request.method, + TracerUtil.tags.HTTP_URL: request.path, }, finish_on_close=True, ) @@ -436,7 +436,7 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - TracerUtil.set_tag(TracerUtil.Tags.HTTP_STATUS_CODE, response.code) + TracerUtil.set_tag(TracerUtil.tags.HTTP_STATUS_CODE, response.code) if 200 <= response.code < 300: pass diff --git a/synapse/http/site.py b/synapse/http/site.py index 313320a88c8e..5e16a7cf5759 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -241,10 +241,10 @@ def _started_processing(self, servlet_name): "incoming-federation-request", tags={ "request_id": self.get_request_id(), - TracerUtil.Tags.SPAN_KIND: TracerUtil.Tags.SPAN_KIND_RPC_SERVER, - TracerUtil.Tags.HTTP_METHOD: self.get_method(), - TracerUtil.Tags.HTTP_URL: self.get_redacted_uri(), - TracerUtil.Tags.PEER_HOST_IPV6: self.getClientIP(), + TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_SERVER, + TracerUtil.tags.HTTP_METHOD: self.get_method(), + TracerUtil.tags.HTTP_URL: self.get_redacted_uri(), + TracerUtil.tags.PEER_HOST_IPV6: self.getClientIP(), }, ) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 799766ea366f..ea6c471b9591 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -20,6 +20,38 @@ logger = logging.getLogger(__name__) +class _DumTagNames(object): + """wrapper of opentracings tags. We need to have them if we + want to reference them without opentracing around. Clearly they + should never actually show up in a trace. `set_tags` overwrites + these with the correct ones.""" + + INVALID_TAG = "invalid-tag" + COMPONENT = INVALID_TAG + DATABASE_INSTANCE = INVALID_TAG + DATABASE_STATEMENT = INVALID_TAG + DATABASE_TYPE = INVALID_TAG + DATABASE_USER = INVALID_TAG + ERROR = INVALID_TAG + HTTP_METHOD = INVALID_TAG + HTTP_STATUS_CODE = INVALID_TAG + HTTP_URL = INVALID_TAG + MESSAGE_BUS_DESTINATION = INVALID_TAG + PEER_ADDRESS = INVALID_TAG + PEER_HOSTNAME = INVALID_TAG + PEER_HOST_IPV4 = INVALID_TAG + PEER_HOST_IPV6 = INVALID_TAG + PEER_PORT = INVALID_TAG + PEER_SERVICE = INVALID_TAG + SAMPLING_PRIORITY = INVALID_TAG + SERVICE = INVALID_TAG + SPAN_KIND = INVALID_TAG + SPAN_KIND_CONSUMER = INVALID_TAG + SPAN_KIND_PRODUCER = INVALID_TAG + SPAN_KIND_RPC_CLIENT = INVALID_TAG + SPAN_KIND_RPC_SERVER = INVALID_TAG + + def only_if_tracing(func): """Executes the function only if we're tracing. Otherwise return. Assumes the function wrapped may return None""" @@ -41,6 +73,8 @@ class TracerUtil(object): # Block everything by default _homeserver_whitelist = None + tags = _DumTagNames + @classmethod def init_tracer(cls, config): """Set the whitelists and initialise the JaegerClient tracer @@ -55,7 +89,7 @@ def init_tracer(cls, config): return cls.import_opentracing() - cls.set_tags() + cls.setup_tags() cls.setup_tracing(config) @classmethod @@ -71,7 +105,6 @@ def import_opentracing(cls): raise cls._opentracing = opentracing - cls.set_tags() @classmethod def setup_tracing(cls, config): @@ -96,40 +129,10 @@ def setup_tracing(cls, config): ) jaeger_config.initialize_tracer() - class Tags(object): - """wrapper of opentracings tags. We need to have them if we - want to reference them without opentracing around. Clearly they - should never actually show up in a trace. `set_tags` overwrites - these with the correct ones.""" - - COMPONENT = "invlalid-tag" - DATABASE_INSTANCE = "invlalid-tag" - DATABASE_STATEMENT = "invlalid-tag" - DATABASE_TYPE = "invlalid-tag" - DATABASE_USER = "invlalid-tag" - ERROR = "invlalid-tag" - HTTP_METHOD = "invlalid-tag" - HTTP_STATUS_CODE = "invlalid-tag" - HTTP_URL = "invlalid-tag" - MESSAGE_BUS_DESTINATION = "invlalid-tag" - PEER_ADDRESS = "invlalid-tag" - PEER_HOSTNAME = "invlalid-tag" - PEER_HOST_IPV4 = "invlalid-tag" - PEER_HOST_IPV6 = "invlalid-tag" - PEER_PORT = "invlalid-tag" - PEER_SERVICE = "invlalid-tag" - SAMPLING_PRIORITY = "invlalid-tag" - SERVICE = "invlalid-tag" - SPAN_KIND = "invlalid-tag" - SPAN_KIND_CONSUMER = "invlalid-tag" - SPAN_KIND_PRODUCER = "invlalid-tag" - SPAN_KIND_RPC_CLIENT = "invlalid-tag" - SPAN_KIND_RPC_SERVER = "invlalid-tag" - @classmethod @only_if_tracing - def set_tags(cls): - cls.Tags = cls._opentracing.tags + def setup_tags(cls): + cls.tags = cls._opentracing.tags # Could use kwargs but I want these to be explicit @classmethod From b008aa4674219c3fcb13d23c32015eec4fc2d052 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 11:24:22 +0100 Subject: [PATCH 40/69] Instantiate tracing as object instead of global class --- synapse/util/tracerutils.py | 109 ++++++++++++++++-------------------- 1 file changed, 48 insertions(+), 61 deletions(-) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index ea6c471b9591..920129477d44 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -57,26 +57,24 @@ def only_if_tracing(func): Assumes the function wrapped may return None""" @wraps(func) - def f(cls, *args, **kwargs): - if cls._opentracing: - return func(cls, *args, **kwargs) + def f(self, *args, **kwargs): + if self._opentracing: + return func(self, *args, **kwargs) else: return return f -class TracerUtil(object): +class OpenTracing(object): _opentracing = None - _opentracing_formats = None # Block everything by default _homeserver_whitelist = None tags = _DumTagNames - @classmethod - def init_tracer(cls, config): + def __init__(self, config=None): """Set the whitelists and initialise the JaegerClient tracer Args: @@ -84,16 +82,18 @@ def init_tracer(cls, config): The config used by the homserver. Here it's used to set the service name to the homeserver's. """ + # If no config is given do not trace. This is useful for testing + if config is None: + return if not config.tracer_config.get("tracer_enabled", False): # We don't have a tracer return - cls.import_opentracing() - cls.setup_tags() - cls.setup_tracing(config) + self.import_opentracing() + self.setup_tags() + self.setup_tracing(config) - @classmethod - def import_opentracing(cls): + def import_opentracing(self): try: # Try to import the tracer. If it's not there we want to throw an eror import opentracing @@ -104,10 +104,9 @@ def import_opentracing(cls): ) raise - cls._opentracing = opentracing + self._opentracing = opentracing - @classmethod - def setup_tracing(cls, config): + def setup_tracing(self, config): try: from jaeger_client import Config as JaegerConfig from synapse.util.scopecontextmanager import LogContextScopeManager @@ -121,7 +120,7 @@ def setup_tracing(cls, config): # Include the worker name name = config.worker_name if config.worker_name else "master" - cls.set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) + self.set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) jaeger_config = JaegerConfig( config={"sampler": {"type": "const", "param": 1}, "logging": True}, service_name="{} {}".format(config.server_name, name), @@ -129,16 +128,14 @@ def setup_tracing(cls, config): ) jaeger_config.initialize_tracer() - @classmethod @only_if_tracing - def setup_tags(cls): - cls.tags = cls._opentracing.tags + def setup_tags(self): + self.tags = self._opentracing.tags # Could use kwargs but I want these to be explicit - @classmethod @only_if_tracing def start_active_span( - cls, + self, operation_name, child_of=None, references=None, @@ -148,7 +145,7 @@ def start_active_span( finish_on_close=True, ): # We need to enter the scope here for the logcontext to become active - cls._opentracing.tracer.start_active_span( + self._opentracing.tracer.start_active_span( operation_name, child_of=child_of, references=references, @@ -158,37 +155,31 @@ def start_active_span( finish_on_close=finish_on_close, ).__enter__() - @classmethod @only_if_tracing - def close_active_span(cls): - cls._opentracing.tracer.scope_manager.active.__exit__(None, None, None) + def close_active_span(self): + self._opentracing.tracer.scope_manager.active.__exit__(None, None, None) - @classmethod @only_if_tracing - def set_tag(cls, key, value): - cls._opentracing.tracer.active_span.set_tag(key, value) + def set_tag(self, key, value): + self._opentracing.tracer.active_span.set_tag(key, value) - @classmethod @only_if_tracing - def log_kv(cls, key_values, timestamp=None): - cls._opentracing.tracer.active_span.log_kv(key_values, timestamp) + def log_kv(self, key_values, timestamp=None): + self._opentracing.tracer.active_span.log_kv(key_values, timestamp) # Note: we don't have a get baggage items because we're trying to hide all # scope and span state from synapse. I think this method may also be useless # as a result - @classmethod @only_if_tracing - def set_baggage_item(cls, key, value): - cls._opentracing.tracer.active_span.set_baggage_item(key, value) + def set_baggage_item(self, key, value): + self._opentracing.tracer.active_span.set_baggage_item(key, value) - @classmethod @only_if_tracing - def set_operation_name(cls, operation_name): - cls._opentracing.tracer.active_span.set_operation_name(operation_name) + def set_operation_name(self, operation_name): + self._opentracing.tracer.active_span.set_operation_name(operation_name) - @classmethod @only_if_tracing - def set_homeserver_whitelist(cls, homeserver_whitelist): + def set_homeserver_whitelist(self, homeserver_whitelist): """Sets the whitelist Args: @@ -196,21 +187,19 @@ def set_homeserver_whitelist(cls, homeserver_whitelist): """ if homeserver_whitelist: # Makes a single regex which accepts all passed in regexes in the list - cls._homeserver_whitelist = re.compile( + self._homeserver_whitelist = re.compile( "({})".format(")|(".join(homeserver_whitelist)) ) - @classmethod @only_if_tracing - def whitelisted_homeserver(cls, destination): - if cls._homeserver_whitelist: - return cls._homeserver_whitelist.match(destination) + def whitelisted_homeserver(self, destination): + if self._homeserver_whitelist: + return self._homeserver_whitelist.match(destination) return False - @classmethod @only_if_tracing def start_active_span_from_context( - cls, + self, headers, operation_name, references=None, @@ -230,11 +219,11 @@ def start_active_span_from_context( # So, we take the first item in the list. # Also, twisted uses byte arrays while opentracing expects strings. header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} - context = cls._opentracing.tracer.extract( - cls._opentracing.Format.HTTP_HEADERS, header_dict + context = self._opentracing.tracer.extract( + self._opentracing.Format.HTTP_HEADERS, header_dict ) - cls._opentracing.tracer.start_active_span( + self._opentracing.tracer.start_active_span( operation_name, child_of=context, references=references, @@ -244,9 +233,8 @@ def start_active_span_from_context( finish_on_close=finish_on_close, ) - @classmethod @only_if_tracing - def inject_active_span_twisted_headers(cls, headers, destination): + def inject_active_span_twisted_headers(self, headers, destination): """ Injects a span context into twisted headers inplace @@ -265,21 +253,20 @@ def inject_active_span_twisted_headers(cls, headers, destination): https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ - if not TracerUtil.whitelisted_homeserver(destination): + if not self.whitelisted_homeserver(destination): return - span = cls._opentracing.tracer.active_span + span = self._opentracing.tracer.active_span carrier = {} - cls._opentracing.tracer.inject( - span, cls._opentracing.Format.HTTP_HEADERS, carrier + self._opentracing.tracer.inject( + span, self._opentracing.Format.HTTP_HEADERS, carrier ) for key, value in carrier.items(): headers.addRawHeaders(key, value) - @classmethod @only_if_tracing - def inject_active_span_byte_dict(cls, headers, destination): + def inject_active_span_byte_dict(self, headers, destination): """ Injects a span context into a dict where the headers are encoded as byte strings @@ -298,14 +285,14 @@ def inject_active_span_byte_dict(cls, headers, destination): here: https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ - if not TracerUtil.whitelisted_homeserver(destination): + if not self.whitelisted_homeserver(destination): return - span = cls._opentracing.tracer.active_span + span = self._opentracing.tracer.active_span carrier = {} - cls._opentracing.tracer.inject( - span, cls._opentracing.Format.HTTP_HEADERS, carrier + self._opentracing.tracer.inject( + span, self._opentracing.Format.HTTP_HEADERS, carrier ) for key, value in carrier.items(): From e27516b12c88691f5b7be34963ace786cdb70e90 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 11:26:48 +0100 Subject: [PATCH 41/69] Inlcude opentracing as a homeserver member. --- synapse/app/_base.py | 3 --- synapse/server.py | 8 ++++++++ 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 13a2af291d86..d50a9840d4f6 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -240,9 +240,6 @@ def handle_sighup(*args, **kwargs): # Load the certificate from disk. refresh_certificate(hs) - # Start the tracer - synapse.util.tracerutils.TracerUtil.init_tracer(hs.config) - # It is now safe to start your Synapse. hs.start_listening(listeners) hs.get_datastore().start_profiling() diff --git a/synapse/server.py b/synapse/server.py index a9592c396c74..f6ea9e2180e5 100644 --- a/synapse/server.py +++ b/synapse/server.py @@ -98,6 +98,7 @@ from synapse.streams.events import EventSources from synapse.util import Clock from synapse.util.distributor import Distributor +from synapse.util.tracerutils import OpenTracing logger = logging.getLogger(__name__) @@ -223,6 +224,7 @@ def __init__(self, hostname, reactor=None, **kwargs): self.registration_ratelimiter = Ratelimiter() self.datastore = None + self.opentracing = None # Other kwargs are explicit dependencies for depname in kwargs: @@ -230,6 +232,9 @@ def __init__(self, hostname, reactor=None, **kwargs): def setup(self): logger.info("Setting up.") + + self.opentracing = OpenTracing(self.config) + with self.get_db_conn() as conn: self.datastore = self.DATASTORE_CLASS(conn, self) conn.commit() @@ -272,6 +277,9 @@ def get_config(self): def get_distributor(self): return self.distributor + def get_opentracing(self): + return self.opentracing + def get_ratelimiter(self): return self.ratelimiter From 9d2734b3dd60bc9bb2f46cbd1f6683cc5bb5faea Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 11:28:30 +0100 Subject: [PATCH 42/69] Thread opentracing to the request level --- synapse/app/appservice.py | 1 + synapse/app/client_reader.py | 1 + synapse/app/event_creator.py | 1 + synapse/app/federation_reader.py | 1 + synapse/app/federation_sender.py | 1 + synapse/app/frontend_proxy.py | 1 + synapse/app/homeserver.py | 2 ++ synapse/app/media_repository.py | 1 + synapse/app/pusher.py | 1 + synapse/app/synchrotron.py | 1 + synapse/app/user_dir.py | 1 + synapse/http/site.py | 26 ++++++++++++++------------ 12 files changed, 26 insertions(+), 12 deletions(-) diff --git a/synapse/app/appservice.py b/synapse/app/appservice.py index 9120bdb1438c..fb8bb4c0cde6 100644 --- a/synapse/app/appservice.py +++ b/synapse/app/appservice.py @@ -76,6 +76,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/client_reader.py b/synapse/app/client_reader.py index 90bc79cdda87..aa7221a409e9 100644 --- a/synapse/app/client_reader.py +++ b/synapse/app/client_reader.py @@ -135,6 +135,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/event_creator.py b/synapse/app/event_creator.py index ff522e4499f3..89f4ef620571 100644 --- a/synapse/app/event_creator.py +++ b/synapse/app/event_creator.py @@ -129,6 +129,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/federation_reader.py b/synapse/app/federation_reader.py index 94214209301a..274db331133c 100644 --- a/synapse/app/federation_reader.py +++ b/synapse/app/federation_reader.py @@ -113,6 +113,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), reactor=self.get_reactor(), ) diff --git a/synapse/app/federation_sender.py b/synapse/app/federation_sender.py index 969be58d0b04..e9ec2f8afe53 100644 --- a/synapse/app/federation_sender.py +++ b/synapse/app/federation_sender.py @@ -105,6 +105,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/frontend_proxy.py b/synapse/app/frontend_proxy.py index 2fd7d57ebf1c..53ea00d7bc78 100644 --- a/synapse/app/frontend_proxy.py +++ b/synapse/app/frontend_proxy.py @@ -185,6 +185,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), reactor=self.get_reactor(), ) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index 49da105cf62e..e8b97897dd44 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -133,6 +133,7 @@ def _listener_http(self, config, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), self.tls_server_context_factory, reactor=self.get_reactor(), @@ -149,6 +150,7 @@ def _listener_http(self, config, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), reactor=self.get_reactor(), ) diff --git a/synapse/app/media_repository.py b/synapse/app/media_repository.py index cf0e2036c3fd..b6e407978cf4 100644 --- a/synapse/app/media_repository.py +++ b/synapse/app/media_repository.py @@ -93,6 +93,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/pusher.py b/synapse/app/pusher.py index df29ea5ecbea..7a3ef49a2ee1 100644 --- a/synapse/app/pusher.py +++ b/synapse/app/pusher.py @@ -96,6 +96,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/synchrotron.py b/synapse/app/synchrotron.py index 858949910d0d..8f57d6826eaa 100644 --- a/synapse/app/synchrotron.py +++ b/synapse/app/synchrotron.py @@ -308,6 +308,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/app/user_dir.py b/synapse/app/user_dir.py index 2d9d2e1bbc02..04d775807734 100644 --- a/synapse/app/user_dir.py +++ b/synapse/app/user_dir.py @@ -132,6 +132,7 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, + self.get_opentracing(), ), ) diff --git a/synapse/http/site.py b/synapse/http/site.py index 5e16a7cf5759..f67af7439c39 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -20,7 +20,6 @@ from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext -from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) @@ -48,12 +47,13 @@ class SynapseRequest(Request): logcontext(LoggingContext) : the log context for this request """ - def __init__(self, site, channel, *args, **kw): + def __init__(self, site, opentracing, channel, *args, **kw): Request.__init__(self, channel, *args, **kw) self.site = site self._channel = channel # this is used by the tests self.authenticated_entity = None self.start_time = 0 + self.opentracing = opentracing # we can't yet create the logcontext, as we don't know the method. self.logcontext = None @@ -236,15 +236,15 @@ def _started_processing(self, servlet_name): ) # Start a span - TracerUtil.start_active_span_from_context( + self.opentracing.start_active_span_from_context( self.requestHeaders, "incoming-federation-request", tags={ "request_id": self.get_request_id(), - TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_SERVER, - TracerUtil.tags.HTTP_METHOD: self.get_method(), - TracerUtil.tags.HTTP_URL: self.get_redacted_uri(), - TracerUtil.tags.PEER_HOST_IPV6: self.getClientIP(), + self.opentracing.tags.SPAN_KIND: self.opentracing.tags.SPAN_KIND_RPC_SERVER, + self.opentracing.tags.HTTP_METHOD: self.get_method(), + self.opentracing.tags.HTTP_URL: self.get_redacted_uri(), + self.opentracing.tags.PEER_HOST_IPV6: self.getClientIP(), }, ) @@ -318,8 +318,8 @@ def _finished_processing(self): ) # finish the span if it's there. - TracerUtil.set_tag("peer.address", authenticated_entity) - TracerUtil.close_active_span() + self.opentracing.set_tag("peer.address", authenticated_entity) + self.opentracing.close_active_span() try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) @@ -351,15 +351,16 @@ def getClientIP(self): class SynapseRequestFactory(object): - def __init__(self, site, x_forwarded_for): + def __init__(self, site, x_forwarded_for, opentracing): self.site = site self.x_forwarded_for = x_forwarded_for + self.opentracing = opentracing def __call__(self, *args, **kwargs): if self.x_forwarded_for: return XForwardedForRequest(self.site, *args, **kwargs) else: - return SynapseRequest(self.site, *args, **kwargs) + return SynapseRequest(self.site, self.opentracing, *args, **kwargs) class SynapseSite(Site): @@ -375,6 +376,7 @@ def __init__( config, resource, server_version_string, + opentracing, *args, **kwargs ): @@ -383,7 +385,7 @@ def __init__( self.site_tag = site_tag proxied = config.get("x_forwarded", False) - self.requestFactory = SynapseRequestFactory(self, proxied) + self.requestFactory = SynapseRequestFactory(self, proxied, opentracing) self.access_logger = logging.getLogger(logger_name) self.server_version_string = server_version_string.encode("ascii") From df255d7e9254c8eca8dbafddba0336bdf0784b17 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 11:29:49 +0100 Subject: [PATCH 43/69] Reference opetnracing through hs --- synapse/http/matrixfederationclient.py | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index c242f1c9c57d..a102c180f0e1 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -51,7 +51,6 @@ from synapse.util.async_helpers import timeout_deferred from synapse.util.logcontext import make_deferred_yieldable from synapse.util.metrics import Measure -from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) @@ -174,6 +173,7 @@ def __init__(self, hs, tls_client_options_factory): self.hs = hs self.signing_key = hs.config.signing_key[0] self.server_name = hs.hostname + self._opentracing = hs.get_opentracing() real_reactor = hs.get_reactor() @@ -341,20 +341,22 @@ def _send_request( query_bytes = b"" # Retreive current span - TracerUtil.start_active_span( + self._opentracing.start_active_span( "outgoing-federation-request", tags={ - TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_CLIENT, - TracerUtil.tags.PEER_ADDRESS: request.destination, - TracerUtil.tags.HTTP_METHOD: request.method, - TracerUtil.tags.HTTP_URL: request.path, + self._opentracing.tags.SPAN_KIND: self._opentracing.tags.SPAN_KIND_RPC_CLIENT, + self._opentracing.tags.PEER_ADDRESS: request.destination, + self._opentracing.tags.HTTP_METHOD: request.method, + self._opentracing.tags.HTTP_URL: request.path, }, finish_on_close=True, ) # Inject the span into the headers headers_dict = {} - TracerUtil.inject_active_span_byte_dict(headers_dict, request.destination) + self._opentracing.inject_active_span_byte_dict( + headers_dict, request.destination + ) headers_dict[b"User-Agent"] = [self.version_string_bytes] @@ -436,7 +438,9 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - TracerUtil.set_tag(TracerUtil.tags.HTTP_STATUS_CODE, response.code) + self._opentracing.set_tag( + self._opentracing.tags.HTTP_STATUS_CODE, response.code + ) if 200 <= response.code < 300: pass @@ -518,7 +522,7 @@ def _send_request( _flatten_response_never_received(e), ) raise - TracerUtil.close_active_span() + self._opentracing.close_active_span() defer.returnValue(response) def build_auth_headers( From 64f8510d1d65c07450cfc600d25447aa448d291f Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 11:30:04 +0100 Subject: [PATCH 44/69] Instantiate dummy opentracin g for tests. --- tests/server.py | 3 ++- tests/test_server.py | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/server.py b/tests/server.py index e573c4e4c5ce..24fde3ce71f0 100644 --- a/tests/server.py +++ b/tests/server.py @@ -19,6 +19,7 @@ from synapse.http.site import SynapseRequest from synapse.util import Clock +from synapse.util.tracerutils import OpenTracing from tests.utils import setup_test_homeserver as _sth @@ -170,7 +171,7 @@ def make_request( site = FakeSite() channel = FakeChannel(reactor) - req = request(site, channel) + req = request(site, OpenTracing(), channel) req.process = lambda: b"" req.content = BytesIO(content) req.postpath = list(map(unquote, path[1:].split(b"/"))) diff --git a/tests/test_server.py b/tests/test_server.py index da29ae92ced7..8e3f293c131d 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -28,6 +28,7 @@ from synapse.http.site import SynapseSite, logger from synapse.util import Clock from synapse.util.logcontext import make_deferred_yieldable +from synapse.util.tracerutils import OpenTracing from tests import unittest from tests.server import ( @@ -181,7 +182,7 @@ def render(self, request): # time out the request while it's 'processing' base_resource = Resource() base_resource.putChild(b"", HangingResource()) - site = SynapseSite("test", "site_tag", {}, base_resource, "1.0") + site = SynapseSite("test", "site_tag", {}, base_resource, "1.0", OpenTracing()) server = site.buildProtocol(None) client = AccumulatingProtocol() From 69561e0f0d4d660930932c6c6d71731eaf150665 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 15:54:38 +0100 Subject: [PATCH 45/69] About to revert, just keeping the unfinished changes just in case --- synapse/app/_base.py | 1 + synapse/app/homeserver.py | 4 ++++ synapse/federation/transport/server.py | 17 +++++++++++++++++ synapse/http/site.py | 19 +------------------ synapse/server.py | 4 ---- 5 files changed, 23 insertions(+), 22 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index d50a9840d4f6..cc7cf6ff0a74 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -241,6 +241,7 @@ def handle_sighup(*args, **kwargs): refresh_certificate(hs) # It is now safe to start your Synapse. + hs.start_tracing() hs.start_listening(listeners) hs.get_datastore().start_profiling() diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index e8b97897dd44..f019152f1c33 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -77,6 +77,7 @@ from synapse.util.module_loader import load_module from synapse.util.rlimit import change_resource_limit from synapse.util.versionstring import get_version_string +from synapse.util.tracerutils import OpenTracing logger = logging.getLogger("synapse.app.homeserver") @@ -261,6 +262,9 @@ def _configure_named_resource(self, name, compress=False): return resources + def start_tracing(self): + self.opentracing = OpenTracing(self.config) + def start_listening(self, listeners): config = self.get_config() diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index 955f0f430825..dbaeb15d2653 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -288,6 +288,20 @@ def new_func(request, *args, **kwargs): logger.warn("authenticate_request failed: %s", e) raise + # Start a span + request.opentracing.start_active_span_from_context( + request.requestHeaders, + "incoming-request", + tags={ + "request_id": request.get_request_id(), + request.opentracing.tags.SPAN_KIND: request.opentracing.tags.SPAN_KIND_RPC_SERVER, + request.opentracing.tags.HTTP_METHOD: request.get_method(), + request.opentracing.tags.HTTP_URL: request.get_redacted_uri(), + request.opentracing.tags.PEER_HOST_IPV6: request.getClientIP(), + }, + ) + request.opentracing.set_tag("authenticated_entity", origin) + if origin: with ratelimiter.ratelimit(origin) as d: yield d @@ -297,6 +311,9 @@ def new_func(request, *args, **kwargs): else: response = yield func(origin, content, request.args, *args, **kwargs) + # Finish the span + request.opentracing.close_active_span() + defer.returnValue(response) # Extra logic that functools.wraps() doesn't finish diff --git a/synapse/http/site.py b/synapse/http/site.py index f67af7439c39..4e1780c538cb 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -235,19 +235,6 @@ def _started_processing(self, servlet_name): self.get_redacted_uri(), ) - # Start a span - self.opentracing.start_active_span_from_context( - self.requestHeaders, - "incoming-federation-request", - tags={ - "request_id": self.get_request_id(), - self.opentracing.tags.SPAN_KIND: self.opentracing.tags.SPAN_KIND_RPC_SERVER, - self.opentracing.tags.HTTP_METHOD: self.get_method(), - self.opentracing.tags.HTTP_URL: self.get_redacted_uri(), - self.opentracing.tags.PEER_HOST_IPV6: self.getClientIP(), - }, - ) - def _finished_processing(self): """Log the completion of this request and update the metrics """ @@ -317,10 +304,6 @@ def _finished_processing(self): usage.evt_db_fetch_count, ) - # finish the span if it's there. - self.opentracing.set_tag("peer.address", authenticated_entity) - self.opentracing.close_active_span() - try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) except Exception as e: @@ -358,7 +341,7 @@ def __init__(self, site, x_forwarded_for, opentracing): def __call__(self, *args, **kwargs): if self.x_forwarded_for: - return XForwardedForRequest(self.site, *args, **kwargs) + return XForwardedForRequest(self.site, self.opentracing, *args, **kwargs) else: return SynapseRequest(self.site, self.opentracing, *args, **kwargs) diff --git a/synapse/server.py b/synapse/server.py index f6ea9e2180e5..11abc2d19638 100644 --- a/synapse/server.py +++ b/synapse/server.py @@ -98,7 +98,6 @@ from synapse.streams.events import EventSources from synapse.util import Clock from synapse.util.distributor import Distributor -from synapse.util.tracerutils import OpenTracing logger = logging.getLogger(__name__) @@ -232,9 +231,6 @@ def __init__(self, hostname, reactor=None, **kwargs): def setup(self): logger.info("Setting up.") - - self.opentracing = OpenTracing(self.config) - with self.get_db_conn() as conn: self.datastore = self.DATASTORE_CLASS(conn, self) conn.commit() From 46564031b303b15b4ebd0c72c3dfcabebf522b5e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 16:05:10 +0100 Subject: [PATCH 46/69] Revert back to global state, commit number: 9ce4a3d9067bf9889b86c360c05ac88618b85c4f --- synapse/app/_base.py | 4 +- synapse/app/appservice.py | 1 - synapse/app/client_reader.py | 1 - synapse/app/event_creator.py | 1 - synapse/app/federation_reader.py | 1 - synapse/app/federation_sender.py | 1 - synapse/app/frontend_proxy.py | 1 - synapse/app/homeserver.py | 6 -- synapse/app/media_repository.py | 1 - synapse/app/pusher.py | 1 - synapse/app/synchrotron.py | 1 - synapse/app/user_dir.py | 1 - synapse/federation/transport/server.py | 17 ---- synapse/http/matrixfederationclient.py | 22 ++--- synapse/http/site.py | 31 +++++-- synapse/server.py | 4 - synapse/util/tracerutils.py | 109 ++++++++++++++----------- tests/server.py | 3 +- tests/test_server.py | 3 +- 19 files changed, 98 insertions(+), 111 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index cc7cf6ff0a74..13a2af291d86 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -240,8 +240,10 @@ def handle_sighup(*args, **kwargs): # Load the certificate from disk. refresh_certificate(hs) + # Start the tracer + synapse.util.tracerutils.TracerUtil.init_tracer(hs.config) + # It is now safe to start your Synapse. - hs.start_tracing() hs.start_listening(listeners) hs.get_datastore().start_profiling() diff --git a/synapse/app/appservice.py b/synapse/app/appservice.py index fb8bb4c0cde6..9120bdb1438c 100644 --- a/synapse/app/appservice.py +++ b/synapse/app/appservice.py @@ -76,7 +76,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/client_reader.py b/synapse/app/client_reader.py index aa7221a409e9..90bc79cdda87 100644 --- a/synapse/app/client_reader.py +++ b/synapse/app/client_reader.py @@ -135,7 +135,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/event_creator.py b/synapse/app/event_creator.py index 89f4ef620571..ff522e4499f3 100644 --- a/synapse/app/event_creator.py +++ b/synapse/app/event_creator.py @@ -129,7 +129,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/federation_reader.py b/synapse/app/federation_reader.py index 274db331133c..94214209301a 100644 --- a/synapse/app/federation_reader.py +++ b/synapse/app/federation_reader.py @@ -113,7 +113,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), reactor=self.get_reactor(), ) diff --git a/synapse/app/federation_sender.py b/synapse/app/federation_sender.py index e9ec2f8afe53..969be58d0b04 100644 --- a/synapse/app/federation_sender.py +++ b/synapse/app/federation_sender.py @@ -105,7 +105,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/frontend_proxy.py b/synapse/app/frontend_proxy.py index 53ea00d7bc78..2fd7d57ebf1c 100644 --- a/synapse/app/frontend_proxy.py +++ b/synapse/app/frontend_proxy.py @@ -185,7 +185,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), reactor=self.get_reactor(), ) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index f019152f1c33..49da105cf62e 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -77,7 +77,6 @@ from synapse.util.module_loader import load_module from synapse.util.rlimit import change_resource_limit from synapse.util.versionstring import get_version_string -from synapse.util.tracerutils import OpenTracing logger = logging.getLogger("synapse.app.homeserver") @@ -134,7 +133,6 @@ def _listener_http(self, config, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), self.tls_server_context_factory, reactor=self.get_reactor(), @@ -151,7 +149,6 @@ def _listener_http(self, config, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), reactor=self.get_reactor(), ) @@ -262,9 +259,6 @@ def _configure_named_resource(self, name, compress=False): return resources - def start_tracing(self): - self.opentracing = OpenTracing(self.config) - def start_listening(self, listeners): config = self.get_config() diff --git a/synapse/app/media_repository.py b/synapse/app/media_repository.py index b6e407978cf4..cf0e2036c3fd 100644 --- a/synapse/app/media_repository.py +++ b/synapse/app/media_repository.py @@ -93,7 +93,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/pusher.py b/synapse/app/pusher.py index 7a3ef49a2ee1..df29ea5ecbea 100644 --- a/synapse/app/pusher.py +++ b/synapse/app/pusher.py @@ -96,7 +96,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/synchrotron.py b/synapse/app/synchrotron.py index 8f57d6826eaa..858949910d0d 100644 --- a/synapse/app/synchrotron.py +++ b/synapse/app/synchrotron.py @@ -308,7 +308,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/app/user_dir.py b/synapse/app/user_dir.py index 04d775807734..2d9d2e1bbc02 100644 --- a/synapse/app/user_dir.py +++ b/synapse/app/user_dir.py @@ -132,7 +132,6 @@ def _listen_http(self, listener_config): listener_config, root_resource, self.version_string, - self.get_opentracing(), ), ) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index dbaeb15d2653..955f0f430825 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -288,20 +288,6 @@ def new_func(request, *args, **kwargs): logger.warn("authenticate_request failed: %s", e) raise - # Start a span - request.opentracing.start_active_span_from_context( - request.requestHeaders, - "incoming-request", - tags={ - "request_id": request.get_request_id(), - request.opentracing.tags.SPAN_KIND: request.opentracing.tags.SPAN_KIND_RPC_SERVER, - request.opentracing.tags.HTTP_METHOD: request.get_method(), - request.opentracing.tags.HTTP_URL: request.get_redacted_uri(), - request.opentracing.tags.PEER_HOST_IPV6: request.getClientIP(), - }, - ) - request.opentracing.set_tag("authenticated_entity", origin) - if origin: with ratelimiter.ratelimit(origin) as d: yield d @@ -311,9 +297,6 @@ def new_func(request, *args, **kwargs): else: response = yield func(origin, content, request.args, *args, **kwargs) - # Finish the span - request.opentracing.close_active_span() - defer.returnValue(response) # Extra logic that functools.wraps() doesn't finish diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index a102c180f0e1..c242f1c9c57d 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -51,6 +51,7 @@ from synapse.util.async_helpers import timeout_deferred from synapse.util.logcontext import make_deferred_yieldable from synapse.util.metrics import Measure +from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) @@ -173,7 +174,6 @@ def __init__(self, hs, tls_client_options_factory): self.hs = hs self.signing_key = hs.config.signing_key[0] self.server_name = hs.hostname - self._opentracing = hs.get_opentracing() real_reactor = hs.get_reactor() @@ -341,22 +341,20 @@ def _send_request( query_bytes = b"" # Retreive current span - self._opentracing.start_active_span( + TracerUtil.start_active_span( "outgoing-federation-request", tags={ - self._opentracing.tags.SPAN_KIND: self._opentracing.tags.SPAN_KIND_RPC_CLIENT, - self._opentracing.tags.PEER_ADDRESS: request.destination, - self._opentracing.tags.HTTP_METHOD: request.method, - self._opentracing.tags.HTTP_URL: request.path, + TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_CLIENT, + TracerUtil.tags.PEER_ADDRESS: request.destination, + TracerUtil.tags.HTTP_METHOD: request.method, + TracerUtil.tags.HTTP_URL: request.path, }, finish_on_close=True, ) # Inject the span into the headers headers_dict = {} - self._opentracing.inject_active_span_byte_dict( - headers_dict, request.destination - ) + TracerUtil.inject_active_span_byte_dict(headers_dict, request.destination) headers_dict[b"User-Agent"] = [self.version_string_bytes] @@ -438,9 +436,7 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - self._opentracing.set_tag( - self._opentracing.tags.HTTP_STATUS_CODE, response.code - ) + TracerUtil.set_tag(TracerUtil.tags.HTTP_STATUS_CODE, response.code) if 200 <= response.code < 300: pass @@ -522,7 +518,7 @@ def _send_request( _flatten_response_never_received(e), ) raise - self._opentracing.close_active_span() + TracerUtil.close_active_span() defer.returnValue(response) def build_auth_headers( diff --git a/synapse/http/site.py b/synapse/http/site.py index 4e1780c538cb..5e16a7cf5759 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -20,6 +20,7 @@ from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext +from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) @@ -47,13 +48,12 @@ class SynapseRequest(Request): logcontext(LoggingContext) : the log context for this request """ - def __init__(self, site, opentracing, channel, *args, **kw): + def __init__(self, site, channel, *args, **kw): Request.__init__(self, channel, *args, **kw) self.site = site self._channel = channel # this is used by the tests self.authenticated_entity = None self.start_time = 0 - self.opentracing = opentracing # we can't yet create the logcontext, as we don't know the method. self.logcontext = None @@ -235,6 +235,19 @@ def _started_processing(self, servlet_name): self.get_redacted_uri(), ) + # Start a span + TracerUtil.start_active_span_from_context( + self.requestHeaders, + "incoming-federation-request", + tags={ + "request_id": self.get_request_id(), + TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_SERVER, + TracerUtil.tags.HTTP_METHOD: self.get_method(), + TracerUtil.tags.HTTP_URL: self.get_redacted_uri(), + TracerUtil.tags.PEER_HOST_IPV6: self.getClientIP(), + }, + ) + def _finished_processing(self): """Log the completion of this request and update the metrics """ @@ -304,6 +317,10 @@ def _finished_processing(self): usage.evt_db_fetch_count, ) + # finish the span if it's there. + TracerUtil.set_tag("peer.address", authenticated_entity) + TracerUtil.close_active_span() + try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) except Exception as e: @@ -334,16 +351,15 @@ def getClientIP(self): class SynapseRequestFactory(object): - def __init__(self, site, x_forwarded_for, opentracing): + def __init__(self, site, x_forwarded_for): self.site = site self.x_forwarded_for = x_forwarded_for - self.opentracing = opentracing def __call__(self, *args, **kwargs): if self.x_forwarded_for: - return XForwardedForRequest(self.site, self.opentracing, *args, **kwargs) + return XForwardedForRequest(self.site, *args, **kwargs) else: - return SynapseRequest(self.site, self.opentracing, *args, **kwargs) + return SynapseRequest(self.site, *args, **kwargs) class SynapseSite(Site): @@ -359,7 +375,6 @@ def __init__( config, resource, server_version_string, - opentracing, *args, **kwargs ): @@ -368,7 +383,7 @@ def __init__( self.site_tag = site_tag proxied = config.get("x_forwarded", False) - self.requestFactory = SynapseRequestFactory(self, proxied, opentracing) + self.requestFactory = SynapseRequestFactory(self, proxied) self.access_logger = logging.getLogger(logger_name) self.server_version_string = server_version_string.encode("ascii") diff --git a/synapse/server.py b/synapse/server.py index 11abc2d19638..a9592c396c74 100644 --- a/synapse/server.py +++ b/synapse/server.py @@ -223,7 +223,6 @@ def __init__(self, hostname, reactor=None, **kwargs): self.registration_ratelimiter = Ratelimiter() self.datastore = None - self.opentracing = None # Other kwargs are explicit dependencies for depname in kwargs: @@ -273,9 +272,6 @@ def get_config(self): def get_distributor(self): return self.distributor - def get_opentracing(self): - return self.opentracing - def get_ratelimiter(self): return self.ratelimiter diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 920129477d44..ea6c471b9591 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -57,24 +57,26 @@ def only_if_tracing(func): Assumes the function wrapped may return None""" @wraps(func) - def f(self, *args, **kwargs): - if self._opentracing: - return func(self, *args, **kwargs) + def f(cls, *args, **kwargs): + if cls._opentracing: + return func(cls, *args, **kwargs) else: return return f -class OpenTracing(object): +class TracerUtil(object): _opentracing = None + _opentracing_formats = None # Block everything by default _homeserver_whitelist = None tags = _DumTagNames - def __init__(self, config=None): + @classmethod + def init_tracer(cls, config): """Set the whitelists and initialise the JaegerClient tracer Args: @@ -82,18 +84,16 @@ def __init__(self, config=None): The config used by the homserver. Here it's used to set the service name to the homeserver's. """ - # If no config is given do not trace. This is useful for testing - if config is None: - return if not config.tracer_config.get("tracer_enabled", False): # We don't have a tracer return - self.import_opentracing() - self.setup_tags() - self.setup_tracing(config) + cls.import_opentracing() + cls.setup_tags() + cls.setup_tracing(config) - def import_opentracing(self): + @classmethod + def import_opentracing(cls): try: # Try to import the tracer. If it's not there we want to throw an eror import opentracing @@ -104,9 +104,10 @@ def import_opentracing(self): ) raise - self._opentracing = opentracing + cls._opentracing = opentracing - def setup_tracing(self, config): + @classmethod + def setup_tracing(cls, config): try: from jaeger_client import Config as JaegerConfig from synapse.util.scopecontextmanager import LogContextScopeManager @@ -120,7 +121,7 @@ def setup_tracing(self, config): # Include the worker name name = config.worker_name if config.worker_name else "master" - self.set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) + cls.set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) jaeger_config = JaegerConfig( config={"sampler": {"type": "const", "param": 1}, "logging": True}, service_name="{} {}".format(config.server_name, name), @@ -128,14 +129,16 @@ def setup_tracing(self, config): ) jaeger_config.initialize_tracer() + @classmethod @only_if_tracing - def setup_tags(self): - self.tags = self._opentracing.tags + def setup_tags(cls): + cls.tags = cls._opentracing.tags # Could use kwargs but I want these to be explicit + @classmethod @only_if_tracing def start_active_span( - self, + cls, operation_name, child_of=None, references=None, @@ -145,7 +148,7 @@ def start_active_span( finish_on_close=True, ): # We need to enter the scope here for the logcontext to become active - self._opentracing.tracer.start_active_span( + cls._opentracing.tracer.start_active_span( operation_name, child_of=child_of, references=references, @@ -155,31 +158,37 @@ def start_active_span( finish_on_close=finish_on_close, ).__enter__() + @classmethod @only_if_tracing - def close_active_span(self): - self._opentracing.tracer.scope_manager.active.__exit__(None, None, None) + def close_active_span(cls): + cls._opentracing.tracer.scope_manager.active.__exit__(None, None, None) + @classmethod @only_if_tracing - def set_tag(self, key, value): - self._opentracing.tracer.active_span.set_tag(key, value) + def set_tag(cls, key, value): + cls._opentracing.tracer.active_span.set_tag(key, value) + @classmethod @only_if_tracing - def log_kv(self, key_values, timestamp=None): - self._opentracing.tracer.active_span.log_kv(key_values, timestamp) + def log_kv(cls, key_values, timestamp=None): + cls._opentracing.tracer.active_span.log_kv(key_values, timestamp) # Note: we don't have a get baggage items because we're trying to hide all # scope and span state from synapse. I think this method may also be useless # as a result + @classmethod @only_if_tracing - def set_baggage_item(self, key, value): - self._opentracing.tracer.active_span.set_baggage_item(key, value) + def set_baggage_item(cls, key, value): + cls._opentracing.tracer.active_span.set_baggage_item(key, value) + @classmethod @only_if_tracing - def set_operation_name(self, operation_name): - self._opentracing.tracer.active_span.set_operation_name(operation_name) + def set_operation_name(cls, operation_name): + cls._opentracing.tracer.active_span.set_operation_name(operation_name) + @classmethod @only_if_tracing - def set_homeserver_whitelist(self, homeserver_whitelist): + def set_homeserver_whitelist(cls, homeserver_whitelist): """Sets the whitelist Args: @@ -187,19 +196,21 @@ def set_homeserver_whitelist(self, homeserver_whitelist): """ if homeserver_whitelist: # Makes a single regex which accepts all passed in regexes in the list - self._homeserver_whitelist = re.compile( + cls._homeserver_whitelist = re.compile( "({})".format(")|(".join(homeserver_whitelist)) ) + @classmethod @only_if_tracing - def whitelisted_homeserver(self, destination): - if self._homeserver_whitelist: - return self._homeserver_whitelist.match(destination) + def whitelisted_homeserver(cls, destination): + if cls._homeserver_whitelist: + return cls._homeserver_whitelist.match(destination) return False + @classmethod @only_if_tracing def start_active_span_from_context( - self, + cls, headers, operation_name, references=None, @@ -219,11 +230,11 @@ def start_active_span_from_context( # So, we take the first item in the list. # Also, twisted uses byte arrays while opentracing expects strings. header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} - context = self._opentracing.tracer.extract( - self._opentracing.Format.HTTP_HEADERS, header_dict + context = cls._opentracing.tracer.extract( + cls._opentracing.Format.HTTP_HEADERS, header_dict ) - self._opentracing.tracer.start_active_span( + cls._opentracing.tracer.start_active_span( operation_name, child_of=context, references=references, @@ -233,8 +244,9 @@ def start_active_span_from_context( finish_on_close=finish_on_close, ) + @classmethod @only_if_tracing - def inject_active_span_twisted_headers(self, headers, destination): + def inject_active_span_twisted_headers(cls, headers, destination): """ Injects a span context into twisted headers inplace @@ -253,20 +265,21 @@ def inject_active_span_twisted_headers(self, headers, destination): https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ - if not self.whitelisted_homeserver(destination): + if not TracerUtil.whitelisted_homeserver(destination): return - span = self._opentracing.tracer.active_span + span = cls._opentracing.tracer.active_span carrier = {} - self._opentracing.tracer.inject( - span, self._opentracing.Format.HTTP_HEADERS, carrier + cls._opentracing.tracer.inject( + span, cls._opentracing.Format.HTTP_HEADERS, carrier ) for key, value in carrier.items(): headers.addRawHeaders(key, value) + @classmethod @only_if_tracing - def inject_active_span_byte_dict(self, headers, destination): + def inject_active_span_byte_dict(cls, headers, destination): """ Injects a span context into a dict where the headers are encoded as byte strings @@ -285,14 +298,14 @@ def inject_active_span_byte_dict(self, headers, destination): here: https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ - if not self.whitelisted_homeserver(destination): + if not TracerUtil.whitelisted_homeserver(destination): return - span = self._opentracing.tracer.active_span + span = cls._opentracing.tracer.active_span carrier = {} - self._opentracing.tracer.inject( - span, self._opentracing.Format.HTTP_HEADERS, carrier + cls._opentracing.tracer.inject( + span, cls._opentracing.Format.HTTP_HEADERS, carrier ) for key, value in carrier.items(): diff --git a/tests/server.py b/tests/server.py index 24fde3ce71f0..e573c4e4c5ce 100644 --- a/tests/server.py +++ b/tests/server.py @@ -19,7 +19,6 @@ from synapse.http.site import SynapseRequest from synapse.util import Clock -from synapse.util.tracerutils import OpenTracing from tests.utils import setup_test_homeserver as _sth @@ -171,7 +170,7 @@ def make_request( site = FakeSite() channel = FakeChannel(reactor) - req = request(site, OpenTracing(), channel) + req = request(site, channel) req.process = lambda: b"" req.content = BytesIO(content) req.postpath = list(map(unquote, path[1:].split(b"/"))) diff --git a/tests/test_server.py b/tests/test_server.py index 8e3f293c131d..da29ae92ced7 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -28,7 +28,6 @@ from synapse.http.site import SynapseSite, logger from synapse.util import Clock from synapse.util.logcontext import make_deferred_yieldable -from synapse.util.tracerutils import OpenTracing from tests import unittest from tests.server import ( @@ -182,7 +181,7 @@ def render(self, request): # time out the request while it's 'processing' base_resource = Resource() base_resource.putChild(b"", HangingResource()) - site = SynapseSite("test", "site_tag", {}, base_resource, "1.0", OpenTracing()) + site = SynapseSite("test", "site_tag", {}, base_resource, "1.0") server = site.buildProtocol(None) client = AccumulatingProtocol() From a60572ff76375592be4a4d910d9056af1912a9e5 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 16:46:38 +0100 Subject: [PATCH 47/69] Use class level methods in tracerutils --- synapse/app/_base.py | 2 +- synapse/http/matrixfederationclient.py | 20 +- synapse/http/site.py | 16 +- synapse/util/tracerutils.py | 453 ++++++++++++------------- 4 files changed, 245 insertions(+), 246 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 13a2af291d86..69f7f243344c 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -241,7 +241,7 @@ def handle_sighup(*args, **kwargs): refresh_certificate(hs) # Start the tracer - synapse.util.tracerutils.TracerUtil.init_tracer(hs.config) + synapse.util.tracerutils.init_tracer(hs.config) # It is now safe to start your Synapse. hs.start_listening(listeners) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index c242f1c9c57d..0cc221e8def2 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -38,6 +38,7 @@ import synapse.metrics import synapse.util.retryutils +import synapse.util.tracerutils as tracerutils from synapse.api.errors import ( Codes, FederationDeniedError, @@ -51,7 +52,6 @@ from synapse.util.async_helpers import timeout_deferred from synapse.util.logcontext import make_deferred_yieldable from synapse.util.metrics import Measure -from synapse.util.tracerutils import TracerUtil logger = logging.getLogger(__name__) @@ -341,20 +341,20 @@ def _send_request( query_bytes = b"" # Retreive current span - TracerUtil.start_active_span( + tracerutils.start_active_span( "outgoing-federation-request", tags={ - TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_CLIENT, - TracerUtil.tags.PEER_ADDRESS: request.destination, - TracerUtil.tags.HTTP_METHOD: request.method, - TracerUtil.tags.HTTP_URL: request.path, + tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_CLIENT, + tracerutils.tags.PEER_ADDRESS: request.destination, + tracerutils.tags.HTTP_METHOD: request.method, + tracerutils.tags.HTTP_URL: request.path, }, finish_on_close=True, ) # Inject the span into the headers headers_dict = {} - TracerUtil.inject_active_span_byte_dict(headers_dict, request.destination) + tracerutils.inject_active_span_byte_dict(headers_dict, request.destination) headers_dict[b"User-Agent"] = [self.version_string_bytes] @@ -436,7 +436,9 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - TracerUtil.set_tag(TracerUtil.tags.HTTP_STATUS_CODE, response.code) + tracerutils.set_tag( + tracerutils.tags.HTTP_STATUS_CODE, response.code + ) if 200 <= response.code < 300: pass @@ -518,7 +520,7 @@ def _send_request( _flatten_response_never_received(e), ) raise - TracerUtil.close_active_span() + tracerutils.close_active_span() defer.returnValue(response) def build_auth_headers( diff --git a/synapse/http/site.py b/synapse/http/site.py index 5e16a7cf5759..2aa5fcef0e69 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -20,7 +20,7 @@ from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext -from synapse.util.tracerutils import TracerUtil +import synapse.util.tracerutils as tracerutils logger = logging.getLogger(__name__) @@ -236,15 +236,15 @@ def _started_processing(self, servlet_name): ) # Start a span - TracerUtil.start_active_span_from_context( + tracerutils.start_active_span_from_context( self.requestHeaders, "incoming-federation-request", tags={ "request_id": self.get_request_id(), - TracerUtil.tags.SPAN_KIND: TracerUtil.tags.SPAN_KIND_RPC_SERVER, - TracerUtil.tags.HTTP_METHOD: self.get_method(), - TracerUtil.tags.HTTP_URL: self.get_redacted_uri(), - TracerUtil.tags.PEER_HOST_IPV6: self.getClientIP(), + tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_SERVER, + tracerutils.tags.HTTP_METHOD: self.get_method(), + tracerutils.tags.HTTP_URL: self.get_redacted_uri(), + tracerutils.tags.PEER_HOST_IPV6: self.getClientIP(), }, ) @@ -318,8 +318,8 @@ def _finished_processing(self): ) # finish the span if it's there. - TracerUtil.set_tag("peer.address", authenticated_entity) - TracerUtil.close_active_span() + tracerutils.set_tag("peer.address", authenticated_entity) + tracerutils.close_active_span() try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index ea6c471b9591..e691ca3d7987 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -57,256 +57,253 @@ def only_if_tracing(func): Assumes the function wrapped may return None""" @wraps(func) - def f(cls, *args, **kwargs): - if cls._opentracing: - return func(cls, *args, **kwargs) + def f(*args, **kwargs): + if _opentracing: + return func(*args, **kwargs) else: return return f -class TracerUtil(object): - _opentracing = None - _opentracing_formats = None +_opentracing = None - # Block everything by default - _homeserver_whitelist = None +# Block everything by default +_homeserver_whitelist = None - tags = _DumTagNames +tags = _DumTagNames - @classmethod - def init_tracer(cls, config): - """Set the whitelists and initialise the JaegerClient tracer - Args: - config (Config) - The config used by the homserver. Here it's used to set the service - name to the homeserver's. - """ - if not config.tracer_config.get("tracer_enabled", False): - # We don't have a tracer - return +def init_tracer(config): + """Set the whitelists and initialise the JaegerClient tracer - cls.import_opentracing() - cls.setup_tags() - cls.setup_tracing(config) - - @classmethod - def import_opentracing(cls): - try: - # Try to import the tracer. If it's not there we want to throw an eror - import opentracing - except ImportError as e: - logger.error( - "The server has been configure to use opentracing but " - "the {} module has not been installed.".format(e.name) - ) - raise - - cls._opentracing = opentracing - - @classmethod - def setup_tracing(cls, config): - try: - from jaeger_client import Config as JaegerConfig - from synapse.util.scopecontextmanager import LogContextScopeManager - except ImportError as e: - logger.error( - "The server has been configure to use opentracing but " - "the {} module has not been installed.".format(e.name) - ) - raise - - # Include the worker name - name = config.worker_name if config.worker_name else "master" - - cls.set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) - jaeger_config = JaegerConfig( - config={"sampler": {"type": "const", "param": 1}, "logging": True}, - service_name="{} {}".format(config.server_name, name), - scope_manager=LogContextScopeManager(config), - ) - jaeger_config.initialize_tracer() - - @classmethod - @only_if_tracing - def setup_tags(cls): - cls.tags = cls._opentracing.tags - - # Could use kwargs but I want these to be explicit - @classmethod - @only_if_tracing - def start_active_span( - cls, - operation_name, - child_of=None, - references=None, - tags=None, - start_time=None, - ignore_active_span=False, - finish_on_close=True, - ): - # We need to enter the scope here for the logcontext to become active - cls._opentracing.tracer.start_active_span( - operation_name, - child_of=child_of, - references=references, - tags=tags, - start_time=start_time, - ignore_active_span=ignore_active_span, - finish_on_close=finish_on_close, - ).__enter__() - - @classmethod - @only_if_tracing - def close_active_span(cls): - cls._opentracing.tracer.scope_manager.active.__exit__(None, None, None) - - @classmethod - @only_if_tracing - def set_tag(cls, key, value): - cls._opentracing.tracer.active_span.set_tag(key, value) - - @classmethod - @only_if_tracing - def log_kv(cls, key_values, timestamp=None): - cls._opentracing.tracer.active_span.log_kv(key_values, timestamp) - - # Note: we don't have a get baggage items because we're trying to hide all - # scope and span state from synapse. I think this method may also be useless - # as a result - @classmethod - @only_if_tracing - def set_baggage_item(cls, key, value): - cls._opentracing.tracer.active_span.set_baggage_item(key, value) - - @classmethod - @only_if_tracing - def set_operation_name(cls, operation_name): - cls._opentracing.tracer.active_span.set_operation_name(operation_name) - - @classmethod - @only_if_tracing - def set_homeserver_whitelist(cls, homeserver_whitelist): - """Sets the whitelist - - Args: - homeserver_whitelist (iterable of strings): regex of whitelisted homeservers - """ - if homeserver_whitelist: - # Makes a single regex which accepts all passed in regexes in the list - cls._homeserver_whitelist = re.compile( - "({})".format(")|(".join(homeserver_whitelist)) - ) - - @classmethod - @only_if_tracing - def whitelisted_homeserver(cls, destination): - if cls._homeserver_whitelist: - return cls._homeserver_whitelist.match(destination) - return False - - @classmethod - @only_if_tracing - def start_active_span_from_context( - cls, - headers, - operation_name, - references=None, - tags=None, - start_time=None, - ignore_active_span=False, - finish_on_close=True, - ): - """ - Extracts a span context from Twisted Headers. - args: - headers (twisted.web.http_headers.Headers) - returns: - span_context (opentracing.span.SpanContext) - """ - # Twisted encodes the values as lists whereas opentracing doesn't. - # So, we take the first item in the list. - # Also, twisted uses byte arrays while opentracing expects strings. - header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} - context = cls._opentracing.tracer.extract( - cls._opentracing.Format.HTTP_HEADERS, header_dict + Args: + config (Config) + The config used by the homserver. Here it's used to set the service + name to the homeserver's. + """ + if not config.tracer_config.get("tracer_enabled", False): + # We don't have a tracer + return + + import_opentracing() + setup_tags() + setup_tracing(config) + + +def import_opentracing(): + global _opentracing + try: + # Try to import the tracer. If it's not there we want to throw an eror + import opentracing + except ImportError as e: + logger.error( + "The server has been configure to use opentracing but " + "the {} module has not been installed.".format(e.name) ) + raise + + _opentracing = opentracing - cls._opentracing.tracer.start_active_span( - operation_name, - child_of=context, - references=references, - tags=tags, - start_time=start_time, - ignore_active_span=ignore_active_span, - finish_on_close=finish_on_close, + +def setup_tracing(config): + try: + from jaeger_client import Config as JaegerConfig + from synapse.util.scopecontextmanager import LogContextScopeManager + except ImportError as e: + logger.error( + "The server has been configure to use opentracing but " + "the {} module has not been installed.".format(e.name) ) + raise + + # Include the worker name + name = config.worker_name if config.worker_name else "master" + + set_homeserver_whitelist(config.tracer_config["homeserver_whitelist"]) + jaeger_config = JaegerConfig( + config={"sampler": {"type": "const", "param": 1}, "logging": True}, + service_name="{} {}".format(config.server_name, name), + scope_manager=LogContextScopeManager(config), + ) + jaeger_config.initialize_tracer() + + +@only_if_tracing +def setup_tags(): + global tags, _opentracing + tags = _opentracing.tags + + +# Could use kwargs but I want these to be explicit +@only_if_tracing +def start_active_span( + operation_name, + child_of=None, + references=None, + tags=None, + start_time=None, + ignore_active_span=False, + finish_on_close=True, +): + # We need to enter the scope here for the logcontext to become active + _opentracing.tracer.start_active_span( + operation_name, + child_of=child_of, + references=references, + tags=tags, + start_time=start_time, + ignore_active_span=ignore_active_span, + finish_on_close=finish_on_close, + ).__enter__() - @classmethod - @only_if_tracing - def inject_active_span_twisted_headers(cls, headers, destination): - """ - Injects a span context into twisted headers inplace - Args: - headers (twisted.web.http_headers.Headers) - span (opentracing.Span) +@only_if_tracing +def close_active_span(): + _opentracing.tracer.scope_manager.active.__exit__(None, None, None) - Returns: - Inplace modification of headers - Note: - The headers set by the tracer are custom to the tracer implementation which - should be unique enough that they don't interfere with any headers set by - synapse or twisted. If we're still using jaeger these headers would be those - here: - https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py - """ +@only_if_tracing +def set_tag(key, value): + _opentracing.tracer.active_span.set_tag(key, value) - if not TracerUtil.whitelisted_homeserver(destination): - return - span = cls._opentracing.tracer.active_span - carrier = {} - cls._opentracing.tracer.inject( - span, cls._opentracing.Format.HTTP_HEADERS, carrier - ) +@only_if_tracing +def log_kv(key_values, timestamp=None): + _opentracing.tracer.active_span.log_kv(key_values, timestamp) + + +# Note: we don't have a get baggage items because we're trying to hide all +# scope and span state from synapse. I think this method may also be useless +# as a result +@only_if_tracing +def set_baggage_item(key, value): + _opentracing.tracer.active_span.set_baggage_item(key, value) - for key, value in carrier.items(): - headers.addRawHeaders(key, value) - - @classmethod - @only_if_tracing - def inject_active_span_byte_dict(cls, headers, destination): - """ - Injects a span context into a dict where the headers are encoded as byte - strings - - Args: - headers (dict) - span (opentracing.Span) - - Returns: - Inplace modification of headers - - Note: - The headers set by the tracer are custom to the tracer implementation which - should be unique enough that they don't interfere with any headers set by - synapse or twisted. If we're still using jaeger these headers would be those - here: - https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py - """ - if not TracerUtil.whitelisted_homeserver(destination): - return - span = cls._opentracing.tracer.active_span +@only_if_tracing +def set_operation_name(operation_name): + _opentracing.tracer.active_span.set_operation_name(operation_name) - carrier = {} - cls._opentracing.tracer.inject( - span, cls._opentracing.Format.HTTP_HEADERS, carrier + +@only_if_tracing +def set_homeserver_whitelist(homeserver_whitelist): + """Sets the whitelist + + Args: + homeserver_whitelist (iterable of strings): regex of whitelisted homeservers + """ + global _homeserver_whitelist + if homeserver_whitelist: + # Makes a single regex which accepts all passed in regexes in the list + _homeserver_whitelist = re.compile( + "({})".format(")|(".join(homeserver_whitelist)) ) - for key, value in carrier.items(): - headers[key.encode()] = [value.encode()] + +@only_if_tracing +def whitelisted_homeserver(destination): + global _homeserver_whitelist + if _homeserver_whitelist: + return _homeserver_whitelist.match(destination) + return False + + +@only_if_tracing +def start_active_span_from_context( + headers, + operation_name, + references=None, + tags=None, + start_time=None, + ignore_active_span=False, + finish_on_close=True, +): + """ + Extracts a span context from Twisted Headers. + args: + headers (twisted.web.http_headers.Headers) + returns: + span_context (opentracing.span.SpanContext) + """ + global _opentracing + # Twisted encodes the values as lists whereas opentracing doesn't. + # So, we take the first item in the list. + # Also, twisted uses byte arrays while opentracing expects strings. + header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} + context = _opentracing.tracer.extract(_opentracing.Format.HTTP_HEADERS, header_dict) + + _opentracing.tracer.start_active_span( + operation_name, + child_of=context, + references=references, + tags=tags, + start_time=start_time, + ignore_active_span=ignore_active_span, + finish_on_close=finish_on_close, + ) + + +@only_if_tracing +def inject_active_span_twisted_headers(headers, destination): + """ + Injects a span context into twisted headers inplace + + Args: + headers (twisted.web.http_headers.Headers) + span (opentracing.Span) + + Returns: + Inplace modification of headers + + Note: + The headers set by the tracer are custom to the tracer implementation which + should be unique enough that they don't interfere with any headers set by + synapse or twisted. If we're still using jaeger these headers would be those + here: + https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py + """ + global _opentracing + + if not whitelisted_homeserver(destination): + return + + span = _opentracing.tracer.active_span + carrier = {} + _opentracing.tracer.inject(span, _opentracing.Format.HTTP_HEADERS, carrier) + + for key, value in carrier.items(): + headers.addRawHeaders(key, value) + + +@only_if_tracing +def inject_active_span_byte_dict(headers, destination): + """ + Injects a span context into a dict where the headers are encoded as byte + strings + + Args: + headers (dict) + span (opentracing.Span) + + Returns: + Inplace modification of headers + + Note: + The headers set by the tracer are custom to the tracer implementation which + should be unique enough that they don't interfere with any headers set by + synapse or twisted. If we're still using jaeger these headers would be those + here: + https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py + """ + global _opentracing + if not whitelisted_homeserver(destination): + return + + span = _opentracing.tracer.active_span + + carrier = {} + _opentracing.tracer.inject(span, _opentracing.Format.HTTP_HEADERS, carrier) + + for key, value in carrier.items(): + headers[key.encode()] = [value.encode()] From bc6b23693a40299e01ea4431c7244c711f978936 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 16:54:49 +0100 Subject: [PATCH 48/69] Start and stop requests spans in a place where we have access to the authenticated entity --- synapse/federation/transport/server.py | 18 ++++++++++++++++++ synapse/http/site.py | 17 ----------------- 2 files changed, 18 insertions(+), 17 deletions(-) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index 955f0f430825..7f334cbc4f73 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -40,6 +40,7 @@ from synapse.util.logcontext import run_in_background from synapse.util.ratelimitutils import FederationRateLimiter from synapse.util.versionstring import get_version_string +import synapse.util.tracerutils as tracerutils logger = logging.getLogger(__name__) @@ -288,6 +289,20 @@ def new_func(request, *args, **kwargs): logger.warn("authenticate_request failed: %s", e) raise + # Start an opentracing span + tracerutils.start_active_span_from_context( + request.requestHeaders, + "incoming-request", + tags={ + "request_id": request.get_request_id(), + tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_SERVER, + tracerutils.tags.HTTP_METHOD: request.get_method(), + tracerutils.tags.HTTP_URL: request.get_redacted_uri(), + tracerutils.tags.PEER_HOST_IPV6: request.getClientIP(), + "authenticated_entity": origin, + }, + ) + if origin: with ratelimiter.ratelimit(origin) as d: yield d @@ -297,6 +312,9 @@ def new_func(request, *args, **kwargs): else: response = yield func(origin, content, request.args, *args, **kwargs) + # Finish the span + tracerutils.close_active_span() + defer.returnValue(response) # Extra logic that functools.wraps() doesn't finish diff --git a/synapse/http/site.py b/synapse/http/site.py index 2aa5fcef0e69..dbcaa04616c4 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -235,19 +235,6 @@ def _started_processing(self, servlet_name): self.get_redacted_uri(), ) - # Start a span - tracerutils.start_active_span_from_context( - self.requestHeaders, - "incoming-federation-request", - tags={ - "request_id": self.get_request_id(), - tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_SERVER, - tracerutils.tags.HTTP_METHOD: self.get_method(), - tracerutils.tags.HTTP_URL: self.get_redacted_uri(), - tracerutils.tags.PEER_HOST_IPV6: self.getClientIP(), - }, - ) - def _finished_processing(self): """Log the completion of this request and update the metrics """ @@ -317,10 +304,6 @@ def _finished_processing(self): usage.evt_db_fetch_count, ) - # finish the span if it's there. - tracerutils.set_tag("peer.address", authenticated_entity) - tracerutils.close_active_span() - try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) except Exception as e: From 68e4595ad5bba5be5a7a5251af87bc2377d7380d Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 2 Jul 2019 16:58:09 +0100 Subject: [PATCH 49/69] Seen it, isort it --- synapse/federation/transport/server.py | 2 +- synapse/http/site.py | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index 7f334cbc4f73..6eafa63110a4 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -21,6 +21,7 @@ from twisted.internet import defer import synapse +import synapse.util.tracerutils as tracerutils from synapse.api.errors import Codes, FederationDeniedError, SynapseError from synapse.api.room_versions import RoomVersions from synapse.api.urls import ( @@ -40,7 +41,6 @@ from synapse.util.logcontext import run_in_background from synapse.util.ratelimitutils import FederationRateLimiter from synapse.util.versionstring import get_version_string -import synapse.util.tracerutils as tracerutils logger = logging.getLogger(__name__) diff --git a/synapse/http/site.py b/synapse/http/site.py index dbcaa04616c4..7a11af5c0c5c 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -20,7 +20,6 @@ from synapse.http import redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter from synapse.util.logcontext import LoggingContext, PreserveLoggingContext -import synapse.util.tracerutils as tracerutils logger = logging.getLogger(__name__) From 9bfe90fbe9a23c506d7406e9e559f71c83e08c58 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 3 Jul 2019 09:33:16 +0100 Subject: [PATCH 50/69] Make sure to close the active span. --- synapse/federation/transport/server.py | 23 ++++++++++++----------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index 6eafa63110a4..ae9b23056d0e 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -303,17 +303,18 @@ def new_func(request, *args, **kwargs): }, ) - if origin: - with ratelimiter.ratelimit(origin) as d: - yield d - response = yield func( - origin, content, request.args, *args, **kwargs - ) - else: - response = yield func(origin, content, request.args, *args, **kwargs) - - # Finish the span - tracerutils.close_active_span() + try: + if origin: + with ratelimiter.ratelimit(origin) as d: + yield d + response = yield func( + origin, content, request.args, *args, **kwargs + ) + else: + response = yield func(origin, content, request.args, *args, **kwargs) + finally: + # Finish the span + tracerutils.close_active_span() defer.returnValue(response) From 800e7076b1899260c4ad8f8af77c1c41ff77cbb7 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 3 Jul 2019 09:41:58 +0100 Subject: [PATCH 51/69] I'm getting black and blue from this. --- synapse/federation/transport/server.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index ae9b23056d0e..e4d021effb35 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -311,7 +311,9 @@ def new_func(request, *args, **kwargs): origin, content, request.args, *args, **kwargs ) else: - response = yield func(origin, content, request.args, *args, **kwargs) + response = yield func( + origin, content, request.args, *args, **kwargs + ) finally: # Finish the span tracerutils.close_active_span() From b09aa24fb6fe9e679e94e15b22c2af8d6fc6de52 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 3 Jul 2019 15:31:51 +0100 Subject: [PATCH 52/69] Logger formatting Co-Authored-By: Erik Johnston --- synapse/util/tracerutils.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index e691ca3d7987..2832b778d81c 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -99,7 +99,7 @@ def import_opentracing(): except ImportError as e: logger.error( "The server has been configure to use opentracing but " - "the {} module has not been installed.".format(e.name) + "the %s module has not been installed.", e.name ) raise @@ -113,7 +113,7 @@ def setup_tracing(config): except ImportError as e: logger.error( "The server has been configure to use opentracing but " - "the {} module has not been installed.".format(e.name) + "the %s module has not been installed.", e.name ) raise From 374e81ca563edd006e1a335a2ef9da0aa87782b4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 3 Jul 2019 15:26:28 +0100 Subject: [PATCH 53/69] Outdated comment --- synapse/http/site.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 7a11af5c0c5c..93f679ea4845 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -211,7 +211,6 @@ def _started_processing(self, servlet_name): This will log the request's arrival. Once the request completes, be sure to call finished_processing. - It will also start a span for this request. Args: servlet_name (str): the name of the servlet which will be From e111dcdc301eecfaecbcbeea985d1c2c669b2a2e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 3 Jul 2019 15:39:34 +0100 Subject: [PATCH 54/69] Import opentracing at the top --- synapse/util/tracerutils.py | 57 ++++++++++++++++--------------------- 1 file changed, 24 insertions(+), 33 deletions(-) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 2832b778d81c..119267afecf8 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -13,6 +13,11 @@ # See the License for the specific language governing permissions and # limitations under the License.import opentracing +try: + import opentracing +except ImportError: + opentracing = None + import logging import re from functools import wraps @@ -58,7 +63,7 @@ def only_if_tracing(func): @wraps(func) def f(*args, **kwargs): - if _opentracing: + if opentracing: return func(*args, **kwargs) else: return @@ -66,8 +71,6 @@ def f(*args, **kwargs): return f -_opentracing = None - # Block everything by default _homeserver_whitelist = None @@ -86,24 +89,15 @@ def init_tracer(config): # We don't have a tracer return - import_opentracing() - setup_tags() - setup_tracing(config) - - -def import_opentracing(): - global _opentracing - try: - # Try to import the tracer. If it's not there we want to throw an eror - import opentracing - except ImportError as e: + if not opentracing: logger.error( "The server has been configure to use opentracing but " "the %s module has not been installed.", e.name ) - raise + raise ModuleNotFoundError("opentracing") - _opentracing = opentracing + setup_tags() + setup_tracing(config) def setup_tracing(config): @@ -131,8 +125,8 @@ def setup_tracing(config): @only_if_tracing def setup_tags(): - global tags, _opentracing - tags = _opentracing.tags + global tags + tags = opentracing.tags # Could use kwargs but I want these to be explicit @@ -147,7 +141,7 @@ def start_active_span( finish_on_close=True, ): # We need to enter the scope here for the logcontext to become active - _opentracing.tracer.start_active_span( + opentracing.tracer.start_active_span( operation_name, child_of=child_of, references=references, @@ -160,17 +154,17 @@ def start_active_span( @only_if_tracing def close_active_span(): - _opentracing.tracer.scope_manager.active.__exit__(None, None, None) + opentracing.tracer.scope_manager.active.__exit__(None, None, None) @only_if_tracing def set_tag(key, value): - _opentracing.tracer.active_span.set_tag(key, value) + opentracing.tracer.active_span.set_tag(key, value) @only_if_tracing def log_kv(key_values, timestamp=None): - _opentracing.tracer.active_span.log_kv(key_values, timestamp) + opentracing.tracer.active_span.log_kv(key_values, timestamp) # Note: we don't have a get baggage items because we're trying to hide all @@ -178,12 +172,12 @@ def log_kv(key_values, timestamp=None): # as a result @only_if_tracing def set_baggage_item(key, value): - _opentracing.tracer.active_span.set_baggage_item(key, value) + opentracing.tracer.active_span.set_baggage_item(key, value) @only_if_tracing def set_operation_name(operation_name): - _opentracing.tracer.active_span.set_operation_name(operation_name) + opentracing.tracer.active_span.set_operation_name(operation_name) @only_if_tracing @@ -226,14 +220,13 @@ def start_active_span_from_context( returns: span_context (opentracing.span.SpanContext) """ - global _opentracing # Twisted encodes the values as lists whereas opentracing doesn't. # So, we take the first item in the list. # Also, twisted uses byte arrays while opentracing expects strings. header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} - context = _opentracing.tracer.extract(_opentracing.Format.HTTP_HEADERS, header_dict) + context = opentracing.tracer.extract(opentracing.Format.HTTP_HEADERS, header_dict) - _opentracing.tracer.start_active_span( + opentracing.tracer.start_active_span( operation_name, child_of=context, references=references, @@ -263,14 +256,13 @@ def inject_active_span_twisted_headers(headers, destination): here: https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ - global _opentracing if not whitelisted_homeserver(destination): return - span = _opentracing.tracer.active_span + span = opentracing.tracer.active_span carrier = {} - _opentracing.tracer.inject(span, _opentracing.Format.HTTP_HEADERS, carrier) + opentracing.tracer.inject(span, opentracing.Format.HTTP_HEADERS, carrier) for key, value in carrier.items(): headers.addRawHeaders(key, value) @@ -296,14 +288,13 @@ def inject_active_span_byte_dict(headers, destination): here: https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py """ - global _opentracing if not whitelisted_homeserver(destination): return - span = _opentracing.tracer.active_span + span = opentracing.tracer.active_span carrier = {} - _opentracing.tracer.inject(span, _opentracing.Format.HTTP_HEADERS, carrier) + opentracing.tracer.inject(span, opentracing.Format.HTTP_HEADERS, carrier) for key, value in carrier.items(): headers[key.encode()] = [value.encode()] From 14376e7760fe298a64077b186407d2d25f8af41a Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 3 Jul 2019 15:53:50 +0100 Subject: [PATCH 55/69] Return a contextmanager --- synapse/util/tracerutils.py | 51 +++++++++++++++++++++---------------- 1 file changed, 29 insertions(+), 22 deletions(-) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 119267afecf8..085d2be13f63 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -17,7 +17,14 @@ import opentracing except ImportError: opentracing = None +try: + from jaeger_client import Config as JaegerConfig + from synapse.util.scopecontextmanager import LogContextScopeManager +except ImportError: + JaegerConfig = None + LogContextScopeManager = None +import contextlib import logging import re from functools import wraps @@ -91,8 +98,7 @@ def init_tracer(config): if not opentracing: logger.error( - "The server has been configure to use opentracing but " - "the %s module has not been installed.", e.name + "The server has been configure to use opentracing but opentracing is not installed." ) raise ModuleNotFoundError("opentracing") @@ -101,15 +107,10 @@ def init_tracer(config): def setup_tracing(config): - try: - from jaeger_client import Config as JaegerConfig - from synapse.util.scopecontextmanager import LogContextScopeManager - except ImportError as e: + if not JaegerConfig: logger.error( - "The server has been configure to use opentracing but " - "the %s module has not been installed.", e.name + "The server has been configure to use opentracing but opentracing is not installed." ) - raise # Include the worker name name = config.worker_name if config.worker_name else "master" @@ -129,8 +130,12 @@ def setup_tags(): tags = opentracing.tags +@contextlib.contextmanager +def _noop_context_manager(*args, **kwargs): + yield + + # Could use kwargs but I want these to be explicit -@only_if_tracing def start_active_span( operation_name, child_of=None, @@ -140,16 +145,19 @@ def start_active_span( ignore_active_span=False, finish_on_close=True, ): - # We need to enter the scope here for the logcontext to become active - opentracing.tracer.start_active_span( - operation_name, - child_of=child_of, - references=references, - tags=tags, - start_time=start_time, - ignore_active_span=ignore_active_span, - finish_on_close=finish_on_close, - ).__enter__() + if opentracing is None: + return _noop_context_manager + else: + # We need to enter the scope here for the logcontext to become active + return opentracing.tracer.start_active_span( + operation_name, + child_of=child_of, + references=references, + tags=tags, + start_time=start_time, + ignore_active_span=ignore_active_span, + finish_on_close=finish_on_close, + ) @only_if_tracing @@ -203,7 +211,6 @@ def whitelisted_homeserver(destination): return False -@only_if_tracing def start_active_span_from_context( headers, operation_name, @@ -226,7 +233,7 @@ def start_active_span_from_context( header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} context = opentracing.tracer.extract(opentracing.Format.HTTP_HEADERS, header_dict) - opentracing.tracer.start_active_span( + return opentracing.tracer.start_active_span( operation_name, child_of=context, references=references, From 24b38347529b90d34219899bd4d9f742b061c3d8 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 09:32:53 +0100 Subject: [PATCH 56/69] Start tracing client requests from the servlet --- synapse/http/servlet.py | 5 ++++- synapse/util/tracerutils.py | 23 +++++++++++++++++++++++ 2 files changed, 27 insertions(+), 1 deletion(-) diff --git a/synapse/http/servlet.py b/synapse/http/servlet.py index cd8415acd5ab..f4f5f146a3e1 100644 --- a/synapse/http/servlet.py +++ b/synapse/http/servlet.py @@ -20,6 +20,7 @@ from canonicaljson import json from synapse.api.errors import Codes, SynapseError +from synapse.util.tracerutils import trace_servlet logger = logging.getLogger(__name__) @@ -290,7 +291,9 @@ def register(self, http_server): for method in ("GET", "PUT", "POST", "OPTIONS", "DELETE"): if hasattr(self, "on_%s" % (method,)): method_handler = getattr(self, "on_%s" % (method,)) - http_server.register_paths(method, patterns, method_handler) + http_server.register_paths( + method, patterns, trace_servlet(method_handler) + ) else: raise NotImplementedError("RestServlet must register something.") diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 085d2be13f63..075e932c91e1 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -29,6 +29,8 @@ import re from functools import wraps +from twisted.internet import defer + logger = logging.getLogger(__name__) @@ -305,3 +307,24 @@ def inject_active_span_byte_dict(headers, destination): for key, value in carrier.items(): headers[key.encode()] = [value.encode()] + + +def trace_servlet(func): + @wraps(func) + @defer.inlineCallbacks + def f(request, *args, **kwargs): + with start_active_span_from_context( + request.requestHeaders, + "incoming-client-request", + tags={ + "request_id": request.get_request_id(), + tags.SPAN_KIND: tags.SPAN_KIND_RPC_SERVER, + tags.HTTP_METHOD: request.get_method(), + tags.HTTP_URL: request.get_redacted_uri(), + tags.PEER_HOST_IPV6: request.getClientIP(), + }, + ): + result = yield defer.maybeDeferred(func, request, *args, **kwargs) + defer.returnValue(result) + + return f From 386285b21959c971ca9094256a594b364a7f17c2 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 10:18:53 +0100 Subject: [PATCH 57/69] Return noop context manager if not tracing --- synapse/util/tracerutils.py | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-) diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 075e932c91e1..85d4712c4d93 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -94,8 +94,10 @@ def init_tracer(config): The config used by the homserver. Here it's used to set the service name to the homeserver's. """ + global opentracing if not config.tracer_config.get("tracer_enabled", False): # We don't have a tracer + opentracing = None return if not opentracing: @@ -148,7 +150,7 @@ def start_active_span( finish_on_close=True, ): if opentracing is None: - return _noop_context_manager + return _noop_context_manager() else: # We need to enter the scope here for the logcontext to become active return opentracing.tracer.start_active_span( @@ -232,6 +234,9 @@ def start_active_span_from_context( # Twisted encodes the values as lists whereas opentracing doesn't. # So, we take the first item in the list. # Also, twisted uses byte arrays while opentracing expects strings. + if opentracing is None: + return _noop_context_manager() + header_dict = {k.decode(): v[0].decode() for k, v in headers.getAllRawHeaders()} context = opentracing.tracer.extract(opentracing.Format.HTTP_HEADERS, header_dict) @@ -313,7 +318,7 @@ def trace_servlet(func): @wraps(func) @defer.inlineCallbacks def f(request, *args, **kwargs): - with start_active_span_from_context( + scope = start_active_span_from_context( request.requestHeaders, "incoming-client-request", tags={ @@ -323,8 +328,16 @@ def f(request, *args, **kwargs): tags.HTTP_URL: request.get_redacted_uri(), tags.PEER_HOST_IPV6: request.getClientIP(), }, - ): + ) + # A context manager would be the most logical here but defer.returnValue + # raises an exception in order to provide the return value. This causes + # opentracing to mark each request as erroring, in order to avoid this we + # need to give the finally clause explicitly. + scope.__enter__() + try: result = yield defer.maybeDeferred(func, request, *args, **kwargs) defer.returnValue(result) + finally: + scope.__exit__(None, None, None) return f From 3dde444dd3a0f6e37468a79e83fed27313959857 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 14:25:33 +0100 Subject: [PATCH 58/69] Explicitely say that these are federation requests --- synapse/federation/transport/server.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index e4d021effb35..5480fd5f7c42 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -292,7 +292,7 @@ def new_func(request, *args, **kwargs): # Start an opentracing span tracerutils.start_active_span_from_context( request.requestHeaders, - "incoming-request", + "incoming-federation-request", tags={ "request_id": request.get_request_id(), tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_SERVER, From b5cd7dfe9dfd80bb37d899cb17ca4e0114ab0366 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 14:40:47 +0100 Subject: [PATCH 59/69] Include servlet name in client requests --- synapse/http/servlet.py | 4 +++- synapse/util/tracerutils.py | 3 ++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/synapse/http/servlet.py b/synapse/http/servlet.py index f4f5f146a3e1..6da94e25df3c 100644 --- a/synapse/http/servlet.py +++ b/synapse/http/servlet.py @@ -292,7 +292,9 @@ def register(self, http_server): if hasattr(self, "on_%s" % (method,)): method_handler = getattr(self, "on_%s" % (method,)) http_server.register_paths( - method, patterns, trace_servlet(method_handler) + method, + patterns, + trace_servlet(self.__class__.__name__, method_handler), ) else: diff --git a/synapse/util/tracerutils.py b/synapse/util/tracerutils.py index 85d4712c4d93..2e6ed581ed3c 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/util/tracerutils.py @@ -314,7 +314,7 @@ def inject_active_span_byte_dict(headers, destination): headers[key.encode()] = [value.encode()] -def trace_servlet(func): +def trace_servlet(servlet_name, func): @wraps(func) @defer.inlineCallbacks def f(request, *args, **kwargs): @@ -327,6 +327,7 @@ def f(request, *args, **kwargs): tags.HTTP_METHOD: request.get_method(), tags.HTTP_URL: request.get_redacted_uri(), tags.PEER_HOST_IPV6: request.getClientIP(), + "servlet_name": servlet_name, }, ) # A context manager would be the most logical here but defer.returnValue From f93b60dd41beecc6ef85e144f98fb032c2b0f901 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 15:05:03 +0100 Subject: [PATCH 60/69] Use context manager --- synapse/federation/transport/server.py | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index 5480fd5f7c42..aac997c049b0 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -290,7 +290,7 @@ def new_func(request, *args, **kwargs): raise # Start an opentracing span - tracerutils.start_active_span_from_context( + with tracerutils.start_active_span_from_context( request.requestHeaders, "incoming-federation-request", tags={ @@ -301,9 +301,7 @@ def new_func(request, *args, **kwargs): tracerutils.tags.PEER_HOST_IPV6: request.getClientIP(), "authenticated_entity": origin, }, - ) - - try: + ): if origin: with ratelimiter.ratelimit(origin) as d: yield d @@ -314,9 +312,6 @@ def new_func(request, *args, **kwargs): response = yield func( origin, content, request.args, *args, **kwargs ) - finally: - # Finish the span - tracerutils.close_active_span() defer.returnValue(response) From 6ab84bbb75cb232e2c9ff1c05183a291bf890522 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 16:38:56 +0100 Subject: [PATCH 61/69] Move opentracing to logging/ --- synapse/app/_base.py | 2 +- synapse/federation/transport/server.py | 12 +++++------ synapse/http/matrixfederationclient.py | 20 +++++++++---------- synapse/http/servlet.py | 2 +- .../tracerutils.py => logging/opentracing.py} | 2 +- .../{util => logging}/scopecontextmanager.py | 2 +- 6 files changed, 20 insertions(+), 20 deletions(-) rename synapse/{util/tracerutils.py => logging/opentracing.py} (99%) rename synapse/{util => logging}/scopecontextmanager.py (98%) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 425f2e8bb1fa..bd285122eab9 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -244,7 +244,7 @@ def handle_sighup(*args, **kwargs): refresh_certificate(hs) # Start the tracer - synapse.util.tracerutils.init_tracer(hs.config) + synapse.logging.opentracing.init_tracer(hs.config) # It is now safe to start your Synapse. hs.start_listening(listeners) diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py index c549521a89b2..c45d458d946d 100644 --- a/synapse/federation/transport/server.py +++ b/synapse/federation/transport/server.py @@ -21,7 +21,7 @@ from twisted.internet import defer import synapse -import synapse.util.tracerutils as tracerutils +import synapse.logging.opentracing as opentracing from synapse.api.errors import Codes, FederationDeniedError, SynapseError from synapse.api.room_versions import RoomVersions from synapse.api.urls import ( @@ -290,15 +290,15 @@ def new_func(request, *args, **kwargs): raise # Start an opentracing span - with tracerutils.start_active_span_from_context( + with opentracing.start_active_span_from_context( request.requestHeaders, "incoming-federation-request", tags={ "request_id": request.get_request_id(), - tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_SERVER, - tracerutils.tags.HTTP_METHOD: request.get_method(), - tracerutils.tags.HTTP_URL: request.get_redacted_uri(), - tracerutils.tags.PEER_HOST_IPV6: request.getClientIP(), + opentracing.tags.SPAN_KIND: opentracing.tags.SPAN_KIND_RPC_SERVER, + opentracing.tags.HTTP_METHOD: request.get_method(), + opentracing.tags.HTTP_URL: request.get_redacted_uri(), + opentracing.tags.PEER_HOST_IPV6: request.getClientIP(), "authenticated_entity": origin, }, ): diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 54fdc05401d8..81e33f3c6f4d 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -38,7 +38,7 @@ import synapse.metrics import synapse.util.retryutils -import synapse.util.tracerutils as tracerutils +import synapse.logging.opentracing as opentracing from synapse.api.errors import ( Codes, FederationDeniedError, @@ -341,20 +341,20 @@ def _send_request( query_bytes = b"" # Retreive current span - tracerutils.start_active_span( + opentracing.start_active_span( "outgoing-federation-request", tags={ - tracerutils.tags.SPAN_KIND: tracerutils.tags.SPAN_KIND_RPC_CLIENT, - tracerutils.tags.PEER_ADDRESS: request.destination, - tracerutils.tags.HTTP_METHOD: request.method, - tracerutils.tags.HTTP_URL: request.path, + opentracing.tags.SPAN_KIND: opentracing.tags.SPAN_KIND_RPC_CLIENT, + opentracing.tags.PEER_ADDRESS: request.destination, + opentracing.tags.HTTP_METHOD: request.method, + opentracing.tags.HTTP_URL: request.path, }, finish_on_close=True, ) # Inject the span into the headers headers_dict = {} - tracerutils.inject_active_span_byte_dict(headers_dict, request.destination) + opentracing.inject_active_span_byte_dict(headers_dict, request.destination) headers_dict[b"User-Agent"] = [self.version_string_bytes] @@ -436,8 +436,8 @@ def _send_request( response.phrase.decode("ascii", errors="replace"), ) - tracerutils.set_tag( - tracerutils.tags.HTTP_STATUS_CODE, response.code + opentracing.set_tag( + opentracing.tags.HTTP_STATUS_CODE, response.code ) if 200 <= response.code < 300: @@ -520,7 +520,7 @@ def _send_request( _flatten_response_never_received(e), ) raise - tracerutils.close_active_span() + opentracing.close_active_span() defer.returnValue(response) def build_auth_headers( diff --git a/synapse/http/servlet.py b/synapse/http/servlet.py index 6da94e25df3c..889038ff2585 100644 --- a/synapse/http/servlet.py +++ b/synapse/http/servlet.py @@ -20,7 +20,7 @@ from canonicaljson import json from synapse.api.errors import Codes, SynapseError -from synapse.util.tracerutils import trace_servlet +from synapse.logging.opentracing import trace_servlet logger = logging.getLogger(__name__) diff --git a/synapse/util/tracerutils.py b/synapse/logging/opentracing.py similarity index 99% rename from synapse/util/tracerutils.py rename to synapse/logging/opentracing.py index 2e6ed581ed3c..630cea52916d 100644 --- a/synapse/util/tracerutils.py +++ b/synapse/logging/opentracing.py @@ -19,7 +19,7 @@ opentracing = None try: from jaeger_client import Config as JaegerConfig - from synapse.util.scopecontextmanager import LogContextScopeManager + from synapse.logging.scopecontextmanager import LogContextScopeManager except ImportError: JaegerConfig = None LogContextScopeManager = None diff --git a/synapse/util/scopecontextmanager.py b/synapse/logging/scopecontextmanager.py similarity index 98% rename from synapse/util/scopecontextmanager.py rename to synapse/logging/scopecontextmanager.py index e041f786c3bf..29f96c790608 100644 --- a/synapse/util/scopecontextmanager.py +++ b/synapse/logging/scopecontextmanager.py @@ -17,7 +17,7 @@ from opentracing import Scope, ScopeManager -from .logcontext import LoggingContext, nested_logging_context +from synapse.logging.context import LoggingContext, nested_logging_context logger = logging.getLogger(__name__) From 9a3c98a5efde716743d2b01469fd159d02d8beee Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 4 Jul 2019 16:42:53 +0100 Subject: [PATCH 62/69] Seen it, isort it again! --- synapse/http/matrixfederationclient.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 81e33f3c6f4d..5a594f9f6dec 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -36,9 +36,9 @@ from twisted.web._newclient import ResponseDone from twisted.web.http_headers import Headers +import synapse.logging.opentracing as opentracing import synapse.metrics import synapse.util.retryutils -import synapse.logging.opentracing as opentracing from synapse.api.errors import ( Codes, FederationDeniedError, From 0c19608247438ace2e8b12aed0aea267986f99c0 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 5 Jul 2019 14:20:33 +0100 Subject: [PATCH 63/69] Ignore twisted return exceptions on context exit --- synapse/logging/opentracing.py | 12 ++---------- synapse/logging/scopecontextmanager.py | 7 ++++++- 2 files changed, 8 insertions(+), 11 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 630cea52916d..8ec56d637ab2 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -318,7 +318,7 @@ def trace_servlet(servlet_name, func): @wraps(func) @defer.inlineCallbacks def f(request, *args, **kwargs): - scope = start_active_span_from_context( + with start_active_span_from_context( request.requestHeaders, "incoming-client-request", tags={ @@ -329,16 +329,8 @@ def f(request, *args, **kwargs): tags.PEER_HOST_IPV6: request.getClientIP(), "servlet_name": servlet_name, }, - ) - # A context manager would be the most logical here but defer.returnValue - # raises an exception in order to provide the return value. This causes - # opentracing to mark each request as erroring, in order to avoid this we - # need to give the finally clause explicitly. - scope.__enter__() - try: + ): result = yield defer.maybeDeferred(func, request, *args, **kwargs) defer.returnValue(result) - finally: - scope.__exit__(None, None, None) return f diff --git a/synapse/logging/scopecontextmanager.py b/synapse/logging/scopecontextmanager.py index 29f96c790608..91e14462f308 100644 --- a/synapse/logging/scopecontextmanager.py +++ b/synapse/logging/scopecontextmanager.py @@ -17,6 +17,8 @@ from opentracing import Scope, ScopeManager +import twisted + from synapse.logging.context import LoggingContext, nested_logging_context logger = logging.getLogger(__name__) @@ -120,7 +122,10 @@ def __enter__(self): self.logcontext.__enter__() def __exit__(self, type, value, traceback): - super(_LogContextScope, self).__exit__(type, value, traceback) + if type == twisted.internet.defer._DefGen_Return: + super(_LogContextScope, self).__exit__(None, None, None) + else: + super(_LogContextScope, self).__exit__(type, value, traceback) if self._enter_logcontext: self.logcontext.__exit__(type, value, traceback) else: # the logcontext existed before the creation of the scope From 18a902fe0eec03522322a66abd0a80a0a68ba4ac Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 10 Jul 2019 15:29:56 +0100 Subject: [PATCH 64/69] Escape the scope --- synapse/logging/opentracing.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 8ec56d637ab2..3d2b2d1c70aa 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -331,6 +331,6 @@ def f(request, *args, **kwargs): }, ): result = yield defer.maybeDeferred(func, request, *args, **kwargs) - defer.returnValue(result) + defer.returnValue(result) return f From 49038b136b4be831a252c60ce66eeaa9c88e53e3 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 10 Jul 2019 15:32:22 +0100 Subject: [PATCH 65/69] Scopes should be entered to make them useful. --- synapse/http/matrixfederationclient.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 5a594f9f6dec..bf728edc5f13 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -341,7 +341,7 @@ def _send_request( query_bytes = b"" # Retreive current span - opentracing.start_active_span( + scope = opentracing.start_active_span( "outgoing-federation-request", tags={ opentracing.tags.SPAN_KIND: opentracing.tags.SPAN_KIND_RPC_CLIENT, @@ -358,7 +358,7 @@ def _send_request( headers_dict[b"User-Agent"] = [self.version_string_bytes] - with limiter: + with limiter, scope: # XXX: Would be much nicer to retry only at the transaction-layer # (once we have reliable transactions in place) if long_retries: From 00e08bddb772526018043c6dd640ebebbac300f1 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 10 Jul 2019 15:35:20 +0100 Subject: [PATCH 66/69] Nicer decorator names --- synapse/logging/opentracing.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 3d2b2d1c70aa..6e9a80c39910 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -71,13 +71,13 @@ def only_if_tracing(func): Assumes the function wrapped may return None""" @wraps(func) - def f(*args, **kwargs): + def _only_if_tracing_inner(*args, **kwargs): if opentracing: return func(*args, **kwargs) else: return - return f + return _only_if_tracing_inner # Block everything by default @@ -317,7 +317,7 @@ def inject_active_span_byte_dict(headers, destination): def trace_servlet(servlet_name, func): @wraps(func) @defer.inlineCallbacks - def f(request, *args, **kwargs): + def _trace_servlet_inner(request, *args, **kwargs): with start_active_span_from_context( request.requestHeaders, "incoming-client-request", @@ -333,4 +333,4 @@ def f(request, *args, **kwargs): result = yield defer.maybeDeferred(func, request, *args, **kwargs) defer.returnValue(result) - return f + return _trace_servlet_inner From 06baa498b1d3cb8bd950717d46bfd711f578da89 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 10 Jul 2019 15:40:29 +0100 Subject: [PATCH 67/69] Just one init, init? --- synapse/logging/opentracing.py | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 6e9a80c39910..216b6b1dfd39 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -91,7 +91,7 @@ def init_tracer(config): Args: config (Config) - The config used by the homserver. Here it's used to set the service + The config used by the homeserver. Here it's used to set the service name to the homeserver's. """ global opentracing @@ -106,11 +106,6 @@ def init_tracer(config): ) raise ModuleNotFoundError("opentracing") - setup_tags() - setup_tracing(config) - - -def setup_tracing(config): if not JaegerConfig: logger.error( "The server has been configure to use opentracing but opentracing is not installed." @@ -127,9 +122,7 @@ def setup_tracing(config): ) jaeger_config.initialize_tracer() - -@only_if_tracing -def setup_tags(): + # Set up tags to be opentracing's tags global tags tags = opentracing.tags From b07a4c6d92aee727553e23f9939606cc9fc043c7 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 10 Jul 2019 15:41:34 +0100 Subject: [PATCH 68/69] Don't need to close something that isn't open --- synapse/http/matrixfederationclient.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index bf728edc5f13..e60334547e96 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -520,7 +520,6 @@ def _send_request( _flatten_response_never_received(e), ) raise - opentracing.close_active_span() defer.returnValue(response) def build_auth_headers( From 6f3109eca73ec98e6fccf6c4d8f2644f5213e03a Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 10 Jul 2019 16:00:01 +0100 Subject: [PATCH 69/69] Docs make you smarter --- synapse/logging/opentracing.py | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 216b6b1dfd39..f0ceea2a642a 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -13,6 +13,17 @@ # See the License for the specific language governing permissions and # limitations under the License.import opentracing + +# NOTE +# This is a small wrapper around opentracing because opentracing is not currently +# packaged downstream (specifically debian). Since opentracing instrumentation is +# fairly invasive it was awkward to make it optional. As a result we opted to encapsulate +# all opentracing state in these methods which effectively noop if opentracing is +# not present. We should strongly consider encouraging the downstream distributers +# to package opentracing and making opentracing a full dependency. In order to facilitate +# this move the methods have work very similarly to opentracing's and it should only +# be a matter of few regexes to move over to opentracing's access patterns proper. + try: import opentracing except ImportError: @@ -129,6 +140,8 @@ def init_tracer(config): @contextlib.contextmanager def _noop_context_manager(*args, **kwargs): + """Does absolutely nothing really well. Can be entered and exited arbitrarily. + Good substitute for an opentracing scope.""" yield @@ -142,6 +155,14 @@ def start_active_span( ignore_active_span=False, finish_on_close=True, ): + """Starts an active opentracing span. Note, the scope doesn't become active + until it has been entered, however, the span starts from the time this + message is called. + Args: + See opentracing.tracer + Returns: + scope (Scope) or noop_context_manager + """ if opentracing is None: return _noop_context_manager() else: @@ -159,16 +180,20 @@ def start_active_span( @only_if_tracing def close_active_span(): + """Closes the active span. This will close it's logcontext if the context + was made for the span""" opentracing.tracer.scope_manager.active.__exit__(None, None, None) @only_if_tracing def set_tag(key, value): + """Set's a tag on the active span""" opentracing.tracer.active_span.set_tag(key, value) @only_if_tracing def log_kv(key_values, timestamp=None): + """Log to the active span""" opentracing.tracer.active_span.log_kv(key_values, timestamp) @@ -177,11 +202,13 @@ def log_kv(key_values, timestamp=None): # as a result @only_if_tracing def set_baggage_item(key, value): + """Attach baggage to the active span""" opentracing.tracer.active_span.set_baggage_item(key, value) @only_if_tracing def set_operation_name(operation_name): + """Sets the operation name of the active span""" opentracing.tracer.active_span.set_operation_name(operation_name) @@ -202,6 +229,9 @@ def set_homeserver_whitelist(homeserver_whitelist): @only_if_tracing def whitelisted_homeserver(destination): + """Checks if a destination matches the whitelist + Args: + destination (String)""" global _homeserver_whitelist if _homeserver_whitelist: return _homeserver_whitelist.match(destination) @@ -308,6 +338,9 @@ def inject_active_span_byte_dict(headers, destination): def trace_servlet(servlet_name, func): + """Decorator which traces a serlet. It starts a span with some servlet specific + tags such as the servlet_name and request information""" + @wraps(func) @defer.inlineCallbacks def _trace_servlet_inner(request, *args, **kwargs):