bugfix: #32 Runtime Error for nested sync fns

Author: heitorlessa

python/CHANGELOG.md

@@ -1,5 +1,11 @@
 # HISTORY 
 
+## May 16th
+
+**0.9.3**
+
+* **Tracer**: Bugfix - Runtime Error for nested sync due to incorrect loop usage
+
 ## May 14th
 
 **0.9.2**

python/aws_lambda_powertools/tracing/tracer.py

@@ -1,4 +1,3 @@
-import asyncio
 import copy
 import functools
 import inspect
@@ -250,10 +249,11 @@ def handler(event, context)
         err
             Exception raised by method
         """
+        lambda_handler_name = lambda_handler.__name__
 
         @functools.wraps(lambda_handler)
         def decorate(event, context):
-            with self.provider.in_subsegment(name=f"## {lambda_handler.__name__}") as subsegment:
+            with self.provider.in_subsegment(name=f"## {lambda_handler_name}") as subsegment:
                 global is_cold_start
                 if is_cold_start:
                     logger.debug("Annotating cold start")
@@ -265,13 +265,12 @@ def decorate(event, context):
                     response = lambda_handler(event, context)
                     logger.debug("Received lambda handler response successfully")
                     logger.debug(response)
-                    if response:
-                        subsegment.put_metadata(
-                            key="lambda handler response", value=response, namespace=self._config["service"]
-                        )
+                    self._add_response_as_metadata(
+                        function_name=lambda_handler_name, data=response, subsegment=subsegment
+                    )
                 except Exception as err:
-                    logger.exception("Exception received from lambda handler", exc_info=True)
-                    subsegment.put_metadata(key=f"{self.service} error", value=err, namespace=self._config["service"])
+                    logger.exception("Exception received from lambda handler")
+                    self._add_full_exception_as_metadata(function_name=self.service, error=err, subsegment=subsegment)
                     raise
 
                 return response
@@ -392,71 +391,79 @@ async def async_tasks():
         """
         method_name = f"{method.__name__}"
 
-        async def decorate_logic(
-            decorated_method_with_args: functools.partial = None,
-            subsegment: aws_xray_sdk.core.models.subsegment = None,
-            coroutine: bool = False,
-        ) -> Any:
-            """Decorate logic runs both sync and async decorated methods
-
-            Parameters
-            ----------
-            decorated_method_with_args : functools.partial
-                Partial decorated method with arguments/keyword arguments
-            subsegment : aws_xray_sdk.core.models.subsegment
-                X-Ray subsegment to reuse
-            coroutine : bool, optional
-                Instruct whether partial decorated method is a wrapped coroutine, by default False
-
-            Returns
-            -------
-            Any
-                Returns method's response
-            """
-            response = None
-            try:
-                logger.debug(f"Calling method: {method_name}")
-                if coroutine:
-                    response = await decorated_method_with_args()
-                else:
-                    response = decorated_method_with_args()
-                    logger.debug(f"Received {method_name} response successfully")
-                    logger.debug(response)
-            except Exception as err:
-                logger.exception(f"Exception received from '{method_name}' method", exc_info=True)
-                subsegment.put_metadata(key=f"{method_name} error", value=err, namespace=self._config["service"])
-                raise
-            finally:
-                if response is not None:
-                    subsegment.put_metadata(  # pragma: no cover
-                        key=f"{method_name} response", value=response, namespace=self._config["service"]
-                    )
-
-            return response
-
         if inspect.iscoroutinefunction(method):
 
             @functools.wraps(method)
             async def decorate(*args, **kwargs):
-                decorated_method_with_args = functools.partial(method, *args, **kwargs)
                 async with self.provider.in_subsegment_async(name=f"## {method_name}") as subsegment:
-                    return await decorate_logic(
-                        decorated_method_with_args=decorated_method_with_args, subsegment=subsegment, coroutine=True
-                    )
+                    try:
+                        logger.debug(f"Calling method: {method_name}")
+                        response = await method(*args, **kwargs)
+                        self._add_response_as_metadata(function_name=method_name, data=response, subsegment=subsegment)
+                    except Exception as err:
+                        logger.exception(f"Exception received from '{method_name}' method")
+                        self._add_full_exception_as_metadata(
+                            function_name=method_name, error=err, subsegment=subsegment
+                        )
+                        raise
+
+                    return response
 
         else:
 
             @functools.wraps(method)
             def decorate(*args, **kwargs):
-                loop = asyncio.get_event_loop()
-                decorated_method_with_args = functools.partial(method, *args, **kwargs)
                 with self.provider.in_subsegment(name=f"## {method_name}") as subsegment:
