diff --git a/.gitignore b/.gitignore index a69b4eaf618..2a814459161 100644 --- a/.gitignore +++ b/.gitignore @@ -252,6 +252,7 @@ dmypy.json .pyre/ ### VisualStudioCode ### +.vscode .vscode/* !.vscode/tasks.json !.vscode/launch.json diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index cf0a7598051..c52fe90893f 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/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 diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 45f8bc80721..28d899d25e5 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/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) diff --git a/aws_lambda_powertools/logging/types.py b/aws_lambda_powertools/logging/types.py index d166b2e023c..eb2b39afe69 100644 --- a/aws_lambda_powertools/logging/types.py +++ b/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]] diff --git a/docs/contributing/documentation/rfcs.md b/docs/contributing/documentation/rfcs.md index 6d344daceea..4a9f925adbb 100644 --- a/docs/contributing/documentation/rfcs.md +++ b/docs/contributing/documentation/rfcs.md @@ -3,6 +3,8 @@ title: Writing Request For Comment (RFC) description: Contributing RFCs to Powertools for AWS Lambda (Python) --- + + ## TBW Something great will come. diff --git a/docs/core/logger.md b/docs/core/logger.md index 6fc48e8898f..237f48c006f 100644 --- a/docs/core/logger.md +++ b/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`. diff --git a/examples/logger/src/logging_stacktrace.py b/examples/logger/src/logging_stacktrace.py new file mode 100644 index 00000000000..128836f5138 --- /dev/null +++ b/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" diff --git a/examples/logger/src/logging_stacktrace_output.json b/examples/logger/src/logging_stacktrace_output.json new file mode 100644 index 00000000000..d972f3ff6a9 --- /dev/null +++ b/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)" + } + ] + } + } diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index de589b9accc..47803b1e52d 100644 --- a/tests/functional/test_logger.py +++ b/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 diff --git a/tests/functional/test_logger_powertools_formatter.py b/tests/functional/test_logger_powertools_formatter.py index 61c3f76efd4..94e80850d2b 100644 --- a/tests/functional/test_logger_powertools_formatter.py +++ b/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