feat(logger): new stack_trace field with rich exception details (#3147)

Co-authored-by: Leandro Damascena <[email protected]>

Author: stevrobu

.gitignore

@@ -252,6 +252,7 @@ dmypy.json
 .pyre/
 
 ### VisualStudioCode ###
+.vscode
 .vscode/*
 !.vscode/tasks.json
 !.vscode/launch.json

aws_lambda_powertools/logging/formatter.py

@@ -5,12 +5,13 @@
 import logging
 import os
 import time
+import traceback
 from abc import ABCMeta, abstractmethod
 from datetime import datetime, timezone
 from functools import partial
 from typing import Any, Callable, Dict, Iterable, List, Optional, Tuple, Union
 
-from aws_lambda_powertools.logging.types import LogRecord
+from aws_lambda_powertools.logging.types import LogRecord, LogStackTrace
 from aws_lambda_powertools.shared import constants
 from aws_lambda_powertools.shared.functions import powertools_dev_is_set
 
@@ -77,6 +78,7 @@ def __init__(
         log_record_order: List[str] | None = None,
         utc: bool = False,
         use_rfc3339: bool = False,
+        serialize_stacktrace: bool = True,
         **kwargs,
     ) -> None:
         """Return a LambdaPowertoolsFormatter instance.
@@ -148,6 +150,8 @@ def __init__(
         self.keys_combined = {**self._build_default_keys(), **kwargs}
         self.log_format.update(**self.keys_combined)
 
+        self.serialize_stacktrace = serialize_stacktrace
+
         super().__init__(datefmt=self.datefmt)
 
     def serialize(self, log: LogRecord) -> str:
@@ -158,11 +162,15 @@ def format(self, record: logging.LogRecord) -> str:  # noqa: A003
         """Format logging record as structured JSON str"""
         formatted_log = self._extract_log_keys(log_record=record)
         formatted_log["message"] = self._extract_log_message(log_record=record)
+
         # exception and exception_name fields can be added as extra key
         # in any log level, we try to extract and use them first
         extracted_exception, extracted_exception_name = self._extract_log_exception(log_record=record)
         formatted_log["exception"] = formatted_log.get("exception", extracted_exception)
         formatted_log["exception_name"] = formatted_log.get("exception_name", extracted_exception_name)
+        if self.serialize_stacktrace:
+            # Generate the traceback from the traceback library
+            formatted_log["stack_trace"] = self._serialize_stacktrace(log_record=record)
         formatted_log["xray_trace_id"] = self._get_latest_trace_id()
         formatted_log = self._strip_none_records(records=formatted_log)
 
@@ -273,6 +281,24 @@ def _extract_log_message(self, log_record: logging.LogRecord) -> Union[Dict[str,
 
         return message
 
+    def _serialize_stacktrace(self, log_record: logging.LogRecord) -> LogStackTrace | None:
+        if log_record.exc_info:
+            exception_info: LogStackTrace = {
+                "type": log_record.exc_info[0].__name__,  # type: ignore
+                "value": log_record.exc_info[1],  # type: ignore
+                "module": log_record.exc_info[1].__class__.__module__,
+                "frames": [],
+            }
+
+            exception_info["frames"] = [
+                {"file": fs.filename, "line": fs.lineno, "function": fs.name, "statement": fs.line}
+                for fs in traceback.extract_tb(log_record.exc_info[2])
+            ]
+
+            return exception_info
+
+        return None
+
     def _extract_log_exception(self, log_record: logging.LogRecord) -> Union[Tuple[str, str], Tuple[None, None]]:
         """Format traceback information, if available
 

aws_lambda_powertools/logging/logger.py

@@ -220,6 +220,7 @@ def __init__(
         log_record_order: Optional[List[str]] = None,
         utc: bool = False,
         use_rfc3339: bool = False,
+        serialize_stacktrace: bool = True,
         **kwargs,
     ) -> None:
         self.service = resolve_env_var_choice(
@@ -253,6 +254,7 @@ def __init__(
             "log_record_order": log_record_order,
             "utc": utc,
             "use_rfc3339": use_rfc3339,
+            "serialize_stacktrace": serialize_stacktrace,
         }
 
         self._init_logger(formatter_options=formatter_options, log_level=level, **kwargs)

aws_lambda_powertools/logging/types.py

@@ -5,6 +5,7 @@
 from aws_lambda_powertools.shared.types import NotRequired, TypeAlias, TypedDict
 
 LogRecord: TypeAlias = Union[Dict[str, Any], "PowertoolsLogRecord"]
+LogStackTrace: TypeAlias = Union[Dict[str, Any], "PowertoolsStackTrace"]
 
 
 class PowertoolsLogRecord(TypedDict):
@@ -33,3 +34,11 @@ class PowertoolsLogRecord(TypedDict):
     # Fields from logger.exception
     exception_name: NotRequired[str]
     exception: NotRequired[str]
+    stack_trace: NotRequired[Dict[str, Any]]
+
+
+class PowertoolsStackTrace(TypedDict):
+    type: str
+    value: str
+    module: str
+    frames: List[Dict[str, Any]]

docs/contributing/documentation/rfcs.md

@@ -3,6 +3,8 @@ title: Writing Request For Comment (RFC)
 description: Contributing RFCs to Powertools for AWS Lambda (Python)
 ---
 
+<!-- markdownlint-disable MD043 -->
+
 ## TBW
 
 Something great will come.

docs/core/logger.md

@@ -319,6 +319,22 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception
     --8<-- "examples/logger/src/logging_uncaught_exceptions_output.json"
     ```
 
+#### Stack trace logging
+
+By default, the Logger will automatically include the full stack trace in JSON format when using `logger.exception`. If you want to disable this feature, set `serialize_stacktrace=False` during initialization."
+
+=== "logging_stacktrace.py"
+
+    ```python hl_lines="7 15"
+    --8<-- "examples/logger/src/logging_stacktrace.py"
+    ```
+
+=== "logging_stacktrace_output.json"
+
+    ```json hl_lines="9-27"
+    --8<-- "examples/logger/src/logging_stacktrace_output.json"
+    ```
+
 ### Date formatting
 
 Logger uses Python's standard logging date format with the addition of timezone: `2021-05-03 11:47:12,494+0200`.

examples/logger/src/logging_stacktrace.py

@@ -0,0 +1,18 @@
+import requests
+
+from aws_lambda_powertools import Logger
+from aws_lambda_powertools.utilities.typing import LambdaContext
+
+ENDPOINT = "http://httpbin.org/status/500"
+logger = Logger(serialize_stacktrace=True)
+
+
+def lambda_handler(event: dict, context: LambdaContext) -> str:
+    try:
+        ret = requests.get(ENDPOINT)
+        ret.raise_for_status()
+    except requests.HTTPError as e:
+        logger.exception(e)
+        raise RuntimeError("Unable to fullfil request") from e
+
+    return "hello world"

examples/logger/src/logging_stacktrace_output.json

@@ -0,0 +1,28 @@
+{
+    "level":"ERROR",
+    "location":"lambda_handler:16",
+    "message":"500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500",
+    "timestamp":"2023-10-09 17:47:50,191+0000",
+    "service":"service_undefined",
+    "exception":"Traceback (most recent call last):\n  File \"/var/task/app.py\", line 14, in lambda_handler\n    ret.raise_for_status()\n  File \"/var/task/requests/models.py\", line 1021, in raise_for_status\n    raise HTTPError(http_error_msg, response=self)\nrequests.exceptions.HTTPError: 500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500",
+    "exception_name":"HTTPError",
+    "stack_trace":{
+       "type":"HTTPError",
+       "value":"500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500",
+       "module":"requests.exceptions",
+       "frames":[
+          {
+             "file":"/var/task/app.py",
+             "line":14,
+             "function":"lambda_handler",
+             "statement":"ret.raise_for_status()"
+          },
+          {
+             "file":"/var/task/requests/models.py",
+             "line":1021,
+             "function":"raise_for_status",
+             "statement":"raise HTTPError(http_error_msg, response=self)"
+          }
+       ]
+    }
+ }

tests/functional/test_logger.py

@@ -959,3 +959,37 @@ def test_stream_defaults_to_stdout(service_name, capsys):
     # NOTE: we can't assert on capsys.readouterr().err due to a known bug: https://github.com/pytest-dev/pytest/issues/5997
     log = json.loads(capsys.readouterr().out.strip())
     assert log["message"] == msg
+
+
+def test_logger_logs_stack_trace_with_default_value(service_name, stdout):
+    # GIVEN a Logger instance with serialize_stacktrace default value = True
+    logger = Logger(service=service_name, stream=stdout)
+
+    # WHEN invoking a Lambda
+    def handler(event, context):
+        try:
+            raise ValueError("something went wrong")
+        except Exception:
+            logger.exception("Received an exception")
+
+    # THEN we expect a "stack_trace" in log
+    handler({}, lambda_context)
+    log = capture_logging_output(stdout)
+    assert "stack_trace" in log
+
+
+def test_logger_logs_stack_trace_with_non_default_value(service_name, stdout):
+    # GIVEN a Logger instance with serialize_stacktrace = False
+    logger = Logger(service=service_name, stream=stdout, serialize_stacktrace=False)
+
+    # WHEN invoking a Lambda
+    def handler(event, context):
+        try:
+            raise ValueError("something went wrong")
+        except Exception:
+            logger.exception("Received an exception")
+
+    # THEN we expect a "stack_trace" not in log
+    handler({}, lambda_context)
+    log = capture_logging_output(stdout)
+    assert "stack_trace" not in log

tests/functional/test_logger_powertools_formatter.py

@@ -6,13 +6,27 @@
 import re
 import string
 import time
+from collections import namedtuple
 
 import pytest
 
 from aws_lambda_powertools import Logger
+from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter
 from aws_lambda_powertools.logging.formatters.datadog import DatadogLogFormatter
 
 
+@pytest.fixture
+def lambda_context():
+    lambda_context = {
+        "function_name": "test",
+        "memory_limit_in_mb": 128,
+        "invoked_function_arn": "arn:aws:lambda:eu-west-1:809313241:function:test",
+        "aws_request_id": "52fdfc07-2182-154f-163f-5f0f9a621d72",
+    }
+
+    return namedtuple("LambdaContext", lambda_context.keys())(*lambda_context.values())
+
+
 @pytest.fixture
 def stdout():
     return io.StringIO()
@@ -350,3 +364,42 @@ def test_datadog_formatter_use_rfc3339_date(stdout, service_name):
     log = capture_logging_output(stdout)
 
     assert re.fullmatch(RFC3339_REGEX, log["timestamp"])  # "2022-10-27T17:42:26.841+0200"
+
+
+def test_logger_logs_stack_trace_with_formatter_default_value(service_name, stdout):
+    # GIVEN a Logger instance with LambdaPowertoolsFormatter set explictly
+    # GIVE serialize_stacktrace default value = True
+    logger = Logger(service=service_name, stream=stdout, logger_formatter=LambdaPowertoolsFormatter())
+
+    # WHEN invoking a Lambda
+    def handler(event, context):
+        try:
+            raise ValueError("something went wrong")
+        except Exception:
+            logger.exception("Received an exception")
+
+    # THEN we expect a "stack_trace" in log
+    handler({}, lambda_context)
+    log = capture_logging_output(stdout)
+    assert "stack_trace" in log
+
+
+def test_logger_logs_stack_trace_with_formatter_non_default_value(service_name, stdout):
+    # GIVEN a Logger instance with serialize_stacktrace = False
+    logger = Logger(
+        service=service_name,
+        stream=stdout,
+        logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False),
+    )
+
+    # WHEN invoking a Lambda
+    def handler(event, context):
+        try:
+            raise ValueError("something went wrong")
+        except Exception:
+            logger.exception("Received an exception")
+
+    # THEN we expect a "stack_trace" not in log
+    handler({}, lambda_context)
+    log = capture_logging_output(stdout)
+    assert "stack_trace" not in log