-                    return loop.run_until_complete(
-                        decorate_logic(decorated_method_with_args=decorated_method_with_args, subsegment=subsegment)
-                    )
+                    try:
+                        logger.debug(f"Calling method: {method_name}")
+                        response = method(*args, **kwargs)
+                        self._add_response_as_metadata(function_name=method_name, data=response, subsegment=subsegment)
+                    except Exception as err:
+                        logger.exception(f"Exception received from '{method_name}' method")
+                        self._add_full_exception_as_metadata(
+                            function_name=method_name, error=err, subsegment=subsegment
+                        )
+                        raise
+
+                    return response
 
         return decorate
 
+    def _add_response_as_metadata(
+        self, function_name: str = None, data: Any = None, subsegment: aws_xray_sdk.core.models.subsegment = None
+    ):
+        """Add response as metadata for given subsegment
+
+        Parameters
+        ----------
+        function_name : str, optional
+            function name to add as metadata key, by default None
+        data : Any, optional
+            data to add as subsegment metadata, by default None
+        subsegment : aws_xray_sdk.core.models.subsegment, optional
+            existing subsegment to add metadata on, by default None
+        """
+        if data is None or subsegment is None:
+            return
+
+        subsegment.put_metadata(key=f"{function_name} response", value=data, namespace=self._config["service"])
+
+    def _add_full_exception_as_metadata(
+        self, function_name: str = None, error: Exception = None, subsegment: aws_xray_sdk.core.models.subsegment = None
+    ):
+        """Add full exception object as metadata for given subsegment
+
+        Parameters
+        ----------
+        function_name : str, optional
+            function name to add as metadata key, by default None
+        error : Exception, optional
+            error to add as subsegment metadata, by default None
+        subsegment : aws_xray_sdk.core.models.subsegment, optional
+            existing subsegment to add metadata on, by default None
+        """
+        subsegment.put_metadata(key=f"{function_name} error", value=error, namespace=self._config["service"])
+
     def __disable_tracing_provider(self):
         """Forcefully disables tracing"""
         logger.debug("Disabling tracer provider...")

python/example/hello_world/app.py

@@ -59,6 +59,21 @@ def my_middleware(handler, event, context, say_hello=False):
     return ret
 
 
+@tracer.capture_method
+def func_1():
+    return 1
+
+
+@tracer.capture_method
+def func_2():
+    return 2
+
+
+@tracer.capture_method
+def sums_values():
+    return func_1() + func_2()  # nested sync calls to reproduce issue #32
+
+
 @metrics.log_metrics
 @tracer.capture_lambda_handler
 @my_middleware(say_hello=True)
@@ -84,7 +99,7 @@ def lambda_handler(event, context):
 
         Return doc: https://docs.aws.amazon.com/apigateway/latest/developerguide/set-up-lambda-proxy-integrations.html
     """
-
+    sums_values()
     async_http_ret = asyncio.run(async_tasks())
 
     if "charge_id" in event:

python/pyproject.toml

@@ -1,6 +1,6 @@
 [tool.poetry]
 name = "aws_lambda_powertools"
-version = "0.9.2"
+version = "0.9.3"
 description = "Python utilities for AWS Lambda functions including but not limited to tracing, logging and custom metric"
 authors = ["Amazon Web Services"]
 classifiers=[

python/tests/functional/test_tracing.py

@@ -124,3 +124,24 @@ def test_tracer_reuse():
 
     assert id(tracer_a) != id(tracer_b)
     assert tracer_a.__dict__.items() == tracer_b.__dict__.items()
+
+
+def test_tracer_method_nested_sync(mocker):
+    # GIVEN tracer is disabled, decorator is used
+    # WHEN multiple sync functions are nested
+    # THEN tracer should not raise a Runtime Error
+    tracer = Tracer(disabled=True)
+
+    @tracer.capture_method
+    def func_1():
+        return 1
+
+    @tracer.capture_method
+    def func_2():
+        return 2
+
+    @tracer.capture_method
+    def sums_values():
+        return func_1() + func_2()
+
+    sums_values()

python/tests/unit/test_tracing.py

@@ -91,7 +91,7 @@ def handler(event, context):
     assert in_subsegment_mock.in_subsegment.call_count == 1
     assert in_subsegment_mock.in_subsegment.call_args == mocker.call(name="## handler")
     assert in_subsegment_mock.put_metadata.call_args == mocker.call(
-        key="lambda handler response", value=dummy_response, namespace="booking"
+        key="handler response", value=dummy_response, namespace="booking"
     )
     assert in_subsegment_mock.put_annotation.call_count == 1
     assert in_subsegment_mock.put_annotation.call_args == mocker.call(key="ColdStart", value=True)