From d444c44d52d571effb5c1d92b31c5eab2b3efa2a Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 28 Jun 2019 10:30:56 +0100 Subject: [PATCH 01/28] Add decerators for tracing functions --- synapse/logging/opentracing.py | 60 ++++++++++++++++++++++++++++++++++ 1 file changed, 60 insertions(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 415040f5ee00..428e6410ea22 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -28,6 +28,8 @@ import logging import re from functools import wraps +from twisted.internet import defer + from twisted.internet import defer @@ -356,3 +358,61 @@ def _trace_servlet_inner(request, *args, **kwargs): defer.returnValue(result) return _trace_servlet_inner + + +def trace_defered_function(func): + @wraps(func) + @defer.inlineCallbacks + def f(self, *args, **kwargs): + # Start scope + TracerUtil.start_active_span(func.__name__) + try: + r = yield func(self, *args, **kwargs) + except: + raise + finally: + TracerUtil.close_active_span() + defer.returnValue(r) + + return f + + +def trace_defered_function_using_operation_name(name): + def trace_defered_function(func): + @wraps(func) + @defer.inlineCallbacks + def f(self, *args, **kwargs): + # Start scope + TracerUtil.start_active_span(name) + try: + r = yield func(self, *args, **kwargs) + except: + raise + finally: + TracerUtil.close_active_span() + defer.returnValue(r) + + return f + + return trace_defered_function + + +def trace_function(func): + @wraps(func) + def f(self, *args, **kwargs): + TracerUtil.start_active_span(func.__name__) + result = func(self, *args, **kwargs) + TracerUtil.close_active_span() + return result + + return f + + +def tag_args(func): + @wraps(func) + def f(self, *args, **kwargs): + TracerUtil.set_tag("args", args) + TracerUtil.set_tag("kwargs", kwargs) + return func(self, *args, **kwargs) + + return f From 3df45c905adde6771247f3a847d004e54d485714 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 28 Jun 2019 15:55:10 +0100 Subject: [PATCH 02/28] Try catch wrapping to make sure the span is finished --- synapse/logging/opentracing.py | 37 +++++++++++++++++++++++++++++++--- 1 file changed, 34 insertions(+), 3 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 428e6410ea22..0860ec8d2229 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -48,6 +48,7 @@ logger = logging.getLogger(__name__) +import inspect class _DumTagNames(object): @@ -401,9 +402,10 @@ def trace_function(func): @wraps(func) def f(self, *args, **kwargs): TracerUtil.start_active_span(func.__name__) - result = func(self, *args, **kwargs) - TracerUtil.close_active_span() - return result + try: + return func(self, *args, **kwargs) + finally: + TracerUtil.close_active_span() return f @@ -416,3 +418,32 @@ def f(self, *args, **kwargs): return func(self, *args, **kwargs) return f + + +def wrap_in_span(func): + """Its purpose is to wrap a function that is being passed into a context + which is a complete break from the current logcontext. This function creates + a non active span from the current context and closes it after the function + executes.""" + + # I haven't use this function yet + + if not TracerUtil._opentracing: + return func + + span = TracerUtil._opentracing.tracer.start_span( + func.__name__, child_of=TracerUtil._opentracing.tracer.active_span + ) + + @wraps(func) + def f(self, *args, **kwargs): + try: + return func(self, *args, **kwargs) + except Exception as e: + span.set_tag("error", True) + span.log_kv({"exception", e}) + raise + finally: + span.finish() + + return f From 6ffaabde11be2b01bbc4355d4b746437c0f6577b Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 5 Jul 2019 14:27:43 +0100 Subject: [PATCH 03/28] Use the new clean contexts --- synapse/logging/opentracing.py | 24 ++++++------------------ 1 file changed, 6 insertions(+), 18 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 0860ec8d2229..9d0f06f83886 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -365,15 +365,9 @@ def trace_defered_function(func): @wraps(func) @defer.inlineCallbacks def f(self, *args, **kwargs): - # Start scope - TracerUtil.start_active_span(func.__name__) - try: + with start_active_span(func.__name__): r = yield func(self, *args, **kwargs) - except: - raise - finally: - TracerUtil.close_active_span() - defer.returnValue(r) + defer.returnValue(r) return f @@ -384,14 +378,9 @@ def trace_defered_function(func): @defer.inlineCallbacks def f(self, *args, **kwargs): # Start scope - TracerUtil.start_active_span(name) - try: + with start_active_span(name): r = yield func(self, *args, **kwargs) - except: - raise - finally: - TracerUtil.close_active_span() - defer.returnValue(r) + defer.returnValue(r) return f @@ -431,12 +420,11 @@ def wrap_in_span(func): if not TracerUtil._opentracing: return func - span = TracerUtil._opentracing.tracer.start_span( - func.__name__, child_of=TracerUtil._opentracing.tracer.active_span - ) + parent_span = opentracing.tracer.active_span @wraps(func) def f(self, *args, **kwargs): + span = opentracing.tracer.start_span(func.__name__, child_of=parent_span) try: return func(self, *args, **kwargs) except Exception as e: From 7b5c3d54bded0a8639c4fa83c13b9360815f6f79 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 13:50:06 +0100 Subject: [PATCH 04/28] Context and edu utils --- synapse/logging/opentracing.py | 93 +++++++++++++++++++++++++++++++++- 1 file changed, 92 insertions(+), 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 9d0f06f83886..a766510afdcc 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -11,7 +11,7 @@ # 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 +# limitations under the License. # NOTE @@ -30,6 +30,7 @@ from functools import wraps from twisted.internet import defer +from canonicaljson import json from twisted.internet import defer @@ -178,6 +179,15 @@ def start_active_span( ) +def start_active_span_follows_from(operation_name, contexts): + if opentracing is None: + return _noop_context_manager() + else: + references = [opentracing.follows_from(context) for context in contexts] + scope = start_active_span(operation_name, references=references) + return scope + + @only_if_tracing def close_active_span(): """Closes the active span. This will close it's logcontext if the context @@ -273,6 +283,50 @@ def start_active_span_from_context( ) +@only_if_tracing +def start_active_span_from_edu( + edu_content, + operation_name, + references=[], + tags=None, + start_time=None, + ignore_active_span=False, + finish_on_close=True, +): + """ + Extracts a span context from an edu and uses it to start a new active span + + Args: + edu_content (Dict): and edu_content with a `context` field whose value is + canonical json for a dict which contains opentracing information. + """ + carrier = json.loads(edu_content.get("context", "{}")).get("opentracing", {}) + context = opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) + _references = [ + opentracing.child_of(span_context_from_string(x)) + for x in carrier.get("references", []) + ] + + # For some reason jaeger decided not to support the visualisation of multiple parent + # spans or explicitely show references. I include the span context as a tag here as + # an aid to people debugging but it's really not an ideal solution. + + references += _references + + scope = 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, + ) + + scope.span.set_tag("references", carrier.get("references", [])) + return scope + + @only_if_tracing def inject_active_span_twisted_headers(headers, destination): """ @@ -336,6 +390,43 @@ def inject_active_span_byte_dict(headers, destination): headers[key.encode()] = [value.encode()] +@only_if_tracing +def inject_active_span_text_map(carrier, destination=None): + if destination and not whitelisted_homeserver(destination): + return + + opentracing.tracer.inject( + opentracing.tracer.active_span, opentracing.Format.TEXT_MAP, carrier + ) + + +def active_span_context_as_string(): + if not opentracing: + return None + + carrier = {} + opentracing.tracer.inject( + opentracing.tracer.active_span, opentracing.Format.TEXT_MAP, carrier + ) + return json.dumps(carrier) + + +@only_if_tracing +def span_context_from_string(carrier): + carrier = json.loads(carrier) + return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) + + +@only_if_tracing +def extract_text_map(carrier): + return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) + + +def trace_defered_function(func): + """Decorator to trace a defered function. Sets the operation name to that of the + function's.""" + + 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""" From ff838f84aca00a6194f0c8cb77fd2b3eef9bad29 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 8 Jul 2019 14:00:49 +0100 Subject: [PATCH 05/28] Typo --- synapse/logging/scopecontextmanager.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/logging/scopecontextmanager.py b/synapse/logging/scopecontextmanager.py index 8c661302c9f0..4eed4f233822 100644 --- a/synapse/logging/scopecontextmanager.py +++ b/synapse/logging/scopecontextmanager.py @@ -131,7 +131,7 @@ def __exit__(self, type, value, traceback): def close(self): if self.manager.active is not self: - logger.error("Tried to close a none active scope!") + logger.error("Tried to close a non-active scope!") return if self._finish_on_close: From e1f3951467cf47deeffa0ef107fa8c3aaca14221 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 17:01:35 +0100 Subject: [PATCH 06/28] Remove unused function. --- synapse/logging/opentracing.py | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index a766510afdcc..aa724d16b610 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -188,13 +188,6 @@ def start_active_span_follows_from(operation_name, contexts): return scope -@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""" @@ -210,6 +203,11 @@ def log_kv(key_values, timestamp=None): # 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 + +# I also thinks it's dangerous with respect to pii. If the whitelisting +# is missconfigured or buggy span information will leak. This is no issue +# if it's jaeger span id's but baggage can contain any arbitrary data. I would +# suggest removing this. @only_if_tracing def set_baggage_item(key, value): """Attach baggage to the active span""" From 518df6c57edea09207acdfd83599e89e778b7bf8 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 17:48:12 +0100 Subject: [PATCH 07/28] Better inner function names --- synapse/logging/opentracing.py | 43 +++++++++++++++++++++------------- 1 file changed, 27 insertions(+), 16 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index aa724d16b610..ed518bae5ac4 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -453,49 +453,60 @@ def _trace_servlet_inner(request, *args, **kwargs): def trace_defered_function(func): @wraps(func) @defer.inlineCallbacks - def f(self, *args, **kwargs): + def _trace_defered_function_inner(self, *args, **kwargs): with start_active_span(func.__name__): r = yield func(self, *args, **kwargs) defer.returnValue(r) - return f + return _trace_defered_function_inner def trace_defered_function_using_operation_name(name): def trace_defered_function(func): @wraps(func) @defer.inlineCallbacks - def f(self, *args, **kwargs): + def _trace_defered_function_inner(self, *args, **kwargs): # Start scope with start_active_span(name): r = yield func(self, *args, **kwargs) defer.returnValue(r) - return f + return _trace_defered_function_inner return trace_defered_function def trace_function(func): @wraps(func) - def f(self, *args, **kwargs): - TracerUtil.start_active_span(func.__name__) - try: + def _trace_function_inner(self, *args, **kwargs): + with start_active_span(func.__name__): return func(self, *args, **kwargs) - finally: - TracerUtil.close_active_span() - return f + return _trace_function_inner + + +def trace_function_using_operation_name(operation_name): + """Decorator to trace a function. Explicitely sets the operation_name to name""" + + def trace_function(func): + @wraps(func) + def _trace_function_inner(self, *args, **kwargs): + with start_active_span(operation_name): + return func(self, *args, **kwargs) + + return _trace_function_inner + + return trace_function def tag_args(func): @wraps(func) - def f(self, *args, **kwargs): - TracerUtil.set_tag("args", args) - TracerUtil.set_tag("kwargs", kwargs) + def _tag_args_inner(self, *args, **kwargs): + set_tag("args", args) + set_tag("kwargs", kwargs) return func(self, *args, **kwargs) - return f + return _tag_args_inner def wrap_in_span(func): @@ -512,7 +523,7 @@ def wrap_in_span(func): parent_span = opentracing.tracer.active_span @wraps(func) - def f(self, *args, **kwargs): + def _wrap_in_span_inner(self, *args, **kwargs): span = opentracing.tracer.start_span(func.__name__, child_of=parent_span) try: return func(self, *args, **kwargs) @@ -523,4 +534,4 @@ def f(self, *args, **kwargs): finally: span.finish() - return f + return _wrap_in_span_inner From 5d300d70aac5f44d79ca81998516760c2ff38278 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 19 Jul 2019 13:46:35 +0100 Subject: [PATCH 08/28] Better decorator names --- synapse/logging/opentracing.py | 37 +++++++++++++++++++--------------- 1 file changed, 21 insertions(+), 16 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index ed518bae5ac4..b0b2b84a5d7e 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -420,7 +420,7 @@ def extract_text_map(carrier): return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) -def trace_defered_function(func): +def trace_deferred(func): """Decorator to trace a defered function. Sets the operation name to that of the function's.""" @@ -453,50 +453,55 @@ def _trace_servlet_inner(request, *args, **kwargs): def trace_defered_function(func): @wraps(func) @defer.inlineCallbacks - def _trace_defered_function_inner(self, *args, **kwargs): + def _trace_deferred_inner(self, *args, **kwargs): with start_active_span(func.__name__): r = yield func(self, *args, **kwargs) defer.returnValue(r) - return _trace_defered_function_inner + return _trace_deferred_inner + +def trace_deferred_using_operation_name(name): + """Decorator to trace a defered function. Explicitely sets the operation_name to name""" -def trace_defered_function_using_operation_name(name): - def trace_defered_function(func): + def trace_deferred(func): @wraps(func) @defer.inlineCallbacks - def _trace_defered_function_inner(self, *args, **kwargs): + def _trace_deferred_inner(self, *args, **kwargs): # Start scope with start_active_span(name): r = yield func(self, *args, **kwargs) defer.returnValue(r) - return _trace_defered_function_inner + return _trace_deferred_inner - return trace_defered_function + return trace_deferred -def trace_function(func): +def trace(func): + """Decorator to trace a normal function. Sets the operation name to that of the + function's.""" + @wraps(func) - def _trace_function_inner(self, *args, **kwargs): + def _trace_inner(self, *args, **kwargs): with start_active_span(func.__name__): return func(self, *args, **kwargs) - return _trace_function_inner + return _trace_inner -def trace_function_using_operation_name(operation_name): +def trace_using_operation_name(operation_name): """Decorator to trace a function. Explicitely sets the operation_name to name""" - def trace_function(func): + def trace(func): @wraps(func) - def _trace_function_inner(self, *args, **kwargs): + def _trace_inner(self, *args, **kwargs): with start_active_span(operation_name): return func(self, *args, **kwargs) - return _trace_function_inner + return _trace_inner - return trace_function + return trace def tag_args(func): From f3e2bc1e22946946df54c38881bf6d5a4ddd36c1 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 18:01:14 +0100 Subject: [PATCH 09/28] Typos and errata --- synapse/logging/opentracing.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index b0b2b84a5d7e..658f7f40edac 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -52,7 +52,7 @@ import inspect -class _DumTagNames(object): +class _DummyTagNames(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 @@ -102,7 +102,7 @@ def _only_if_tracing_inner(*args, **kwargs): # None means 'block everything'. _homeserver_whitelist = None -tags = _DumTagNames +tags = _DummyTagNames def init_tracer(config): @@ -305,7 +305,7 @@ def start_active_span_from_edu( for x in carrier.get("references", []) ] - # For some reason jaeger decided not to support the visualisation of multiple parent + # For some reason jaeger decided not to support the visualization of multiple parent # spans or explicitely show references. I include the span context as a tag here as # an aid to people debugging but it's really not an ideal solution. @@ -421,7 +421,7 @@ def extract_text_map(carrier): def trace_deferred(func): - """Decorator to trace a defered function. Sets the operation name to that of the + """Decorator to trace a deferred function. Sets the operation name to that of the function's.""" @@ -462,7 +462,7 @@ def _trace_deferred_inner(self, *args, **kwargs): def trace_deferred_using_operation_name(name): - """Decorator to trace a defered function. Explicitely sets the operation_name to name""" + """Decorator to trace a deferred function. Explicitely sets the operation_name.""" def trace_deferred(func): @wraps(func) @@ -491,7 +491,7 @@ def _trace_inner(self, *args, **kwargs): def trace_using_operation_name(operation_name): - """Decorator to trace a function. Explicitely sets the operation_name to name""" + """Decorator to trace a function. Explicitely sets the operation_name.""" def trace(func): @wraps(func) From e82f65db98e05cba8705da55dfecb129d3c6fb69 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 18:13:28 +0100 Subject: [PATCH 10/28] Move dummy tags --- synapse/logging/opentracing.py | 95 ++++++++++++++++++++++------------ 1 file changed, 61 insertions(+), 34 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 658f7f40edac..d19910aa00e0 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -52,38 +52,6 @@ import inspect -class _DummyTagNames(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""" @@ -102,8 +70,6 @@ def _only_if_tracing_inner(*args, **kwargs): # None means 'block everything'. _homeserver_whitelist = None -tags = _DummyTagNames - def init_tracer(config): """Set the whitelists and initialise the JaegerClient tracer @@ -540,3 +506,64 @@ def _wrap_in_span_inner(self, *args, **kwargs): span.finish() return _wrap_in_span_inner + + +def trace_servlet(servlet_name, func): + """Decorator to trace a servlet""" + if not opentracing: + return func + + @wraps(func) + @defer.inlineCallbacks + def _trace_servlet_inner(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(), + "servlet_name": servlet_name, + }, + ): + result = yield defer.maybeDeferred(func, request, *args, **kwargs) + defer.returnValue(result) + + return _trace_servlet_inner + + +class _DummyTagNames(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 + + +tags = _DummyTagNames From ffef442d45272b795855730eaae95f75376f676c Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 18:16:35 +0100 Subject: [PATCH 11/28] Group utils --- synapse/logging/opentracing.py | 23 ++++++++++++++++------- 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index d19910aa00e0..be0885f22a8e 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -52,6 +52,12 @@ import inspect +# Block everything by default +_homeserver_whitelist = None + +##### Util methods + + def only_if_tracing(func): """Executes the function only if we're tracing. Otherwise return. Assumes the function wrapped may return None""" @@ -66,9 +72,19 @@ def _only_if_tracing_inner(*args, **kwargs): return _only_if_tracing_inner +<<<<<<< HEAD # A regex which matches the server_names to expose traces for. # None means 'block everything'. _homeserver_whitelist = None +======= +@contextlib.contextmanager +def _noop_context_manager(*args, **kwargs): + """Does exactly what it says on the tin""" + yield + + +##### Setup +>>>>>>> Group utils def init_tracer(config): @@ -105,13 +121,6 @@ def init_tracer(config): tags = opentracing.tags -@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 - - # Could use kwargs but I want these to be explicit def start_active_span( operation_name, From aab13c7a69fc69f3de9c24c07ebb025c8e7b70d7 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 18:21:10 +0100 Subject: [PATCH 12/28] Move opentracing setters --- synapse/logging/opentracing.py | 127 +++++++++++++++++---------------- 1 file changed, 64 insertions(+), 63 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index be0885f22a8e..78ba2c3d0791 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -72,11 +72,6 @@ def _only_if_tracing_inner(*args, **kwargs): return _only_if_tracing_inner -<<<<<<< HEAD -# A regex which matches the server_names to expose traces for. -# None means 'block everything'. -_homeserver_whitelist = None -======= @contextlib.contextmanager def _noop_context_manager(*args, **kwargs): """Does exactly what it says on the tin""" @@ -84,7 +79,6 @@ def _noop_context_manager(*args, **kwargs): ##### Setup ->>>>>>> Group utils def init_tracer(config): @@ -121,6 +115,8 @@ def init_tracer(config): tags = opentracing.tags +##### Start spans and scopes + # Could use kwargs but I want these to be explicit def start_active_span( operation_name, @@ -163,63 +159,6 @@ def start_active_span_follows_from(operation_name, contexts): return scope -@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) - - -# 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 - -# I also thinks it's dangerous with respect to pii. If the whitelisting -# is missconfigured or buggy span information will leak. This is no issue -# if it's jaeger span id's but baggage can contain any arbitrary data. I would -# suggest removing this. -@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) - - -@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)) - ) - - -@only_if_tracing -def whitelisted_homeserver(destination): - """Checks if a destination matches the whitelist - Args: - destination (String)""" - if _homeserver_whitelist: - return _homeserver_whitelist.match(destination) - return False - - def start_active_span_from_context( headers, operation_name, @@ -300,6 +239,68 @@ def start_active_span_from_edu( return scope +###### Opentracing setters for tags, logs, etc + + +@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) + + +# 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 + +# I also thinks it's dangerous with respect to pii. If the whitelisting +# is missconfigured or buggy span information will leak. This is no issue +# if it's jaeger span id's but baggage can contain any arbitrary data. I would +# suggest removing this. +@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) + + +@only_if_tracing +def set_homeserver_whitelist(homeserver_whitelist): + """Sets the homeserver 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)) + ) + + +@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) + return False + + @only_if_tracing def inject_active_span_twisted_headers(headers, destination): """ From 2a4ef6194a3ad3ffa2f65740ba16eff6702dce4f Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 18:21:51 +0100 Subject: [PATCH 13/28] Move whitelisting --- synapse/logging/opentracing.py | 57 ++++++++++++++++++---------------- 1 file changed, 30 insertions(+), 27 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 78ba2c3d0791..8acd33d202b2 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -115,6 +115,36 @@ def init_tracer(config): tags = opentracing.tags +##### Whitelisting + + +@only_if_tracing +def set_homeserver_whitelist(homeserver_whitelist): + """Sets the homeserver 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)) + ) + + +@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) + return False + + ##### Start spans and scopes # Could use kwargs but I want these to be explicit @@ -274,33 +304,6 @@ def set_operation_name(operation_name): opentracing.tracer.active_span.set_operation_name(operation_name) -@only_if_tracing -def set_homeserver_whitelist(homeserver_whitelist): - """Sets the homeserver 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)) - ) - - -@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) - return False - - @only_if_tracing def inject_active_span_twisted_headers(headers, destination): """ From 6a7e6ef52190a03509cdfe6cfe0ede27ce5aac2e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 11 Jul 2019 18:23:25 +0100 Subject: [PATCH 14/28] Sectioning comments --- synapse/logging/opentracing.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 8acd33d202b2..e4dfd59933c2 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -335,6 +335,9 @@ def inject_active_span_twisted_headers(headers, destination): headers.addRawHeaders(key, value) +##### Injection and extraction + + @only_if_tracing def inject_active_span_byte_dict(headers, destination): """ @@ -399,6 +402,9 @@ def extract_text_map(carrier): return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) +##### Tracing decorators + + def trace_deferred(func): """Decorator to trace a deferred function. Sets the operation name to that of the function's.""" @@ -547,6 +553,9 @@ def _trace_servlet_inner(request, *args, **kwargs): return _trace_servlet_inner +##### Helper class + + class _DummyTagNames(object): """wrapper of opentracings tags. We need to have them if we want to reference them without opentracing around. Clearly they From db0de7b88cf8ce15e0887ef2f26118abf92e149e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 15 Jul 2019 11:23:43 +0100 Subject: [PATCH 15/28] Rebase doctoring --- synapse/logging/opentracing.py | 42 +++++++--------------------------- 1 file changed, 8 insertions(+), 34 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index e4dfd59933c2..f2e447f606d9 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -274,7 +274,7 @@ def start_active_span_from_edu( @only_if_tracing def set_tag(key, value): - """Set's a tag on the active span""" + """Sets a tag on the active span""" opentracing.tracer.active_span.set_tag(key, value) @@ -304,6 +304,9 @@ def set_operation_name(operation_name): opentracing.tracer.active_span.set_operation_name(operation_name) +##### Injection and extraction + + @only_if_tracing def inject_active_span_twisted_headers(headers, destination): """ @@ -335,9 +338,6 @@ def inject_active_span_twisted_headers(headers, destination): headers.addRawHeaders(key, value) -##### Injection and extraction - - @only_if_tracing def inject_active_span_byte_dict(headers, destination): """ @@ -409,33 +409,6 @@ def trace_deferred(func): """Decorator to trace a deferred function. Sets the operation name to that of the function's.""" - -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): - 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(), - "servlet_name": servlet_name, - }, - ): - result = yield defer.maybeDeferred(func, request, *args, **kwargs) - defer.returnValue(result) - - return _trace_servlet_inner - - -def trace_defered_function(func): @wraps(func) @defer.inlineCallbacks def _trace_deferred_inner(self, *args, **kwargs): @@ -504,10 +477,10 @@ def wrap_in_span(func): which is a complete break from the current logcontext. This function creates a non active span from the current context and closes it after the function executes.""" - + global opentracing # I haven't use this function yet - if not TracerUtil._opentracing: + if not opentracing: return func parent_span = opentracing.tracer.active_span @@ -528,7 +501,8 @@ def _wrap_in_span_inner(self, *args, **kwargs): def trace_servlet(servlet_name, func): - """Decorator to trace a servlet""" + """Decorator which traces a serlet. It starts a span with some servlet specific + tags such as the servlet_name and request information""" if not opentracing: return func From ed24125f72ed6a963c5b430b0e55abb2eb876f14 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 13:57:26 +0100 Subject: [PATCH 16/28] Isort opentracing --- synapse/logging/opentracing.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index f2e447f606d9..3627748835e1 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -49,7 +49,6 @@ logger = logging.getLogger(__name__) -import inspect # Block everything by default From 614b32d65030cdb40f28fdd7db9ff802ba839862 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 14:00:05 +0100 Subject: [PATCH 17/28] Fix codestyle --- synapse/logging/opentracing.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 3627748835e1..8baed738e158 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -54,7 +54,7 @@ # Block everything by default _homeserver_whitelist = None -##### Util methods +# Util methods def only_if_tracing(func): @@ -77,7 +77,7 @@ def _noop_context_manager(*args, **kwargs): yield -##### Setup +# Setup def init_tracer(config): @@ -114,7 +114,7 @@ def init_tracer(config): tags = opentracing.tags -##### Whitelisting +# Whitelisting @only_if_tracing @@ -144,7 +144,7 @@ def whitelisted_homeserver(destination): return False -##### Start spans and scopes +# Start spans and scopes # Could use kwargs but I want these to be explicit def start_active_span( @@ -268,7 +268,7 @@ def start_active_span_from_edu( return scope -###### Opentracing setters for tags, logs, etc +# Opentracing setters for tags, logs, etc @only_if_tracing @@ -303,7 +303,7 @@ def set_operation_name(operation_name): opentracing.tracer.active_span.set_operation_name(operation_name) -##### Injection and extraction +# Injection and extraction @only_if_tracing @@ -401,7 +401,7 @@ def extract_text_map(carrier): return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) -##### Tracing decorators +# Tracing decorators def trace_deferred(func): @@ -526,7 +526,7 @@ def _trace_servlet_inner(request, *args, **kwargs): return _trace_servlet_inner -##### Helper class +# Helper class class _DummyTagNames(object): From 1635dd2a6a4e3f937dad0ab5fab71ffe6ee1afd8 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Tue, 16 Jul 2019 11:20:20 +0100 Subject: [PATCH 18/28] Better args wrapper --- synapse/logging/opentracing.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 8baed738e158..c1bea461fd18 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -464,7 +464,10 @@ def _trace_inner(self, *args, **kwargs): def tag_args(func): @wraps(func) def _tag_args_inner(self, *args, **kwargs): - set_tag("args", args) + argspec = inspect.getargspec(func) + for i, arg in enumerate(argspec.args[1:]): + set_tag("ARG_" + arg, args[i]) + set_tag("args", args[len(argspec.args) :]) set_tag("kwargs", kwargs) return func(self, *args, **kwargs) From 8da0f7f31f2f174ee0c4905ac6b66339bcc81306 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 11:18:57 +0100 Subject: [PATCH 19/28] Noop if opentracing is disabled --- synapse/logging/opentracing.py | 27 ++++++++++++++++++++++++++- 1 file changed, 26 insertions(+), 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index c1bea461fd18..afaa399bd6c2 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -164,8 +164,10 @@ def start_active_span( Returns: scope (Scope) or noop_context_manager """ + 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( @@ -207,6 +209,7 @@ 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() @@ -224,7 +227,6 @@ def start_active_span_from_context( ) -@only_if_tracing def start_active_span_from_edu( edu_content, operation_name, @@ -241,6 +243,11 @@ def start_active_span_from_edu( edu_content (Dict): and edu_content with a `context` field whose value is canonical json for a dict which contains opentracing information. """ + + if opentracing is None: + logger.info("++++++++++++++++++++ opentracing is None") + return _noop_context_manager() + carrier = json.loads(edu_content.get("context", "{}")).get("opentracing", {}) context = opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) _references = [ @@ -408,6 +415,9 @@ def trace_deferred(func): """Decorator to trace a deferred function. Sets the operation name to that of the function's.""" + if not opentracing: + return func + @wraps(func) @defer.inlineCallbacks def _trace_deferred_inner(self, *args, **kwargs): @@ -422,6 +432,10 @@ def trace_deferred_using_operation_name(name): """Decorator to trace a deferred function. Explicitely sets the operation_name.""" def trace_deferred(func): + + if not opentracing: + return func + @wraps(func) @defer.inlineCallbacks def _trace_deferred_inner(self, *args, **kwargs): @@ -439,6 +453,9 @@ def trace(func): """Decorator to trace a normal function. Sets the operation name to that of the function's.""" + if not opentracing: + return func + @wraps(func) def _trace_inner(self, *args, **kwargs): with start_active_span(func.__name__): @@ -451,6 +468,10 @@ def trace_using_operation_name(operation_name): """Decorator to trace a function. Explicitely sets the operation_name.""" def trace(func): + + if not opentracing: + return func + @wraps(func) def _trace_inner(self, *args, **kwargs): with start_active_span(operation_name): @@ -462,6 +483,10 @@ def _trace_inner(self, *args, **kwargs): def tag_args(func): + + if not opentracing: + return func + @wraps(func) def _tag_args_inner(self, *args, **kwargs): argspec = inspect.getargspec(func) From edc089ee96f457f632e1f3065328bb60bdb00ffe Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 11:52:27 +0100 Subject: [PATCH 20/28] Unbreak json parsing. --- synapse/logging/opentracing.py | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index afaa399bd6c2..b302285f1bac 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -387,13 +387,11 @@ def inject_active_span_text_map(carrier, destination=None): def active_span_context_as_string(): - if not opentracing: - return None - carrier = {} - opentracing.tracer.inject( - opentracing.tracer.active_span, opentracing.Format.TEXT_MAP, carrier - ) + if opentracing: + opentracing.tracer.inject( + opentracing.tracer.active_span, opentracing.Format.TEXT_MAP, carrier + ) return json.dumps(carrier) From 3d96f861850897cb752e817239fa9096dc390423 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 14:24:04 +0100 Subject: [PATCH 21/28] Cleanup --- synapse/logging/opentracing.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index b302285f1bac..51a4de66aaf0 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -245,7 +245,6 @@ def start_active_span_from_edu( """ if opentracing is None: - logger.info("++++++++++++++++++++ opentracing is None") return _noop_context_manager() carrier = json.loads(edu_content.get("context", "{}")).get("opentracing", {}) From 264f5b6ee4ad5dac58b182c92a2cce314848f9c9 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 17 Jul 2019 14:45:34 +0100 Subject: [PATCH 22/28] newsfile --- changelog.d/5703.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/5703.misc diff --git a/changelog.d/5703.misc b/changelog.d/5703.misc new file mode 100644 index 000000000000..f2d236188dee --- /dev/null +++ b/changelog.d/5703.misc @@ -0,0 +1 @@ +Add a set of opentracing utils. From 7ca6fb358e25ad6464834fe2c8823400d93bf2c9 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 18 Jul 2019 16:09:02 +0100 Subject: [PATCH 23/28] Reintroduce Rich's fine housekeeping. --- synapse/logging/opentracing.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 51a4de66aaf0..ea8b0fe2d9a4 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -25,10 +25,10 @@ # be a matter of few regexes to move over to opentracing's access patterns proper. import contextlib +import inspect import logging import re from functools import wraps -from twisted.internet import defer from canonicaljson import json @@ -52,6 +52,8 @@ # Block everything by default +# A regex which matches the server_names to expose traces for. +# None means 'block everything'. _homeserver_whitelist = None # Util methods From 58901965e8351d22e2016a47d2fed4814fcaa3b3 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Fri, 19 Jul 2019 16:42:18 +0100 Subject: [PATCH 24/28] Rename 5703.misc to 5722.misc --- changelog.d/{5703.misc => 5722.misc} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename changelog.d/{5703.misc => 5722.misc} (100%) diff --git a/changelog.d/5703.misc b/changelog.d/5722.misc similarity index 100% rename from changelog.d/5703.misc rename to changelog.d/5722.misc From a368a361db6f9cc6fabcc348e20dd6a66898f980 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 22 Jul 2019 11:41:29 +0100 Subject: [PATCH 25/28] Docstrings Co-Authored-By: Erik Johnston --- synapse/logging/opentracing.py | 59 ++++++++++++++++++++++++++++++---- 1 file changed, 52 insertions(+), 7 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index ea8b0fe2d9a4..d04c69227864 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -124,7 +124,7 @@ def set_homeserver_whitelist(homeserver_whitelist): """Sets the homeserver whitelist Args: - homeserver_whitelist (iterable of strings): regex of whitelisted homeservers + homeserver_whitelist (Iterable[str]): regex of whitelisted homeservers """ global _homeserver_whitelist if homeserver_whitelist: @@ -139,7 +139,8 @@ def whitelisted_homeserver(destination): """Checks if a destination matches the whitelist Args: - destination (String)""" + destination (str) + """ global _homeserver_whitelist if _homeserver_whitelist: return _homeserver_whitelist.match(destination) @@ -205,6 +206,9 @@ def start_active_span_from_context( Extracts a span context from Twisted Headers. args: headers (twisted.web.http_headers.Headers) + + For the other args see opentracing.tracer + returns: span_context (opentracing.span.SpanContext) """ @@ -242,8 +246,10 @@ def start_active_span_from_edu( Extracts a span context from an edu and uses it to start a new active span Args: - edu_content (Dict): and edu_content with a `context` field whose value is - canonical json for a dict which contains opentracing information. + edu_content (dict): and edu_content with a `context` field whose value is + canonical json for a dict which contains opentracing information. + + For the other args see opentracing.tracer """ if opentracing is None: @@ -317,14 +323,14 @@ def set_operation_name(operation_name): @only_if_tracing def inject_active_span_twisted_headers(headers, destination): """ - Injects a span context into twisted headers inplace + Injects a span context into twisted headers in-place Args: headers (twisted.web.http_headers.Headers) span (opentracing.Span) Returns: - Inplace modification of headers + In-place modification of headers Note: The headers set by the tracer are custom to the tracer implementation which @@ -356,7 +362,7 @@ def inject_active_span_byte_dict(headers, destination): span (opentracing.Span) Returns: - Inplace modification of headers + In-place modification of headers Note: The headers set by the tracer are custom to the tracer implementation which @@ -379,6 +385,26 @@ def inject_active_span_byte_dict(headers, destination): @only_if_tracing def inject_active_span_text_map(carrier, destination=None): + """ + Injects a span context into a dict + + Args: + carrier (dict) + destination (str): the name of the remote server. The span context + will only be injected if the destination matches the homeserver_whitelist + or destination is None. + + Returns: + In-place modification of carrier + + 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 destination and not whitelisted_homeserver(destination): return @@ -388,6 +414,10 @@ def inject_active_span_text_map(carrier, destination=None): def active_span_context_as_string(): + """ + Returns: + The active span context encoded as a string. + """ carrier = {} if opentracing: opentracing.tracer.inject( @@ -398,12 +428,24 @@ def active_span_context_as_string(): @only_if_tracing def span_context_from_string(carrier): + """ + Returns: + The active span context decoded from a string. + """ carrier = json.loads(carrier) return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) @only_if_tracing def extract_text_map(carrier): + """ + Wrapper method for opentracing's tracer.extract for TEXT_MAP. + Args: + carrier (dict): a dict possibly containing a span context. + + Returns: + The active span context extracted from carrier. + """ return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier) @@ -482,6 +524,9 @@ def _trace_inner(self, *args, **kwargs): def tag_args(func): + """ + Tags all of the args to the active span. + """ if not opentracing: return func From d94a332411578757b833a9922604bbdf95577750 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 22 Jul 2019 11:58:27 +0100 Subject: [PATCH 26/28] Remove unused methods. --- synapse/logging/opentracing.py | 42 ---------------------------------- 1 file changed, 42 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index d04c69227864..8f2f73a43d37 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -297,20 +297,6 @@ 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 - -# I also thinks it's dangerous with respect to pii. If the whitelisting -# is missconfigured or buggy span information will leak. This is no issue -# if it's jaeger span id's but baggage can contain any arbitrary data. I would -# suggest removing this. -@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""" @@ -543,34 +529,6 @@ def _tag_args_inner(self, *args, **kwargs): return _tag_args_inner -def wrap_in_span(func): - """Its purpose is to wrap a function that is being passed into a context - which is a complete break from the current logcontext. This function creates - a non active span from the current context and closes it after the function - executes.""" - global opentracing - # I haven't use this function yet - - if not opentracing: - return func - - parent_span = opentracing.tracer.active_span - - @wraps(func) - def _wrap_in_span_inner(self, *args, **kwargs): - span = opentracing.tracer.start_span(func.__name__, child_of=parent_span) - try: - return func(self, *args, **kwargs) - except Exception as e: - span.set_tag("error", True) - span.log_kv({"exception", e}) - raise - finally: - span.finish() - - return _wrap_in_span_inner - - 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""" From 08d8f914d09195f5ddb15b9def5ea57636a1a9b4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 22 Jul 2019 12:00:47 +0100 Subject: [PATCH 27/28] Don't use global --- 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 8f2f73a43d37..84628b92cfba 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -141,7 +141,7 @@ def whitelisted_homeserver(destination): Args: destination (str) """ - global _homeserver_whitelist + _homeserver_whitelist if _homeserver_whitelist: return _homeserver_whitelist.match(destination) return False From 250e6679c0c971ae7b0c642fdabf39ec89238cd4 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Mon, 22 Jul 2019 13:29:15 +0100 Subject: [PATCH 28/28] One tracing decorator to rule them all. --- synapse/logging/opentracing.py | 101 ++++++++++++++++++++------------- 1 file changed, 60 insertions(+), 41 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 84628b92cfba..efb977579bef 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -438,55 +438,45 @@ def extract_text_map(carrier): # Tracing decorators -def trace_deferred(func): - """Decorator to trace a deferred function. Sets the operation name to that of the - function's.""" - - if not opentracing: +def trace(func): + """ + Decorator to trace a function. + Sets the operation name to that of the function's. + """ + if opentracing is None: return func @wraps(func) - @defer.inlineCallbacks - def _trace_deferred_inner(self, *args, **kwargs): - with start_active_span(func.__name__): - r = yield func(self, *args, **kwargs) - defer.returnValue(r) - - return _trace_deferred_inner - + def _trace_inner(self, *args, **kwargs): + if opentracing is None: + return func(self, *args, **kwargs) -def trace_deferred_using_operation_name(name): - """Decorator to trace a deferred function. Explicitely sets the operation_name.""" + scope = start_active_span(func.__name__) + scope.__enter__() - def trace_deferred(func): + try: + result = func(self, *args, **kwargs) + if isinstance(result, defer.Deferred): - if not opentracing: - return func + def call_back(result): + scope.__exit__(None, None, None) + return result - @wraps(func) - @defer.inlineCallbacks - def _trace_deferred_inner(self, *args, **kwargs): - # Start scope - with start_active_span(name): - r = yield func(self, *args, **kwargs) - defer.returnValue(r) + def err_back(result): + scope.span.set_tag(tags.ERROR, True) + scope.__exit__(None, None, None) + return result - return _trace_deferred_inner + result.addCallbacks(call_back, err_back) - return trace_deferred + else: + scope.__exit__(None, None, None) + return result -def trace(func): - """Decorator to trace a normal function. Sets the operation name to that of the - function's.""" - - if not opentracing: - return func - - @wraps(func) - def _trace_inner(self, *args, **kwargs): - with start_active_span(func.__name__): - return func(self, *args, **kwargs) + except Exception as e: + scope.__exit__(type(e), None, e.__traceback__) + raise return _trace_inner @@ -495,15 +485,44 @@ def trace_using_operation_name(operation_name): """Decorator to trace a function. Explicitely sets the operation_name.""" def trace(func): - - if not opentracing: + """ + Decorator to trace a function. + Sets the operation name to that of the function's. + """ + if opentracing is None: return func @wraps(func) def _trace_inner(self, *args, **kwargs): - with start_active_span(operation_name): + if opentracing is None: return func(self, *args, **kwargs) + scope = start_active_span(operation_name) + scope.__enter__() + + try: + result = func(self, *args, **kwargs) + if isinstance(result, defer.Deferred): + + def call_back(result): + scope.__exit__(None, None, None) + return result + + def err_back(result): + scope.span.set_tag(tags.ERROR, True) + scope.__exit__(None, None, None) + return result + + result.addCallbacks(call_back, err_back) + else: + scope.__exit__(None, None, None) + + return result + + except Exception as e: + scope.__exit__(type(e), None, e.__traceback__) + raise + return _trace_inner return trace