From 0edd0a58434d2bd2ba0b986766444bd314b97487 Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:11:31 +0100 Subject: [PATCH 1/4] Add some decorators to gracefully handle a missing context. --- synapse/logging/opentracing.py | 110 ++++++++++++++++++++------------- 1 file changed, 68 insertions(+), 42 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 2c34b5470249..01ecedbca36b 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -238,18 +238,46 @@ class _DummyTagNames(object): # Util methods -def only_if_tracing(func): - """Executes the function only if we're tracing. Otherwise return. - Assumes the function wrapped may return None""" +def only_if_tracing(func=None, ret=None): + """Executes the function only if we're tracing. Otherwise returns `ret`.""" + + def only_if_tracing_inner_1(func): + @wraps(func) + def only_if_tracing_inner_2(*args, **kwargs): + if opentracing: + return func(*args, **kwargs) + else: + return ret + + return only_if_tracing_inner_2 + + if func: + return only_if_tracing_inner_1(func) + else: + return only_if_tracing_inner_1 + + +def ensure_active_span(message, ret=None): + """Executes the operation only if there is an active span. Otherwise it logs + an error and returns 'ret'.""" + + def ensure_active_span_inner_1(func): + @wraps(func) + def ensure_active_span_inner_2(*args, **kwargs): + if not opentracing.tracer.active_span: + logger.error( + "There was no active span when trying to %s." + " Did you forget to start one or did a context slip?", + message, + ) + + return ret - @wraps(func) - def _only_if_tracing_inner(*args, **kwargs): - if opentracing: return func(*args, **kwargs) - else: - return - return _only_if_tracing_inner + return ensure_active_span_inner_2 + + return ensure_active_span_inner_1 @contextlib.contextmanager @@ -312,7 +340,7 @@ def set_homeserver_whitelist(homeserver_whitelist): ) -@only_if_tracing +@only_if_tracing(ret=False) def whitelisted_homeserver(destination): """Checks if a destination matches the whitelist @@ -328,6 +356,7 @@ def whitelisted_homeserver(destination): # Start spans and scopes # Could use kwargs but I want these to be explicit +@only_if_tracing(ret=_noop_context_manager()) def start_active_span( operation_name, child_of=None, @@ -345,32 +374,25 @@ 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( - 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, - ) + 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(ret=_noop_context_manager()) 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 + references = [opentracing.follows_from(context) for context in contexts] + scope = start_active_span(operation_name, references=references) + return scope +@only_if_tracing(ret=_noop_context_manager()) def start_active_span_from_request( request, operation_name, @@ -394,9 +416,6 @@ def start_active_span_from_request( # 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 request.requestHeaders.getAllRawHeaders() } @@ -413,6 +432,7 @@ def start_active_span_from_request( ) +@only_if_tracing(ret=_noop_context_manager()) def start_active_span_from_edu( edu_content, operation_name, @@ -432,9 +452,6 @@ def start_active_span_from_edu( For the other args see opentracing.tracer """ - if 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 = [ @@ -466,18 +483,21 @@ def start_active_span_from_edu( @only_if_tracing +@ensure_active_span("set a tag") def set_tag(key, value): """Sets a tag on the active span""" opentracing.tracer.active_span.set_tag(key, value) @only_if_tracing +@ensure_active_span("log") def log_kv(key_values, timestamp=None): """Log to the active span""" opentracing.tracer.active_span.log_kv(key_values, timestamp) @only_if_tracing +@ensure_active_span("set the traces operation name") def set_operation_name(operation_name): """Sets the operation name of the active span""" opentracing.tracer.active_span.set_operation_name(operation_name) @@ -487,6 +507,7 @@ def set_operation_name(operation_name): @only_if_tracing +@ensure_active_span("inject the span into a header") def inject_active_span_twisted_headers(headers, destination, check_destination=True): """ Injects a span context into twisted headers in-place @@ -523,6 +544,7 @@ def inject_active_span_twisted_headers(headers, destination, check_destination=T @only_if_tracing +@ensure_active_span("inject the span into a byte dict") def inject_active_span_byte_dict(headers, destination, check_destination=True): """ Injects a span context into a dict where the headers are encoded as byte @@ -560,6 +582,7 @@ def inject_active_span_byte_dict(headers, destination, check_destination=True): @only_if_tracing +@ensure_active_span("inject the span into a text map") def inject_active_span_text_map(carrier, destination, check_destination=True): """ Injects a span context into a dict @@ -591,6 +614,8 @@ def inject_active_span_text_map(carrier, destination, check_destination=True): ) +@only_if_tracing(ret={}) +@ensure_active_span("get the active span context as a dict", ret={}) def get_active_span_text_map(destination=None): """ Gets a span context as a dict. This can be used instead of manually @@ -603,7 +628,7 @@ def get_active_span_text_map(destination=None): dict: the active span's context if opentracing is enabled, otherwise empty. """ - if not opentracing or (destination and not whitelisted_homeserver(destination)): + if destination and not whitelisted_homeserver(destination): return {} carrier = {} @@ -614,16 +639,17 @@ def get_active_span_text_map(destination=None): return carrier +@only_if_tracing(ret={}) +@ensure_active_span("get the span context as a string.", ret={}) def active_span_context_as_string(): """ Returns: The active span context encoded as a string. """ carrier = {} - if opentracing: - opentracing.tracer.inject( - opentracing.tracer.active_span, opentracing.Format.TEXT_MAP, carrier - ) + opentracing.tracer.inject( + opentracing.tracer.active_span, opentracing.Format.TEXT_MAP, carrier + ) return json.dumps(carrier) From 9a9ac131ec619a53203c686a9449c98b0d8372fc Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:17:43 +0100 Subject: [PATCH 2/4] newsfile --- changelog.d/5988.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/5988.bugfix diff --git a/changelog.d/5988.bugfix b/changelog.d/5988.bugfix new file mode 100644 index 000000000000..5c3597cb53c6 --- /dev/null +++ b/changelog.d/5988.bugfix @@ -0,0 +1 @@ +Fix invalid references to None while opentracing if the log context slips. From c23637b3d683f45d35d2bb01c033feb98c13fede Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:39:00 +0100 Subject: [PATCH 3/4] Make ensure_active_span also check for opentracing --- synapse/logging/opentracing.py | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 01ecedbca36b..d28b2e77cf9e 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -264,6 +264,9 @@ def ensure_active_span(message, ret=None): def ensure_active_span_inner_1(func): @wraps(func) def ensure_active_span_inner_2(*args, **kwargs): + if not opentracing: + return ret + if not opentracing.tracer.active_span: logger.error( "There was no active span when trying to %s." @@ -482,21 +485,18 @@ def start_active_span_from_edu( # Opentracing setters for tags, logs, etc -@only_if_tracing @ensure_active_span("set a tag") def set_tag(key, value): """Sets a tag on the active span""" opentracing.tracer.active_span.set_tag(key, value) -@only_if_tracing @ensure_active_span("log") def log_kv(key_values, timestamp=None): """Log to the active span""" opentracing.tracer.active_span.log_kv(key_values, timestamp) -@only_if_tracing @ensure_active_span("set the traces operation name") def set_operation_name(operation_name): """Sets the operation name of the active span""" @@ -506,7 +506,6 @@ def set_operation_name(operation_name): # Injection and extraction -@only_if_tracing @ensure_active_span("inject the span into a header") def inject_active_span_twisted_headers(headers, destination, check_destination=True): """ @@ -543,7 +542,6 @@ def inject_active_span_twisted_headers(headers, destination, check_destination=T headers.addRawHeaders(key, value) -@only_if_tracing @ensure_active_span("inject the span into a byte dict") def inject_active_span_byte_dict(headers, destination, check_destination=True): """ @@ -581,7 +579,6 @@ def inject_active_span_byte_dict(headers, destination, check_destination=True): headers[key.encode()] = [value.encode()] -@only_if_tracing @ensure_active_span("inject the span into a text map") def inject_active_span_text_map(carrier, destination, check_destination=True): """ @@ -614,7 +611,6 @@ def inject_active_span_text_map(carrier, destination, check_destination=True): ) -@only_if_tracing(ret={}) @ensure_active_span("get the active span context as a dict", ret={}) def get_active_span_text_map(destination=None): """ @@ -639,7 +635,6 @@ def get_active_span_text_map(destination=None): return carrier -@only_if_tracing(ret={}) @ensure_active_span("get the span context as a string.", ret={}) def active_span_context_as_string(): """ From 1fe3043330098be380a158ad3aa587ad99ca7d6e Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Thu, 5 Sep 2019 16:59:33 +0100 Subject: [PATCH 4/4] Revert to only_if_tracing returning None :( --- synapse/logging/opentracing.py | 63 ++++++++++++++++++++-------------- 1 file changed, 38 insertions(+), 25 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index d28b2e77cf9e..8c574ddd2851 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -238,28 +238,31 @@ class _DummyTagNames(object): # Util methods -def only_if_tracing(func=None, ret=None): - """Executes the function only if we're tracing. Otherwise returns `ret`.""" +def only_if_tracing(func): + """Executes the function only if we're tracing. Otherwise returns None.""" - def only_if_tracing_inner_1(func): - @wraps(func) - def only_if_tracing_inner_2(*args, **kwargs): - if opentracing: - return func(*args, **kwargs) - else: - return ret + @wraps(func) + def _only_if_tracing_inner(*args, **kwargs): + if opentracing: + return func(*args, **kwargs) + else: + return - return only_if_tracing_inner_2 - - if func: - return only_if_tracing_inner_1(func) - else: - return only_if_tracing_inner_1 + return _only_if_tracing_inner def ensure_active_span(message, ret=None): - """Executes the operation only if there is an active span. Otherwise it logs - an error and returns 'ret'.""" + """Executes the operation only if opentracing is enabled and there is an active span. + If there is no active span it logs message at the error level. + + Args: + message (str): Message which fills in "There was no active span when trying to %s" + in the error log if there is no active span and opentracing is enabled. + ret (object): return value if opentracing is None or there is no active span. + + Returns (object): The result of the func or ret if opentracing is disabled or there + was no active span. + """ def ensure_active_span_inner_1(func): @wraps(func) @@ -343,7 +346,7 @@ def set_homeserver_whitelist(homeserver_whitelist): ) -@only_if_tracing(ret=False) +@only_if_tracing def whitelisted_homeserver(destination): """Checks if a destination matches the whitelist @@ -359,7 +362,6 @@ def whitelisted_homeserver(destination): # Start spans and scopes # Could use kwargs but I want these to be explicit -@only_if_tracing(ret=_noop_context_manager()) def start_active_span( operation_name, child_of=None, @@ -377,6 +379,10 @@ def start_active_span( Returns: scope (Scope) or noop_context_manager """ + + if opentracing is None: + return _noop_context_manager() + return opentracing.tracer.start_active_span( operation_name, child_of=child_of, @@ -388,14 +394,15 @@ def start_active_span( ) -@only_if_tracing(ret=_noop_context_manager()) def start_active_span_follows_from(operation_name, contexts): + if opentracing is None: + return _noop_context_manager() + references = [opentracing.follows_from(context) for context in contexts] scope = start_active_span(operation_name, references=references) return scope -@only_if_tracing(ret=_noop_context_manager()) def start_active_span_from_request( request, operation_name, @@ -419,6 +426,9 @@ def start_active_span_from_request( # 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 request.requestHeaders.getAllRawHeaders() } @@ -435,7 +445,6 @@ def start_active_span_from_request( ) -@only_if_tracing(ret=_noop_context_manager()) def start_active_span_from_edu( edu_content, operation_name, @@ -455,6 +464,9 @@ def start_active_span_from_edu( For the other args see opentracing.tracer """ + if 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 = [ @@ -642,9 +654,10 @@ def active_span_context_as_string(): The active span context encoded as a string. """ 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)