From 988caa006631448bc0f2afc683da45f73f5e900b Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 16 Jul 2020 10:30:50 -0400 Subject: [PATCH 1/6] Fix the trace function for async functions. --- changelog.d/7872.bugfix | 1 + synapse/logging/opentracing.py | 68 ++++++++++++++++++++++------------ 2 files changed, 46 insertions(+), 23 deletions(-) create mode 100644 changelog.d/7872.bugfix diff --git a/changelog.d/7872.bugfix b/changelog.d/7872.bugfix new file mode 100644 index 000000000000..2ff71c00a6ca --- /dev/null +++ b/changelog.d/7872.bugfix @@ -0,0 +1 @@ +Fix a long standing bug where the tracing of async functions was broken. diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index c6c0e623c16e..a3b59dfdbaa3 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -733,37 +733,59 @@ def decorator(func): _opname = opname if opname else func.__name__ - @wraps(func) - def _trace_inner(*args, **kwargs): - if opentracing is None: - return func(*args, **kwargs) + if inspect.iscoroutinefunction(func): + @wraps(func) + async def _trace_inner(*args, **kwargs): + if opentracing is None: + return await func(*args, **kwargs) - scope = start_active_span(_opname) - scope.__enter__() + scope = start_active_span(_opname) + scope.__enter__() - try: - result = func(*args, **kwargs) - if isinstance(result, defer.Deferred): + try: + result = await func(*args, **kwargs) + scope.__exit__(None, None, None) + return result - def call_back(result): - scope.__exit__(None, None, None) - return result + except Exception as e: + scope.span.set_tag(tags.ERROR, True) + scope.__exit__(type(e), None, e.__traceback__) + raise - def err_back(result): - scope.span.set_tag(tags.ERROR, True) - scope.__exit__(None, None, None) - return result + else: + # The other case here handles both sync functions and those + # decorated with inlineDeferred. + @wraps(func) + def _trace_inner(*args, **kwargs): + if opentracing is None: + return func(*args, **kwargs) - result.addCallbacks(call_back, err_back) + scope = start_active_span(_opname) + scope.__enter__() - else: - scope.__exit__(None, None, None) + try: + result = func(*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 + return result - except Exception as e: - scope.__exit__(type(e), None, e.__traceback__) - raise + except Exception as e: + scope.__exit__(type(e), None, e.__traceback__) + raise return _trace_inner From 9d623e8c700ffa41dc9ff943dc799cafd3479411 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 16 Jul 2020 10:54:21 -0400 Subject: [PATCH 2/6] Remove duplicate checks for if opentracing is enabled. --- synapse/logging/opentracing.py | 6 ------ 1 file changed, 6 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index a3b59dfdbaa3..648aab999515 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -736,9 +736,6 @@ def decorator(func): if inspect.iscoroutinefunction(func): @wraps(func) async def _trace_inner(*args, **kwargs): - if opentracing is None: - return await func(*args, **kwargs) - scope = start_active_span(_opname) scope.__enter__() @@ -757,9 +754,6 @@ async def _trace_inner(*args, **kwargs): # decorated with inlineDeferred. @wraps(func) def _trace_inner(*args, **kwargs): - if opentracing is None: - return func(*args, **kwargs) - scope = start_active_span(_opname) scope.__enter__() From c5c3ef46524f3e99582ffccecfad8dd89781ae56 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 16 Jul 2020 10:57:15 -0400 Subject: [PATCH 3/6] Fix lint. --- synapse/logging/opentracing.py | 1 + 1 file changed, 1 insertion(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 648aab999515..8d847fa61308 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -734,6 +734,7 @@ def decorator(func): _opname = opname if opname else func.__name__ if inspect.iscoroutinefunction(func): + @wraps(func) async def _trace_inner(*args, **kwargs): scope = start_active_span(_opname) From f58a80e8a410d0b19d5c3a79c491e8d3248b89c0 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 16 Jul 2020 11:01:34 -0400 Subject: [PATCH 4/6] Use a context manager. --- synapse/logging/opentracing.py | 18 ++++++------------ 1 file changed, 6 insertions(+), 12 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 8d847fa61308..b62731a85536 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -737,18 +737,12 @@ def decorator(func): @wraps(func) async def _trace_inner(*args, **kwargs): - scope = start_active_span(_opname) - scope.__enter__() - - try: - result = await func(*args, **kwargs) - scope.__exit__(None, None, None) - return result - - except Exception as e: - scope.span.set_tag(tags.ERROR, True) - scope.__exit__(type(e), None, e.__traceback__) - raise + with start_active_span(_opname) as scope: + try: + return await func(*args, **kwargs) + except Exception: + scope.span.set_tag(tags.ERROR, True) + raise else: # The other case here handles both sync functions and those From cb835123c2ce3b9a32be2a666b222b90451fbad5 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 16 Jul 2020 12:00:44 -0400 Subject: [PATCH 5/6] Add back the runtime guards. --- synapse/logging/opentracing.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index b62731a85536..21015175758c 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -737,6 +737,9 @@ def decorator(func): @wraps(func) async def _trace_inner(*args, **kwargs): + if opentracing is None: + return await func(*args, **kwargs) + with start_active_span(_opname) as scope: try: return await func(*args, **kwargs) @@ -749,6 +752,9 @@ async def _trace_inner(*args, **kwargs): # decorated with inlineDeferred. @wraps(func) def _trace_inner(*args, **kwargs): + if opentracing is None: + return func(*args, **kwargs) + scope = start_active_span(_opname) scope.__enter__() From b269f22f94d39251964a76f86ecd024cbcc1270d Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Fri, 17 Jul 2020 11:33:36 -0400 Subject: [PATCH 6/6] Clarify the changelog Co-authored-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> --- changelog.d/7872.bugfix | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog.d/7872.bugfix b/changelog.d/7872.bugfix index 2ff71c00a6ca..b21f8e1f147d 100644 --- a/changelog.d/7872.bugfix +++ b/changelog.d/7872.bugfix @@ -1 +1 @@ -Fix a long standing bug where the tracing of async functions was broken. +Fix a long standing bug where the tracing of async functions with opentracing was broken.