From b21fc7c1f4beff32f8000b3946e8e9ca624bd3bb Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 3 Aug 2022 21:13:00 -0500 Subject: [PATCH 01/15] Allow use of both @trace and @tag_args stacked on the same function ```py @trace @tag_args async def get_oldest_event_ids_with_depth_in_room(...) ... ``` --- synapse/logging/opentracing.py | 146 ++++++++++++++++++++------------- 1 file changed, 91 insertions(+), 55 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index c1aa205eedde..4481069020bf 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -173,6 +173,7 @@ def set_fates(clotho, lachesis, atropos, father="Zues", mother="Themis"): Any, Callable, Collection, + ContextManager, Dict, Generator, Iterable, @@ -823,75 +824,110 @@ def extract_text_map(carrier: Dict[str, str]) -> Optional["opentracing.SpanConte # Tracing decorators -def trace_with_opname(opname: str) -> Callable[[Callable[P, R]], Callable[P, R]]: +def _create_decorator( + func: Callable[P, R], + # TODO: What is the correct type for these `Any`? `P.args, P.kwargs` isn't allowed here + wrapping_logic: Callable[[Callable[P, R], Any, Any], ContextManager[None]], +) -> Callable[P, R]: """ - Decorator to trace a function with a custom opname. - - See the module's doc string for usage examples. - + Creates a decorator that is able to handle sync functions, async functions + (coroutines), and inlineDeferred from Twisted. + Example usage: + ```py + # Decorator to time the function and log it out + def duration(func: Callable[P, R]) -> Callable[P, R]: + @contextlib.contextmanager + def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): + start_ts = time.time() + yield + end_ts = time.time() + duration = end_ts - start_ts + logger.info("%s took %s seconds", func.__name__, duration) + return _create_decorator(func, _wrapping_logic) + ``` + Args: + func: The function to be decorated + wrapping_logic: The business logic of your custom decorator. + This should be a ContextManager so you are able to run your logic + before/after the function as desired. """ - def decorator(func: Callable[P, R]) -> Callable[P, R]: - if opentracing is None: - return func # type: ignore[unreachable] - + @wraps(func) + async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R: if inspect.iscoroutinefunction(func): - - @wraps(func) - async def _trace_inner(*args: P.args, **kwargs: P.kwargs) -> R: - with start_active_span(opname): - return await func(*args, **kwargs) # type: ignore[misc] - + with wrapping_logic(func, *args, **kwargs): + return await func(*args, **kwargs) else: # The other case here handles both sync functions and those # decorated with inlineDeferred. - @wraps(func) - def _trace_inner(*args: P.args, **kwargs: P.kwargs) -> R: - scope = start_active_span(opname) - scope.__enter__() - - try: - result = func(*args, **kwargs) - if isinstance(result, defer.Deferred): - - def call_back(result: R) -> R: - scope.__exit__(None, None, None) - return result - - def err_back(result: R) -> R: - scope.__exit__(None, None, None) - return result - - result.addCallbacks(call_back, err_back) - - else: - if inspect.isawaitable(result): - logger.error( - "@trace may not have wrapped %s correctly! " - "The function is not async but returned a %s.", - func.__qualname__, - type(result).__name__, - ) + scope = wrapping_logic(func, *args, **kwargs) + scope.__enter__() + try: + result = func(*args, **kwargs) + if isinstance(result, defer.Deferred): + + def call_back(result: R) -> R: scope.__exit__(None, None, None) + return result - return result + def err_back(result: R) -> R: + scope.__exit__(None, None, None) + return result - except Exception as e: - scope.__exit__(type(e), None, e.__traceback__) - raise + result.addCallbacks(call_back, err_back) - return _trace_inner # type: ignore[return-value] + else: + if inspect.isawaitable(result): + logger.error( + "@trace may not have wrapped %s correctly! " + "The function is not async but returned a %s.", + func.__qualname__, + type(result).__name__, + ) - return decorator + scope.__exit__(None, None, None) + + return result + + except Exception as e: + scope.__exit__(type(e), None, e.__traceback__) + raise + + return _wrapper # type: ignore[return-value] + + +def trace_with_opname(opname: str) -> Callable[[Callable[P, R]], Callable[P, R]]: + """ + Decorator to trace a function with a custom opname. + See the module's doc string for usage examples. + """ + + @contextlib.contextmanager + def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): + if opentracing is None: + return None + + scope = start_active_span(opname) + scope.__enter__() + try: + yield + except Exception as e: + scope.__exit__(type(e), None, e.__traceback__) + raise + finally: + scope.__exit__(None, None, None) + + def _decorator(func: Callable[P, R]): + return _create_decorator(func, _wrapping_logic) + + return _decorator def trace(func: Callable[P, R]) -> Callable[P, R]: """ Decorator to trace a function. - Sets the operation name to that of the function's name. - See the module's doc string for usage examples. """ @@ -900,22 +936,22 @@ def trace(func: Callable[P, R]) -> Callable[P, R]: def tag_args(func: Callable[P, R]) -> Callable[P, R]: """ - Tags all of the args to the active span. + Decorator to tag all of the args to the active span. """ if not opentracing: return func - @wraps(func) - def _tag_args_inner(*args: P.args, **kwargs: P.kwargs) -> R: + @contextlib.contextmanager + def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): argspec = inspect.getfullargspec(func) for i, arg in enumerate(argspec.args[1:]): set_tag("ARG_" + arg, str(args[i])) # type: ignore[index] set_tag("args", str(args[len(argspec.args) :])) # type: ignore[index] set_tag("kwargs", str(kwargs)) - return func(*args, **kwargs) + yield - return _tag_args_inner + return _create_decorator(func, _wrapping_logic) @contextlib.contextmanager From 991f3d0b79bb955179ac222b2bb79c61e81d5fe7 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 3 Aug 2022 21:19:12 -0500 Subject: [PATCH 02/15] Add changelog --- changelog.d/13453.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/13453.misc diff --git a/changelog.d/13453.misc b/changelog.d/13453.misc new file mode 100644 index 000000000000..d30c5230c865 --- /dev/null +++ b/changelog.d/13453.misc @@ -0,0 +1 @@ +Allow use of both `@trace` and `@tag_args` stacked on the same function (tracing). From 87b09dc8fa422b403be758bc74dc6c662b64b394 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 00:05:58 -0500 Subject: [PATCH 03/15] Simpify wrapper logic --- synapse/logging/opentracing.py | 19 +++++++++++-------- 1 file changed, 11 insertions(+), 8 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 4481069020bf..fdeab9102561 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -908,15 +908,18 @@ def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): if opentracing is None: return None - scope = start_active_span(opname) - scope.__enter__() - try: + with start_active_span(opname): yield - except Exception as e: - scope.__exit__(type(e), None, e.__traceback__) - raise - finally: - scope.__exit__(None, None, None) + + # scope = start_active_span(opname) + # scope.__enter__() + # try: + # yield + # except Exception as e: + # scope.__exit__(type(e), None, e.__traceback__) + # raise + # finally: + # scope.__exit__(None, None, None) def _decorator(func: Callable[P, R]): return _create_decorator(func, _wrapping_logic) From 6727f3d5d5cd8b621e9e1553dfc7ff0ee922f67d Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 00:06:09 -0500 Subject: [PATCH 04/15] Add some usage --- synapse/storage/databases/main/event_federation.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/synapse/storage/databases/main/event_federation.py b/synapse/storage/databases/main/event_federation.py index eec55b647857..856b327a94d9 100644 --- a/synapse/storage/databases/main/event_federation.py +++ b/synapse/storage/databases/main/event_federation.py @@ -33,6 +33,7 @@ from synapse.api.errors import StoreError from synapse.api.room_versions import EventFormatVersions, RoomVersion from synapse.events import EventBase, make_event_from_dict +from synapse.logging.opentracing import tag_args, trace from synapse.metrics.background_process_metrics import wrap_as_background_process from synapse.storage._base import SQLBaseStore, db_to_json, make_in_list_sql_clause from synapse.storage.database import ( @@ -709,6 +710,8 @@ def _get_auth_chain_difference_txn( # Return all events where not all sets can reach them. return {eid for eid, n in event_to_missing_sets.items() if n} + @trace + @tag_args async def get_oldest_event_ids_with_depth_in_room( self, room_id: str ) -> List[Tuple[str, int]]: From 0bb8f7be3454a9e8547638e609460ccdab495bdb Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 00:09:11 -0500 Subject: [PATCH 05/15] Remove dead code --- synapse/logging/opentracing.py | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index fdeab9102561..71de142973f1 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -911,16 +911,6 @@ def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): with start_active_span(opname): yield - # scope = start_active_span(opname) - # scope.__enter__() - # try: - # yield - # except Exception as e: - # scope.__exit__(type(e), None, e.__traceback__) - # raise - # finally: - # scope.__exit__(None, None, None) - def _decorator(func: Callable[P, R]): return _create_decorator(func, _wrapping_logic) From e57ccaaaf5e171575f3f3005e0fff05513f9cc88 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 16:53:01 -0500 Subject: [PATCH 06/15] Fix some types and add tests --- synapse/logging/opentracing.py | 44 ++++++++++------ tests/logging/test_opentracing.py | 83 +++++++++++++++++++++++++++++++ 2 files changed, 111 insertions(+), 16 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 0ec0a06ec2ea..20223f0b37f0 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -837,7 +837,7 @@ def _create_decorator( # Decorator to time the function and log it out def duration(func: Callable[P, R]) -> Callable[P, R]: @contextlib.contextmanager - def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): + def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs) -> Generator[None, None, None]: start_ts = time.time() yield end_ts = time.time() @@ -852,14 +852,18 @@ def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): before/after the function as desired. """ - @wraps(func) - async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R: - if inspect.iscoroutinefunction(func): + if inspect.iscoroutinefunction(func): + + @wraps(func) + async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R: with wrapping_logic(func, *args, **kwargs): - return await func(*args, **kwargs) - else: - # The other case here handles both sync functions and those - # decorated with inlineDeferred. + return await func(*args, **kwargs) # type: ignore[misc] + + else: + # The other case here handles both sync functions and those + # decorated with inlineDeferred. + @wraps(func) + def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R: scope = wrapping_logic(func, *args, **kwargs) scope.__enter__() @@ -897,21 +901,27 @@ def err_back(result: R) -> R: return _wrapper # type: ignore[return-value] -def trace_with_opname(opname: str) -> Callable[[Callable[P, R]], Callable[P, R]]: +def trace_with_opname( + opname: str, + *, + tracer: Optional["opentracing.Tracer"] = None, +) -> Callable[[Callable[P, R]], Callable[P, R]]: """ Decorator to trace a function with a custom opname. See the module's doc string for usage examples. """ @contextlib.contextmanager - def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): - if opentracing is None: - return None - - with start_active_span(opname): + def _wrapping_logic( + func: Callable[P, R], *args: P.args, **kwargs: P.kwargs + ) -> Generator[None, None, None]: + with start_active_span(opname, tracer=tracer): yield - def _decorator(func: Callable[P, R]): + def _decorator(func: Callable[P, R]) -> Callable[P, R]: + if not opentracing: + return func + return _create_decorator(func, _wrapping_logic) return _decorator @@ -941,7 +951,9 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: return func @contextlib.contextmanager - def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs): + def _wrapping_logic( + func: Callable[P, R], *args: P.args, **kwargs: P.kwargs + ) -> Generator[None, None, None]: argspec = inspect.getfullargspec(func) # We use `[1:]` to skip the `self` object reference and `start=1` to # make the index line up with `argspec.args`. diff --git a/tests/logging/test_opentracing.py b/tests/logging/test_opentracing.py index 3b14c76d7e65..2f94d166a412 100644 --- a/tests/logging/test_opentracing.py +++ b/tests/logging/test_opentracing.py @@ -25,6 +25,8 @@ from synapse.logging.opentracing import ( start_active_span, start_active_span_follows_from, + tag_args, + trace_with_opname, ) from synapse.util import Clock @@ -38,8 +40,12 @@ except ImportError: jaeger_client = None # type: ignore +import logging + from tests.unittest import TestCase +logger = logging.getLogger(__name__) + class LogContextScopeManagerTestCase(TestCase): """ @@ -194,3 +200,80 @@ async def root(): self._reporter.get_spans(), [scopes[1].span, scopes[2].span, scopes[0].span], ) + + def test_trace_decorator_sync(self) -> None: + """ + Test whether we can use `@trace_with_opname` (`@trace`) and `@tag_args` + with sync functions + """ + with LoggingContext("root context"): + + @trace_with_opname("fixture_sync_func", tracer=self._tracer) + @tag_args + def fixture_sync_func() -> str: + return "foo" + + result = fixture_sync_func() + self.assertEqual(result, "foo") + + # the span should have been reported + self.assertEqual( + [span.operation_name for span in self._reporter.get_spans()], + ["fixture_sync_func"], + ) + + def test_trace_decorator_deferred(self) -> None: + """ + Test whether we can use `@trace_with_opname` (`@trace`) and `@tag_args` + with functions that return deferreds + """ + reactor = MemoryReactorClock() + + with LoggingContext("root context"): + + @trace_with_opname("fixture_deferred_func", tracer=self._tracer) + @tag_args + def fixture_deferred_func() -> defer.Deferred[str]: + d1: defer.Deferred[str] = defer.Deferred() + d1.callback("foo") + return d1 + + result_d1 = fixture_deferred_func() + + # let the tasks complete + reactor.pump((2,) * 8) + + self.assertEqual(self.successResultOf(result_d1), "foo") + + # the span should have been reported + self.assertEqual( + [span.operation_name for span in self._reporter.get_spans()], + ["fixture_deferred_func"], + ) + + def test_trace_decorator_async(self) -> None: + """ + Test whether we can use `@trace_with_opname` (`@trace`) and `@tag_args` + with async functions + """ + reactor = MemoryReactorClock() + + with LoggingContext("root context"): + + @trace_with_opname("fixture_async_func", tracer=self._tracer) + @tag_args + async def fixture_async_func() -> str: + return "foo" + + d1 = defer.ensureDeferred(fixture_async_func()) + + # let the tasks complete + reactor.pump((2,) * 8) + + self.assertEqual(self.successResultOf(d1), "foo") + + # the span should have been reported + self.assertEqual( + [span.operation_name for span in self._reporter.get_spans()], + ["fixture_async_func"], + ) From 00cc8a0c0fd842f8859de2f5d8ebf98dd6618446 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 17:01:45 -0500 Subject: [PATCH 07/15] Remove usage --- synapse/storage/databases/main/event_federation.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/synapse/storage/databases/main/event_federation.py b/synapse/storage/databases/main/event_federation.py index 856b327a94d9..3209df89f3cc 100644 --- a/synapse/storage/databases/main/event_federation.py +++ b/synapse/storage/databases/main/event_federation.py @@ -710,8 +710,6 @@ def _get_auth_chain_difference_txn( # Return all events where not all sets can reach them. return {eid for eid, n in event_to_missing_sets.items() if n} - @trace - @tag_args async def get_oldest_event_ids_with_depth_in_room( self, room_id: str ) -> List[Tuple[str, int]]: From 223e60028debdb084cbef249e6c93c070bbd072b Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 17:05:09 -0500 Subject: [PATCH 08/15] Remove todo --- synapse/logging/opentracing.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 20223f0b37f0..0613f249f2ec 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -826,7 +826,6 @@ def extract_text_map(carrier: Dict[str, str]) -> Optional["opentracing.SpanConte def _create_decorator( func: Callable[P, R], - # TODO: What is the correct type for these `Any`? `P.args, P.kwargs` isn't allowed here wrapping_logic: Callable[[Callable[P, R], Any, Any], ContextManager[None]], ) -> Callable[P, R]: """ From f218fa2457770c145d8032988b212e7c84f0ce42 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 12:41:36 -0500 Subject: [PATCH 09/15] Fix last lints --- synapse/logging/opentracing.py | 8 +++++--- synapse/storage/databases/main/event_federation.py | 1 - 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 0613f249f2ec..bc55a88a6808 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -910,7 +910,8 @@ def trace_with_opname( See the module's doc string for usage examples. """ - @contextlib.contextmanager + # mypy bug: https://github.com/python/mypy/issues/12909 + @contextlib.contextmanager # type: ignore[arg-type] def _wrapping_logic( func: Callable[P, R], *args: P.args, **kwargs: P.kwargs ) -> Generator[None, None, None]: @@ -949,7 +950,8 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: if not opentracing: return func - @contextlib.contextmanager + # mypy bug: https://github.com/python/mypy/issues/12909 + @contextlib.contextmanager # type: ignore[arg-type] def _wrapping_logic( func: Callable[P, R], *args: P.args, **kwargs: P.kwargs ) -> Generator[None, None, None]: @@ -957,7 +959,7 @@ def _wrapping_logic( # We use `[1:]` to skip the `self` object reference and `start=1` to # make the index line up with `argspec.args`. # - # FIXME: We could update this handle any type of function by ignoring the + # FIXME: We could update this to handle any type of function by ignoring the # first argument only if it's named `self` or `cls`. This isn't fool-proof # but handles the idiomatic cases. for i, arg in enumerate(args[1:], start=1): # type: ignore[index] diff --git a/synapse/storage/databases/main/event_federation.py b/synapse/storage/databases/main/event_federation.py index 3209df89f3cc..eec55b647857 100644 --- a/synapse/storage/databases/main/event_federation.py +++ b/synapse/storage/databases/main/event_federation.py @@ -33,7 +33,6 @@ from synapse.api.errors import StoreError from synapse.api.room_versions import EventFormatVersions, RoomVersion from synapse.events import EventBase, make_event_from_dict -from synapse.logging.opentracing import tag_args, trace from synapse.metrics.background_process_metrics import wrap_as_background_process from synapse.storage._base import SQLBaseStore, db_to_json, make_in_list_sql_clause from synapse.storage.database import ( From dd5f966c44102f2aa80fbdb1ffb014dcd1fd0142 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 12:47:42 -0500 Subject: [PATCH 10/15] Decorate is the function See https://github.com/matrix-org/synapse/pull/13453#discussion_r938695371 --- synapse/logging/opentracing.py | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index bc55a88a6808..b8e6268ca37f 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -824,13 +824,14 @@ def extract_text_map(carrier: Dict[str, str]) -> Optional["opentracing.SpanConte # Tracing decorators -def _create_decorator( +def _decorate( func: Callable[P, R], wrapping_logic: Callable[[Callable[P, R], Any, Any], ContextManager[None]], ) -> Callable[P, R]: """ - Creates a decorator that is able to handle sync functions, async functions + Decorates a function that is able to handle sync functions, async functions (coroutines), and inlineDeferred from Twisted. + Example usage: ```py # Decorator to time the function and log it out @@ -842,8 +843,9 @@ def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs) -> end_ts = time.time() duration = end_ts - start_ts logger.info("%s took %s seconds", func.__name__, duration) - return _create_decorator(func, _wrapping_logic) + return _decorate(func, _wrapping_logic) ``` + Args: func: The function to be decorated wrapping_logic: The business logic of your custom decorator. @@ -922,7 +924,7 @@ def _decorator(func: Callable[P, R]) -> Callable[P, R]: if not opentracing: return func - return _create_decorator(func, _wrapping_logic) + return _decorate(func, _wrapping_logic) return _decorator @@ -968,7 +970,7 @@ def _wrapping_logic( set_tag("kwargs", str(kwargs)) yield - return _create_decorator(func, _wrapping_logic) + return _decorate(func, _wrapping_logic) @contextlib.contextmanager From 2ef4cf450620f2ca236718165e20007095d2faec Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 12:50:32 -0500 Subject: [PATCH 11/15] Other new comment --- synapse/logging/opentracing.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index b8e6268ca37f..b0bd924e226b 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -912,7 +912,7 @@ def trace_with_opname( See the module's doc string for usage examples. """ - # mypy bug: https://github.com/python/mypy/issues/12909 + # type-ignore: mypy bug, see https://github.com/python/mypy/issues/12909 @contextlib.contextmanager # type: ignore[arg-type] def _wrapping_logic( func: Callable[P, R], *args: P.args, **kwargs: P.kwargs @@ -952,7 +952,7 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: if not opentracing: return func - # mypy bug: https://github.com/python/mypy/issues/12909 + # type-ignore: mypy bug, see https://github.com/python/mypy/issues/12909 @contextlib.contextmanager # type: ignore[arg-type] def _wrapping_logic( func: Callable[P, R], *args: P.args, **kwargs: P.kwargs From f3273054bf17e4119d08da640cecdafb0efa15ef Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 13:52:53 -0500 Subject: [PATCH 12/15] Fix weird mismash commentdoc Co-authored-by: Sean Quah <8349537+squahtx@users.noreply.github.com> --- synapse/logging/opentracing.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index b0bd924e226b..328ef2513fe3 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -829,8 +829,8 @@ def _decorate( wrapping_logic: Callable[[Callable[P, R], Any, Any], ContextManager[None]], ) -> Callable[P, R]: """ - Decorates a function that is able to handle sync functions, async functions - (coroutines), and inlineDeferred from Twisted. + Decorates a function that is sync or async (coroutines), or that returns a Twisted + `Deferred`. Example usage: ```py From 513b57552a48f2c9ffeab68ebf4e46ae2adc0f74 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 13:53:48 -0500 Subject: [PATCH 13/15] More robust example See https://github.com/matrix-org/synapse/pull/13453#discussion_r939054578 --- synapse/logging/opentracing.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 328ef2513fe3..e16213b39971 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -839,10 +839,12 @@ def duration(func: Callable[P, R]) -> Callable[P, R]: @contextlib.contextmanager def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs) -> Generator[None, None, None]: start_ts = time.time() - yield - end_ts = time.time() - duration = end_ts - start_ts - logger.info("%s took %s seconds", func.__name__, duration) + try: + yield + finally: + end_ts = time.time() + duration = end_ts - start_ts + logger.info("%s took %s seconds", func.__name__, duration) return _decorate(func, _wrapping_logic) ``` From 7b62d48e2686c06ea7595c14330f3ebc555581f3 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 14:05:38 -0500 Subject: [PATCH 14/15] Add a descriptor to the name See https://github.com/matrix-org/synapse/pull/13453#discussion_r939070135 --- synapse/logging/opentracing.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index e16213b39971..d1fa2cf8ae67 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -824,13 +824,13 @@ def extract_text_map(carrier: Dict[str, str]) -> Optional["opentracing.SpanConte # Tracing decorators -def _decorate( +def _custom_sync_async_decorator( func: Callable[P, R], wrapping_logic: Callable[[Callable[P, R], Any, Any], ContextManager[None]], ) -> Callable[P, R]: """ Decorates a function that is sync or async (coroutines), or that returns a Twisted - `Deferred`. + `Deferred`. The custom business logic of the decorator goes in `wrapping_logic`. Example usage: ```py @@ -845,7 +845,7 @@ def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs) -> end_ts = time.time() duration = end_ts - start_ts logger.info("%s took %s seconds", func.__name__, duration) - return _decorate(func, _wrapping_logic) + return _custom_sync_async_decorator(func, _wrapping_logic) ``` Args: @@ -926,7 +926,7 @@ def _decorator(func: Callable[P, R]) -> Callable[P, R]: if not opentracing: return func - return _decorate(func, _wrapping_logic) + return _custom_sync_async_decorator(func, _wrapping_logic) return _decorator @@ -972,7 +972,7 @@ def _wrapping_logic( set_tag("kwargs", str(kwargs)) yield - return _decorate(func, _wrapping_logic) + return _custom_sync_async_decorator(func, _wrapping_logic) @contextlib.contextmanager From 2f77b13a6d537ccbfaf4229f963ba0bad0cf14c8 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Aug 2022 14:50:12 -0500 Subject: [PATCH 15/15] Fix deferred type lint in old deps See https://github.com/matrix-org/synapse/pull/13453#discussion_r939169472 --- tests/logging/test_opentracing.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/logging/test_opentracing.py b/tests/logging/test_opentracing.py index 2f94d166a412..0917e478a5b0 100644 --- a/tests/logging/test_opentracing.py +++ b/tests/logging/test_opentracing.py @@ -233,7 +233,7 @@ def test_trace_decorator_deferred(self) -> None: @trace_with_opname("fixture_deferred_func", tracer=self._tracer) @tag_args - def fixture_deferred_func() -> defer.Deferred[str]: + def fixture_deferred_func() -> "defer.Deferred[str]": d1: defer.Deferred[str] = defer.Deferred() d1.callback("foo") return d1