From 948090f773184e6c1a0b020ee8355bc7f979a893 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 3 Aug 2022 20:52:31 -0500 Subject: [PATCH 1/7] Fix @tag_args being off-by-one (ahead) Example: ``` argspec.args=[ 'self', 'room_id' ] args=( , '!HBehERstyQBxyJDLfR:my.synapse.server' ) ``` --- synapse/logging/opentracing.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index c1aa205eedde..ea9e5db78a1f 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -909,8 +909,9 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: @wraps(func) def _tag_args_inner(*args: P.args, **kwargs: P.kwargs) -> R: argspec = inspect.getfullargspec(func) + # We use `[1:]` to skip the `self` object reference for i, arg in enumerate(argspec.args[1:]): - set_tag("ARG_" + arg, str(args[i])) # type: ignore[index] + set_tag("ARG_" + arg, str(args[i + 1])) # type: ignore[index] set_tag("args", str(args[len(argspec.args) :])) # type: ignore[index] set_tag("kwargs", str(kwargs)) return func(*args, **kwargs) From a988d5fcc6a5eefab91ffe3ae701b432d36044f3 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 3 Aug 2022 21:00:52 -0500 Subject: [PATCH 2/7] Add changelog --- changelog.d/13452.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/13452.misc diff --git a/changelog.d/13452.misc b/changelog.d/13452.misc new file mode 100644 index 000000000000..13d1523de2aa --- /dev/null +++ b/changelog.d/13452.misc @@ -0,0 +1 @@ +Fix `@tag_args` being off-by-one with the arguments when tagging a span (tracing). From 97ad363d75803a8812e87a001d457f31f623d3aa Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 01:27:47 -0500 Subject: [PATCH 3/7] Fix flawed logic iterating of args See https://github.com/matrix-org/synapse/pull/13452#discussion_r937392286 The previous logic is flawed and we can end up in a situation like this: ``` argspec.args=['self', 'dest', 'room_id', 'limit', 'extremities'] args=(, 'hs1', '!jAEHKIubyIfuLOdfpY:hs1') ``` From this source: ```py async def backfill( self, dest: str, room_id: str, limit: int, extremities: Collection[str] ) -> Optional[List[EventBase]]: ``` And this usage: ```py events = await self._federation_client.backfill( dest, room_id, limit=limit, extremities=extremities ) ``` Causes this error: ``` synapse_main | 2022-08-04 06:13:12,051 - synapse.handlers.federation - 424 - ERROR - GET-5 - Failed to backfill from hs1 because tuple index out of range synapse_main | Traceback (most recent call last): synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 392, in try_backfill synapse_main | await self._federation_event_handler.backfill( synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper synapse_main | return await func(*args, **kwargs) synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 593, in backfill synapse_main | events = await self._federation_client.backfill( synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper synapse_main | return await func(*args, **kwargs) synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 827, in _wrapper synapse_main | with wrapping_logic(func, *args, **kwargs): synapse_main | File "/usr/local/lib/python3.9/contextlib.py", line 119, in __enter__ synapse_main | return next(self.gen) synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 922, in _wrapping_logic synapse_main | set_attribute("ARG_" + arg, str(args[i + 1])) # type: ignore[index] synapse_main | IndexError: tuple index out of range ``` --- 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 ea9e5db78a1f..119022009c4a 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -910,8 +910,8 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: def _tag_args_inner(*args: P.args, **kwargs: P.kwargs) -> R: argspec = inspect.getfullargspec(func) # We use `[1:]` to skip the `self` object reference - for i, arg in enumerate(argspec.args[1:]): - set_tag("ARG_" + arg, str(args[i + 1])) # type: ignore[index] + for i, arg in enumerate(args[1:]): + set_tag("ARG_" + argspec.args[i + 1], str(arg)) # type: ignore[index] set_tag("args", str(args[len(argspec.args) :])) # type: ignore[index] set_tag("kwargs", str(kwargs)) return func(*args, **kwargs) From 7e34d6d385979a1192f888e18d56e039cbaf5544 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 11:25:44 -0500 Subject: [PATCH 4/7] Align indexes See https://github.com/matrix-org/synapse/pull/13452#discussion_r937628146 --- synapse/logging/opentracing.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 119022009c4a..8ba4e3a9e559 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -909,9 +909,10 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: @wraps(func) def _tag_args_inner(*args: P.args, **kwargs: P.kwargs) -> R: argspec = inspect.getfullargspec(func) - # We use `[1:]` to skip the `self` object reference - for i, arg in enumerate(args[1:]): - set_tag("ARG_" + argspec.args[i + 1], str(arg)) # type: ignore[index] + # We use `[1:]` to skip the `self` object reference and `start=1` to + # make the index line up with `argspec.args`. + for i, arg in enumerate(args[1:], start=1): + set_tag("ARG_" + argspec.args[i], str(arg)) # type: ignore[index] set_tag("args", str(args[len(argspec.args) :])) # type: ignore[index] set_tag("kwargs", str(kwargs)) return func(*args, **kwargs) From 7dcf6f7b2a968aa18528d6b3acaf3b52563e8949 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 11:30:17 -0500 Subject: [PATCH 5/7] Note caveat on the kind of function we expect to tag See https://github.com/matrix-org/synapse/pull/13452#discussion_r937641628 --- synapse/logging/opentracing.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 8ba4e3a9e559..31b1f9e855e3 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -901,6 +901,11 @@ 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. + + Args: + func: `func` is assumed to be a method taking a `self` parameter, or a + `classmethod` taking a `cls` parameter. In either case, a tag is not created + for this parameter. """ if not opentracing: From 3389a23e97f8e53e58c089a0ac36aab68a54fd10 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 11:36:04 -0500 Subject: [PATCH 6/7] Fix lints --- 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 31b1f9e855e3..4cd80fccf490 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -903,9 +903,9 @@ def tag_args(func: Callable[P, R]) -> Callable[P, R]: Tags all of the args to the active span. Args: - func: `func` is assumed to be a method taking a `self` parameter, or a - `classmethod` taking a `cls` parameter. In either case, a tag is not created - for this parameter. + func: `func` is assumed to be a method taking a `self` parameter, or a + `classmethod` taking a `cls` parameter. In either case, a tag is not + created for this parameter. """ if not opentracing: @@ -916,8 +916,8 @@ def _tag_args_inner(*args: P.args, **kwargs: P.kwargs) -> R: 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`. - for i, arg in enumerate(args[1:], start=1): - set_tag("ARG_" + argspec.args[i], str(arg)) # type: ignore[index] + for i, arg in enumerate(args[1:], start=1): # type: ignore[index] + set_tag("ARG_" + argspec.args[i], str(arg)) set_tag("args", str(args[len(argspec.args) :])) # type: ignore[index] set_tag("kwargs", str(kwargs)) return func(*args, **kwargs) From 41526131a0b47b9f2d060a65a3bd41f5db217e7a Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 4 Aug 2022 11:54:07 -0500 Subject: [PATCH 7/7] Document potential future upgrades See https://github.com/matrix-org/synapse/pull/13452#discussion_r938025341 --- synapse/logging/opentracing.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 4cd80fccf490..fa3f76c27ff9 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -916,6 +916,10 @@ def _tag_args_inner(*args: P.args, **kwargs: P.kwargs) -> R: 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`. + # + # FIXME: We could update this 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] set_tag("ARG_" + argspec.args[i], str(arg)) set_tag("args", str(args[len(argspec.args) :])) # type: ignore[index]