From 163b90819f4197f6428884d4567c1cf35db377c3 Mon Sep 17 00:00:00 2001 From: Steve Roberts Date: Tue, 26 Sep 2023 16:32:06 -0400 Subject: [PATCH 01/12] Added optional stack trace to exception logging. Issue 1268 --- aws_lambda_powertools/logging/formatter.py | 23 ++++++++++++++++++++++ aws_lambda_powertools/shared/constants.py | 2 ++ 2 files changed, 25 insertions(+) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index cf0a7598051..1824d6421ef 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -5,10 +5,14 @@ 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 ..shared.functions import ( + resolve_truthy_env_var_choice +) from aws_lambda_powertools.logging.types import LogRecord from aws_lambda_powertools.shared import constants @@ -77,6 +81,7 @@ def __init__( log_record_order: List[str] | None = None, utc: bool = False, use_rfc3339: bool = False, + include_traceback: bool = None, **kwargs, ) -> None: """Return a LambdaPowertoolsFormatter instance. @@ -148,16 +153,34 @@ def __init__( self.keys_combined = {**self._build_default_keys(), **kwargs} self.log_format.update(**self.keys_combined) + self.include_traceback = resolve_truthy_env_var_choice(env=os.getenv(constants.POWERTOOLS_TRACEBACK_ENV, "false"), + choice=include_traceback, + ) + super().__init__(datefmt=self.datefmt) def serialize(self, log: LogRecord) -> str: """Serialize structured log dict to JSON str""" return self.json_serializer(log) + + def serialize_traceback(self, e: Exception) -> list: + return [{"File": fs.filename, + "Line": fs.lineno, + "Column": fs.colno, + "Function": fs.name, + "Statement": fs.line + } for fs in traceback.extract_tb(e.__traceback__)] + 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) + + if self.include_traceback: + # Generate the traceback from the traceback library + formatted_log["stack_trace"] = self.serialize_traceback(record.msg) #JSR + # 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) diff --git a/aws_lambda_powertools/shared/constants.py b/aws_lambda_powertools/shared/constants.py index 20a7fbf47d2..711efd4d83f 100644 --- a/aws_lambda_powertools/shared/constants.py +++ b/aws_lambda_powertools/shared/constants.py @@ -42,3 +42,5 @@ POWERTOOLS_DEV_ENV: str = "POWERTOOLS_DEV" POWERTOOLS_DEBUG_ENV: str = "POWERTOOLS_DEBUG" + +POWERTOOLS_TRACEBACK_ENV: str = "POWERTOOLS_LOGGER_ENHANCED_TRACEBACK" \ No newline at end of file From 3ad3c764aed2e6328cce0bb6d393159622d95cfe Mon Sep 17 00:00:00 2001 From: Steve Roberts Date: Thu, 28 Sep 2023 16:12:08 -0400 Subject: [PATCH 02/12] Added tests and documentation --- examples/logger/src/logging_stacktrace.py | 19 ++++++++++++++ .../logger/src/logging_stacktrace_output.json | 26 +++++++++++++++++++ 2 files changed, 45 insertions(+) create mode 100644 examples/logger/src/logging_stacktrace.py create mode 100644 examples/logger/src/logging_stacktrace_output.json diff --git a/examples/logger/src/logging_stacktrace.py b/examples/logger/src/logging_stacktrace.py new file mode 100644 index 00000000000..8a547500a4f --- /dev/null +++ b/examples/logger/src/logging_stacktrace.py @@ -0,0 +1,19 @@ +import requests + +from aws_lambda_powertools import Logger +from aws_lambda_powertools.utilities.typing import LambdaContext +from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter + +ENDPOINT = "http://httpbin.org/status/500" +logger = Logger(logger_formatter=LambdaPowertoolsFormatter(include_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..6e64ac69981 --- /dev/null +++ b/examples/logger/src/logging_stacktrace_output.json @@ -0,0 +1,26 @@ +{ + "level": "ERROR", + "location": "lambda_handler:16", + "message": "500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500", + "timestamp": "2023-09-28 19:25:09,781+0000", + "service": "service_undefined", + "stack_trace": [ + { + "File": "/var/task/app.py", + "Line": 14, + "Column": 8, + "Function": "lambda_handler", + "Statement": "ret.raise_for_status()" + }, + { + "File": "/var/task/requests/models.py", + "Line": 1021, + "Column": 12, + "Function": "raise_for_status", + "Statement": "raise HTTPError(http_error_msg, response=self)" + } + ], + "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", + "xray_trace_id": "1-6515d315-07fbcb5e693988c6480a98e2" +} From 54363775d2f11cf26380b23915a8ac990f6150af Mon Sep 17 00:00:00 2001 From: Steve Roberts Date: Fri, 29 Sep 2023 09:30:56 -0400 Subject: [PATCH 03/12] Added tests and documentation. --- aws_lambda_powertools/logging/formatter.py | 18 +++---- aws_lambda_powertools/shared/constants.py | 2 +- docs/core/logger.md | 17 +++++++ docs/index.md | 1 + tests/functional/test_logger.py | 59 ++++++++++++++++++++++ 5 files changed, 87 insertions(+), 10 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 1824d6421ef..e1bb451ae6a 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -81,7 +81,7 @@ def __init__( log_record_order: List[str] | None = None, utc: bool = False, use_rfc3339: bool = False, - include_traceback: bool = None, + include_stacktrace: bool = None, **kwargs, ) -> None: """Return a LambdaPowertoolsFormatter instance. @@ -153,8 +153,8 @@ def __init__( self.keys_combined = {**self._build_default_keys(), **kwargs} self.log_format.update(**self.keys_combined) - self.include_traceback = resolve_truthy_env_var_choice(env=os.getenv(constants.POWERTOOLS_TRACEBACK_ENV, "false"), - choice=include_traceback, + self.include_stacktrace = resolve_truthy_env_var_choice(env=os.getenv(constants.POWERTOOLS_STACKTRACE_ENV, "false"), + choice=include_stacktrace, ) super().__init__(datefmt=self.datefmt) @@ -164,11 +164,11 @@ def serialize(self, log: LogRecord) -> str: return self.json_serializer(log) def serialize_traceback(self, e: Exception) -> list: - return [{"File": fs.filename, - "Line": fs.lineno, - "Column": fs.colno, - "Function": fs.name, - "Statement": fs.line + return [{"file": fs.filename, + "line": fs.lineno, + "column": fs.colno, + "function": fs.name, + "statement": fs.line } for fs in traceback.extract_tb(e.__traceback__)] @@ -177,7 +177,7 @@ def format(self, record: logging.LogRecord) -> str: # noqa: A003 formatted_log = self._extract_log_keys(log_record=record) formatted_log["message"] = self._extract_log_message(log_record=record) - if self.include_traceback: + if self.include_stacktrace: # Generate the traceback from the traceback library formatted_log["stack_trace"] = self.serialize_traceback(record.msg) #JSR diff --git a/aws_lambda_powertools/shared/constants.py b/aws_lambda_powertools/shared/constants.py index 711efd4d83f..00291f98744 100644 --- a/aws_lambda_powertools/shared/constants.py +++ b/aws_lambda_powertools/shared/constants.py @@ -43,4 +43,4 @@ POWERTOOLS_DEV_ENV: str = "POWERTOOLS_DEV" POWERTOOLS_DEBUG_ENV: str = "POWERTOOLS_DEBUG" -POWERTOOLS_TRACEBACK_ENV: str = "POWERTOOLS_LOGGER_ENHANCED_TRACEBACK" \ No newline at end of file +POWERTOOLS_STACKTRACE_ENV: str = "POWERTOOLS_LOGGER_ENHANCED_STACKTRACE" \ No newline at end of file diff --git a/docs/core/logger.md b/docs/core/logger.md index 6fc48e8898f..a10425c8e05 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 + +Logger can optionally log the full stack trace as JSON by setting `logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=True)` at initialization. Optionally, setting the `POWERTOOLS_LOGGER_ENHANCED_STACKTRACE` environment variable to `true` will include stacktrace information in the logs. + +=== "logging_stacktrace.py" + + ```python hl_lines="8" + --8<-- "examples/logger/src/logging_stacktrace.py" + ``` + +=== "logging_stacktrace_output.json" + + ```json hl_lines="7-22" + --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`. @@ -352,6 +368,7 @@ The following environment variables are available to configure Logger at a globa | **Event Logging** | Whether to log the incoming event. | `POWERTOOLS_LOGGER_LOG_EVENT` | `false` | | **Debug Sample Rate** | Sets the debug log sampling. | `POWERTOOLS_LOGGER_SAMPLE_RATE` | `0` | | **Disable Deduplication** | Disables log deduplication filter protection to use Pytest Live Log feature. | `POWERTOOLS_LOG_DEDUPLICATION_DISABLED` | `false` | +| **Include Stack Trace** | Includes JSON formatted stack trace in the log output. | `POWERTOOLS_LOGGER_ENHANCED_STACKTRACE` | `false` | [`POWERTOOLS_LOGGER_LOG_EVENT`](#logging-incoming-event) can also be set on a per-method basis, and [`POWERTOOLS_LOGGER_SAMPLE_RATE`](#sampling-debug-logs) on a per-instance basis. These parameter values will override the environment variable value. diff --git a/docs/index.md b/docs/index.md index d4130c33024..aaf7c728759 100644 --- a/docs/index.md +++ b/docs/index.md @@ -718,6 +718,7 @@ Core utilities such as Tracing, Logging, Metrics, and Event Handler will be avai | **POWERTOOLS_PARAMETERS_SSM_DECRYPT** | Sets whether to decrypt or not values retrieved from AWS SSM Parameters Store | [Parameters](./utilities/parameters.md#ssmprovider){target="_blank"} | `false` | | **POWERTOOLS_DEV** | Increases verbosity across utilities | Multiple; see [POWERTOOLS_DEV effect below](#optimizing-for-non-production-environments) | `false` | | **LOG_LEVEL** | Sets logging level | [Logging](./core/logger.md){target="_blank"} | `INFO` | +| **POWERTOOLS_LOGGER_ENHANCED_STACKTRACE** | Include JSON formatted stack trace in log message | [Logging](./core/logger.md){target="_blank"} | `false` | ### Optimizing for non-production environments diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index de589b9accc..5fdfc0965eb 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -959,3 +959,62 @@ 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_no_stack_trace_without_parameter(stdout): + logger = Logger(stream=stdout) + + try: + val = 1 + "someString" + except Exception as e: + logger.exception(e) + + log = capture_logging_output(stdout) + assert "stack_trace" not in log + +def test_logger_logs_stack_trace_with_parameter(stdout): + logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=True)) + + try: + val = 1 + "someString" + except Exception as e: + logger.exception(e) + + log = capture_logging_output(stdout) + assert "stack_trace" in log + +def test_logger_logs_stack_trace_with_env_var(stdout, monkeypatch: pytest.MonkeyPatch): + monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "true") + logger = Logger(stream=stdout) + + try: + val = 1 + "someString" + except Exception as e: + logger.exception(e) + + log = capture_logging_output(stdout) + assert "stack_trace" in log + + +def test_logger_logs_no_stack_trace_with_env_var(stdout, monkeypatch: pytest.MonkeyPatch): + monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "false") + logger = Logger(stream=stdout) + + try: + val = 1 + "someString" + except Exception as e: + logger.exception(e) + + log = capture_logging_output(stdout) + assert "stack_trace" not in log + +def test_logger_logs_no_stack_trace_with_parameter_override(stdout, monkeypatch: pytest.MonkeyPatch): + monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "true") + logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=False)) + + try: + val = 1 + "someString" + except Exception as e: + logger.exception(e) + + log = capture_logging_output(stdout) + assert "stack_trace" not in log From faf838f413f035e16c5bb5523c7a4cc2bc80cece Mon Sep 17 00:00:00 2001 From: Steve Roberts Date: Fri, 6 Oct 2023 10:52:09 -0400 Subject: [PATCH 04/12] Updated the tests, serialization method and renamed the parameter --- .gitignore | 1 + aws_lambda_powertools/logging/formatter.py | 42 +++++++++++++++------- aws_lambda_powertools/logging/logger.py | 2 ++ aws_lambda_powertools/shared/constants.py | 2 +- docs/core/logger.md | 4 +-- docs/index.md | 2 +- examples/logger/src/logging_stacktrace.py | 2 +- tests/functional/test_logger.py | 26 +++++++++----- 8 files changed, 56 insertions(+), 25 deletions(-) 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 e1bb451ae6a..6769b0fc4cd 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -1,6 +1,7 @@ from __future__ import annotations import inspect +import sys import json import logging import os @@ -81,7 +82,7 @@ def __init__( log_record_order: List[str] | None = None, utc: bool = False, use_rfc3339: bool = False, - include_stacktrace: bool = None, + serialize_stacktrace: bool = None, **kwargs, ) -> None: """Return a LambdaPowertoolsFormatter instance. @@ -153,8 +154,8 @@ def __init__( self.keys_combined = {**self._build_default_keys(), **kwargs} self.log_format.update(**self.keys_combined) - self.include_stacktrace = resolve_truthy_env_var_choice(env=os.getenv(constants.POWERTOOLS_STACKTRACE_ENV, "false"), - choice=include_stacktrace, + self.serialize_stacktrace = resolve_truthy_env_var_choice(env=os.getenv(constants.POWERTOOLS_STACKTRACE_ENV, "false"), + choice=serialize_stacktrace, ) super().__init__(datefmt=self.datefmt) @@ -163,27 +164,44 @@ def serialize(self, log: LogRecord) -> str: """Serialize structured log dict to JSON str""" return self.json_serializer(log) - def serialize_traceback(self, e: Exception) -> list: - return [{"file": fs.filename, - "line": fs.lineno, - "column": fs.colno, - "function": fs.name, - "statement": fs.line - } for fs in traceback.extract_tb(e.__traceback__)] + # def serialize_traceback(self, e: Exception) -> list: + # return [{"file": fs.filename, + # "line": fs.lineno, + # "column": fs.colno, + # "function": fs.name, + # "statement": fs.line + # } for fs in traceback.extract_tb(e.__traceback__)] + + def serialize_traceback(self, log_record: logging.LogRecord) -> list: + exception_info = { + "type": log_record.exc_info[0].__name__, + "value": log_record.exc_info[1], + "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 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) - if self.include_stacktrace: + if self.serialize_stacktrace: # Generate the traceback from the traceback library - formatted_log["stack_trace"] = self.serialize_traceback(record.msg) #JSR + formatted_log["stack_trace"] = self.serialize_traceback(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["record"] = record formatted_log["exception"] = formatted_log.get("exception", extracted_exception) formatted_log["exception_name"] = formatted_log.get("exception_name", extracted_exception_name) formatted_log["xray_trace_id"] = self._get_latest_trace_id() diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 45f8bc80721..43fb81be086 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 = None, **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/shared/constants.py b/aws_lambda_powertools/shared/constants.py index 00291f98744..f141f40fa33 100644 --- a/aws_lambda_powertools/shared/constants.py +++ b/aws_lambda_powertools/shared/constants.py @@ -43,4 +43,4 @@ POWERTOOLS_DEV_ENV: str = "POWERTOOLS_DEV" POWERTOOLS_DEBUG_ENV: str = "POWERTOOLS_DEBUG" -POWERTOOLS_STACKTRACE_ENV: str = "POWERTOOLS_LOGGER_ENHANCED_STACKTRACE" \ No newline at end of file +POWERTOOLS_STACKTRACE_ENV: str = "POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE" \ No newline at end of file diff --git a/docs/core/logger.md b/docs/core/logger.md index a10425c8e05..5aff60ad38b 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -321,7 +321,7 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception #### Stack trace logging -Logger can optionally log the full stack trace as JSON by setting `logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=True)` at initialization. Optionally, setting the `POWERTOOLS_LOGGER_ENHANCED_STACKTRACE` environment variable to `true` will include stacktrace information in the logs. +Logger can optionally log the full stack trace as JSON by setting `logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)` at initialization. Optionally, setting the `POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE` environment variable to `true` will include stacktrace information in the logs. === "logging_stacktrace.py" @@ -368,7 +368,7 @@ The following environment variables are available to configure Logger at a globa | **Event Logging** | Whether to log the incoming event. | `POWERTOOLS_LOGGER_LOG_EVENT` | `false` | | **Debug Sample Rate** | Sets the debug log sampling. | `POWERTOOLS_LOGGER_SAMPLE_RATE` | `0` | | **Disable Deduplication** | Disables log deduplication filter protection to use Pytest Live Log feature. | `POWERTOOLS_LOG_DEDUPLICATION_DISABLED` | `false` | -| **Include Stack Trace** | Includes JSON formatted stack trace in the log output. | `POWERTOOLS_LOGGER_ENHANCED_STACKTRACE` | `false` | +| **Include Stack Trace** | Includes JSON formatted stack trace in the log output. | `POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE` | `false` | [`POWERTOOLS_LOGGER_LOG_EVENT`](#logging-incoming-event) can also be set on a per-method basis, and [`POWERTOOLS_LOGGER_SAMPLE_RATE`](#sampling-debug-logs) on a per-instance basis. These parameter values will override the environment variable value. diff --git a/docs/index.md b/docs/index.md index a544bf6dc70..a0bf12f0f80 100644 --- a/docs/index.md +++ b/docs/index.md @@ -723,7 +723,7 @@ Core utilities such as Tracing, Logging, Metrics, and Event Handler will be avai | **POWERTOOLS_PARAMETERS_SSM_DECRYPT** | Sets whether to decrypt or not values retrieved from AWS SSM Parameters Store | [Parameters](./utilities/parameters.md#ssmprovider){target="_blank"} | `false` | | **POWERTOOLS_DEV** | Increases verbosity across utilities | Multiple; see [POWERTOOLS_DEV effect below](#optimizing-for-non-production-environments) | `false` | | **LOG_LEVEL** | Sets logging level | [Logging](./core/logger.md){target="_blank"} | `INFO` | -| **POWERTOOLS_LOGGER_ENHANCED_STACKTRACE** | Include JSON formatted stack trace in log message | [Logging](./core/logger.md){target="_blank"} | `false` | +| **POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE** | Include JSON formatted stack trace in log message | [Logging](./core/logger.md){target="_blank"} | `false` | ### Optimizing for non-production environments diff --git a/examples/logger/src/logging_stacktrace.py b/examples/logger/src/logging_stacktrace.py index 8a547500a4f..d105bf46244 100644 --- a/examples/logger/src/logging_stacktrace.py +++ b/examples/logger/src/logging_stacktrace.py @@ -5,7 +5,7 @@ from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter ENDPOINT = "http://httpbin.org/status/500" -logger = Logger(logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=True)) +logger = Logger(logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) def lambda_handler(event: dict, context: LambdaContext) -> str: diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 5fdfc0965eb..7c73a87cce6 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -964,7 +964,7 @@ def test_logger_logs_no_stack_trace_without_parameter(stdout): logger = Logger(stream=stdout) try: - val = 1 + "someString" + raise ValueError("Something went wrong") except Exception as e: logger.exception(e) @@ -972,10 +972,10 @@ def test_logger_logs_no_stack_trace_without_parameter(stdout): assert "stack_trace" not in log def test_logger_logs_stack_trace_with_parameter(stdout): - logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=True)) + logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) try: - val = 1 + "someString" + raise ValueError("Something went wrong") except Exception as e: logger.exception(e) @@ -987,20 +987,19 @@ def test_logger_logs_stack_trace_with_env_var(stdout, monkeypatch: pytest.Monkey logger = Logger(stream=stdout) try: - val = 1 + "someString" + raise ValueError("Something went wrong") except Exception as e: logger.exception(e) log = capture_logging_output(stdout) assert "stack_trace" in log - def test_logger_logs_no_stack_trace_with_env_var(stdout, monkeypatch: pytest.MonkeyPatch): monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "false") logger = Logger(stream=stdout) try: - val = 1 + "someString" + raise ValueError("Something went wrong") except Exception as e: logger.exception(e) @@ -1009,12 +1008,23 @@ def test_logger_logs_no_stack_trace_with_env_var(stdout, monkeypatch: pytest.Mon def test_logger_logs_no_stack_trace_with_parameter_override(stdout, monkeypatch: pytest.MonkeyPatch): monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "true") - logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(include_stacktrace=False)) + logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False)) try: - val = 1 + "someString" + raise ValueError("Something went wrong") except Exception as e: logger.exception(e) log = capture_logging_output(stdout) assert "stack_trace" not in log + +def test_logger_logs_stack_trace_with_logger_parameter(stdout): + logger = Logger(stream=stdout, serialize_stacktrace=True) + + try: + raise ValueError("Something went wrong") + except Exception as e: + logger.exception(e) + + log = capture_logging_output(stdout) + assert "stack_trace" in log.keys() From fee54797df2ff57ab0c651e1176d18c32e41e9d9 Mon Sep 17 00:00:00 2001 From: Steve Roberts Date: Fri, 6 Oct 2023 13:34:41 -0400 Subject: [PATCH 05/12] Removed dead code --- aws_lambda_powertools/logging/formatter.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 6769b0fc4cd..a0614c71740 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -164,14 +164,6 @@ def serialize(self, log: LogRecord) -> str: """Serialize structured log dict to JSON str""" return self.json_serializer(log) - # def serialize_traceback(self, e: Exception) -> list: - # return [{"file": fs.filename, - # "line": fs.lineno, - # "column": fs.colno, - # "function": fs.name, - # "statement": fs.line - # } for fs in traceback.extract_tb(e.__traceback__)] - def serialize_traceback(self, log_record: logging.LogRecord) -> list: exception_info = { "type": log_record.exc_info[0].__name__, From 6d5f14810e6b2afec09416cc6c67c7920bb3178e Mon Sep 17 00:00:00 2001 From: Steve Roberts Date: Mon, 9 Oct 2023 09:36:14 -0400 Subject: [PATCH 06/12] Removed env variable and default stack trace logging to True --- aws_lambda_powertools/logging/formatter.py | 6 ++-- aws_lambda_powertools/logging/logger.py | 2 +- aws_lambda_powertools/shared/constants.py | 2 -- docs/core/logger.md | 3 +- docs/index.md | 1 - tests/functional/test_logger.py | 34 +++++++--------------- 6 files changed, 14 insertions(+), 34 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index a0614c71740..6f79b2dd72e 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -82,7 +82,7 @@ def __init__( log_record_order: List[str] | None = None, utc: bool = False, use_rfc3339: bool = False, - serialize_stacktrace: bool = None, + serialize_stacktrace: bool = True, **kwargs, ) -> None: """Return a LambdaPowertoolsFormatter instance. @@ -154,9 +154,7 @@ def __init__( self.keys_combined = {**self._build_default_keys(), **kwargs} self.log_format.update(**self.keys_combined) - self.serialize_stacktrace = resolve_truthy_env_var_choice(env=os.getenv(constants.POWERTOOLS_STACKTRACE_ENV, "false"), - choice=serialize_stacktrace, - ) + self.serialize_stacktrace = serialize_stacktrace super().__init__(datefmt=self.datefmt) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 43fb81be086..efc8e3c49c6 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -220,7 +220,7 @@ def __init__( log_record_order: Optional[List[str]] = None, utc: bool = False, use_rfc3339: bool = False, - serialize_stacktrace: bool = None, + serialize_stacktrace: bool = True, **kwargs, ) -> None: self.service = resolve_env_var_choice( diff --git a/aws_lambda_powertools/shared/constants.py b/aws_lambda_powertools/shared/constants.py index f141f40fa33..20a7fbf47d2 100644 --- a/aws_lambda_powertools/shared/constants.py +++ b/aws_lambda_powertools/shared/constants.py @@ -42,5 +42,3 @@ POWERTOOLS_DEV_ENV: str = "POWERTOOLS_DEV" POWERTOOLS_DEBUG_ENV: str = "POWERTOOLS_DEBUG" - -POWERTOOLS_STACKTRACE_ENV: str = "POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE" \ No newline at end of file diff --git a/docs/core/logger.md b/docs/core/logger.md index 5aff60ad38b..79da9643e2d 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -321,7 +321,7 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception #### Stack trace logging -Logger can optionally log the full stack trace as JSON by setting `logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)` at initialization. Optionally, setting the `POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE` environment variable to `true` will include stacktrace information in the logs. +Logger can optionally log the full stack trace as JSON by setting `logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)` at initialization. === "logging_stacktrace.py" @@ -368,7 +368,6 @@ The following environment variables are available to configure Logger at a globa | **Event Logging** | Whether to log the incoming event. | `POWERTOOLS_LOGGER_LOG_EVENT` | `false` | | **Debug Sample Rate** | Sets the debug log sampling. | `POWERTOOLS_LOGGER_SAMPLE_RATE` | `0` | | **Disable Deduplication** | Disables log deduplication filter protection to use Pytest Live Log feature. | `POWERTOOLS_LOG_DEDUPLICATION_DISABLED` | `false` | -| **Include Stack Trace** | Includes JSON formatted stack trace in the log output. | `POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE` | `false` | [`POWERTOOLS_LOGGER_LOG_EVENT`](#logging-incoming-event) can also be set on a per-method basis, and [`POWERTOOLS_LOGGER_SAMPLE_RATE`](#sampling-debug-logs) on a per-instance basis. These parameter values will override the environment variable value. diff --git a/docs/index.md b/docs/index.md index a0bf12f0f80..6ff5a3fa5c4 100644 --- a/docs/index.md +++ b/docs/index.md @@ -723,7 +723,6 @@ Core utilities such as Tracing, Logging, Metrics, and Event Handler will be avai | **POWERTOOLS_PARAMETERS_SSM_DECRYPT** | Sets whether to decrypt or not values retrieved from AWS SSM Parameters Store | [Parameters](./utilities/parameters.md#ssmprovider){target="_blank"} | `false` | | **POWERTOOLS_DEV** | Increases verbosity across utilities | Multiple; see [POWERTOOLS_DEV effect below](#optimizing-for-non-production-environments) | `false` | | **LOG_LEVEL** | Sets logging level | [Logging](./core/logger.md){target="_blank"} | `INFO` | -| **POWERTOOLS_LOGGER_SERIALIZE_STACKTRACE** | Include JSON formatted stack trace in log message | [Logging](./core/logger.md){target="_blank"} | `false` | ### Optimizing for non-production environments diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 7c73a87cce6..0b783082ff7 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -960,7 +960,7 @@ def test_stream_defaults_to_stdout(service_name, capsys): log = json.loads(capsys.readouterr().out.strip()) assert log["message"] == msg -def test_logger_logs_no_stack_trace_without_parameter(stdout): +def test_logger_logs_stack_trace_without_parameter(stdout): logger = Logger(stream=stdout) try: @@ -969,7 +969,7 @@ def test_logger_logs_no_stack_trace_without_parameter(stdout): logger.exception(e) log = capture_logging_output(stdout) - assert "stack_trace" not in log + assert "stack_trace" in log def test_logger_logs_stack_trace_with_parameter(stdout): logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) @@ -982,21 +982,8 @@ def test_logger_logs_stack_trace_with_parameter(stdout): log = capture_logging_output(stdout) assert "stack_trace" in log -def test_logger_logs_stack_trace_with_env_var(stdout, monkeypatch: pytest.MonkeyPatch): - monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "true") - logger = Logger(stream=stdout) - - try: - raise ValueError("Something went wrong") - except Exception as e: - logger.exception(e) - - log = capture_logging_output(stdout) - assert "stack_trace" in log - -def test_logger_logs_no_stack_trace_with_env_var(stdout, monkeypatch: pytest.MonkeyPatch): - monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "false") - logger = Logger(stream=stdout) +def test_logger_logs_no_stack_trace_with_parameter_false(stdout): + logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False)) try: raise ValueError("Something went wrong") @@ -1006,9 +993,8 @@ def test_logger_logs_no_stack_trace_with_env_var(stdout, monkeypatch: pytest.Mon log = capture_logging_output(stdout) assert "stack_trace" not in log -def test_logger_logs_no_stack_trace_with_parameter_override(stdout, monkeypatch: pytest.MonkeyPatch): - monkeypatch.setenv(constants.POWERTOOLS_STACKTRACE_ENV, "true") - logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False)) +def test_logger_logs_stack_trace_with_logger_parameter(stdout): + logger = Logger(stream=stdout, serialize_stacktrace=True) try: raise ValueError("Something went wrong") @@ -1016,10 +1002,10 @@ def test_logger_logs_no_stack_trace_with_parameter_override(stdout, monkeypatch: logger.exception(e) log = capture_logging_output(stdout) - assert "stack_trace" not in log + assert "stack_trace" in log.keys() -def test_logger_logs_stack_trace_with_logger_parameter(stdout): - logger = Logger(stream=stdout, serialize_stacktrace=True) +def test_logger_logs_no_stack_trace_with_logger_parameter_false(stdout): + logger = Logger(stream=stdout, serialize_stacktrace=False) try: raise ValueError("Something went wrong") @@ -1027,4 +1013,4 @@ def test_logger_logs_stack_trace_with_logger_parameter(stdout): logger.exception(e) log = capture_logging_output(stdout) - assert "stack_trace" in log.keys() + assert "stack_trace" not in log.keys() From 2ddfde9762db614a697ac725ceafd58709761615 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Mon, 9 Oct 2023 17:32:13 +0100 Subject: [PATCH 07/12] Small changes --- aws_lambda_powertools/logging/formatter.py | 48 ++++++++++------------ aws_lambda_powertools/logging/logger.py | 2 +- aws_lambda_powertools/logging/types.py | 9 ++++ docs/contributing/documentation/rfcs.md | 2 + examples/logger/src/logging_stacktrace.py | 2 +- tests/functional/test_logger.py | 5 +++ 6 files changed, 40 insertions(+), 28 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 6f79b2dd72e..67b862901a3 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -1,7 +1,6 @@ from __future__ import annotations import inspect -import sys import json import logging import os @@ -11,11 +10,8 @@ from datetime import datetime, timezone from functools import partial from typing import Any, Callable, Dict, Iterable, List, Optional, Tuple, Union -from ..shared.functions import ( - resolve_truthy_env_var_choice -) -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 @@ -161,39 +157,21 @@ def __init__( def serialize(self, log: LogRecord) -> str: """Serialize structured log dict to JSON str""" return self.json_serializer(log) - - def serialize_traceback(self, log_record: logging.LogRecord) -> list: - exception_info = { - "type": log_record.exc_info[0].__name__, - "value": log_record.exc_info[1], - "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 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) - if self.serialize_stacktrace: - # Generate the traceback from the traceback library - formatted_log["stack_trace"] = self.serialize_traceback(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["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) @@ -304,6 +282,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 efc8e3c49c6..28d899d25e5 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -254,7 +254,7 @@ def __init__( "log_record_order": log_record_order, "utc": utc, "use_rfc3339": use_rfc3339, - "serialize_stacktrace": serialize_stacktrace + "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/examples/logger/src/logging_stacktrace.py b/examples/logger/src/logging_stacktrace.py index d105bf46244..807d6d69732 100644 --- a/examples/logger/src/logging_stacktrace.py +++ b/examples/logger/src/logging_stacktrace.py @@ -1,8 +1,8 @@ import requests from aws_lambda_powertools import Logger -from aws_lambda_powertools.utilities.typing import LambdaContext from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter +from aws_lambda_powertools.utilities.typing import LambdaContext ENDPOINT = "http://httpbin.org/status/500" logger = Logger(logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 0b783082ff7..b76eb102a1d 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -960,6 +960,7 @@ def test_stream_defaults_to_stdout(service_name, capsys): log = json.loads(capsys.readouterr().out.strip()) assert log["message"] == msg + def test_logger_logs_stack_trace_without_parameter(stdout): logger = Logger(stream=stdout) @@ -971,6 +972,7 @@ def test_logger_logs_stack_trace_without_parameter(stdout): log = capture_logging_output(stdout) assert "stack_trace" in log + def test_logger_logs_stack_trace_with_parameter(stdout): logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) @@ -982,6 +984,7 @@ def test_logger_logs_stack_trace_with_parameter(stdout): log = capture_logging_output(stdout) assert "stack_trace" in log + def test_logger_logs_no_stack_trace_with_parameter_false(stdout): logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False)) @@ -993,6 +996,7 @@ def test_logger_logs_no_stack_trace_with_parameter_false(stdout): log = capture_logging_output(stdout) assert "stack_trace" not in log + def test_logger_logs_stack_trace_with_logger_parameter(stdout): logger = Logger(stream=stdout, serialize_stacktrace=True) @@ -1004,6 +1008,7 @@ def test_logger_logs_stack_trace_with_logger_parameter(stdout): log = capture_logging_output(stdout) assert "stack_trace" in log.keys() + def test_logger_logs_no_stack_trace_with_logger_parameter_false(stdout): logger = Logger(stream=stdout, serialize_stacktrace=False) From 9307e9d17dd8f755b78ce11724d066c8432ff6db Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Mon, 9 Oct 2023 17:43:44 +0100 Subject: [PATCH 08/12] Removing wrong field --- aws_lambda_powertools/logging/formatter.py | 1 - 1 file changed, 1 deletion(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 67b862901a3..c52fe90893f 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -166,7 +166,6 @@ def format(self, record: logging.LogRecord) -> str: # noqa: A003 # 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["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: From 8eba534e9e7c01bde87411cafa73e75e59e84e2e Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Mon, 9 Oct 2023 18:23:31 +0100 Subject: [PATCH 09/12] Adjusting tests --- tests/functional/test_logger.py | 70 ++++++------------- .../test_logger_powertools_formatter.py | 53 ++++++++++++++ 2 files changed, 75 insertions(+), 48 deletions(-) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index b76eb102a1d..47803b1e52d 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -961,61 +961,35 @@ def test_stream_defaults_to_stdout(service_name, capsys): assert log["message"] == msg -def test_logger_logs_stack_trace_without_parameter(stdout): - logger = Logger(stream=stdout) - - try: - raise ValueError("Something went wrong") - except Exception as e: - logger.exception(e) - - log = capture_logging_output(stdout) - assert "stack_trace" in log - - -def test_logger_logs_stack_trace_with_parameter(stdout): - logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) +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) - try: - raise ValueError("Something went wrong") - except Exception as e: - logger.exception(e) + # 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_no_stack_trace_with_parameter_false(stdout): - logger = Logger(stream=stdout, logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False)) +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) - try: - raise ValueError("Something went wrong") - except Exception as e: - logger.exception(e) + # 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 - - -def test_logger_logs_stack_trace_with_logger_parameter(stdout): - logger = Logger(stream=stdout, serialize_stacktrace=True) - - try: - raise ValueError("Something went wrong") - except Exception as e: - logger.exception(e) - - log = capture_logging_output(stdout) - assert "stack_trace" in log.keys() - - -def test_logger_logs_no_stack_trace_with_logger_parameter_false(stdout): - logger = Logger(stream=stdout, serialize_stacktrace=False) - - try: - raise ValueError("Something went wrong") - except Exception as e: - logger.exception(e) - - log = capture_logging_output(stdout) - assert "stack_trace" not in log.keys() 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 From ed2a3c56e4f0fb6c0b9feecee28f6bd1a2297209 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Mon, 9 Oct 2023 18:54:33 +0100 Subject: [PATCH 10/12] Adjusting documentation --- docs/core/logger.md | 6 +-- examples/logger/src/logging_stacktrace.py | 3 +- .../logger/src/logging_stacktrace_output.json | 52 ++++++++++--------- 3 files changed, 31 insertions(+), 30 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 79da9643e2d..df42101f78e 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -321,17 +321,17 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception #### Stack trace logging -Logger can optionally log the full stack trace as JSON by setting `logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)` at initialization. +By default, the Logger will automatically log 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="8" + ```python hl_lines="7 15" --8<-- "examples/logger/src/logging_stacktrace.py" ``` === "logging_stacktrace_output.json" - ```json hl_lines="7-22" + ```json hl_lines="9-27" --8<-- "examples/logger/src/logging_stacktrace_output.json" ``` diff --git a/examples/logger/src/logging_stacktrace.py b/examples/logger/src/logging_stacktrace.py index 807d6d69732..128836f5138 100644 --- a/examples/logger/src/logging_stacktrace.py +++ b/examples/logger/src/logging_stacktrace.py @@ -1,11 +1,10 @@ import requests from aws_lambda_powertools import Logger -from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter from aws_lambda_powertools.utilities.typing import LambdaContext ENDPOINT = "http://httpbin.org/status/500" -logger = Logger(logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=True)) +logger = Logger(serialize_stacktrace=True) def lambda_handler(event: dict, context: LambdaContext) -> str: diff --git a/examples/logger/src/logging_stacktrace_output.json b/examples/logger/src/logging_stacktrace_output.json index 6e64ac69981..d972f3ff6a9 100644 --- a/examples/logger/src/logging_stacktrace_output.json +++ b/examples/logger/src/logging_stacktrace_output.json @@ -1,26 +1,28 @@ { - "level": "ERROR", - "location": "lambda_handler:16", - "message": "500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500", - "timestamp": "2023-09-28 19:25:09,781+0000", - "service": "service_undefined", - "stack_trace": [ - { - "File": "/var/task/app.py", - "Line": 14, - "Column": 8, - "Function": "lambda_handler", - "Statement": "ret.raise_for_status()" - }, - { - "File": "/var/task/requests/models.py", - "Line": 1021, - "Column": 12, - "Function": "raise_for_status", - "Statement": "raise HTTPError(http_error_msg, response=self)" - } - ], - "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", - "xray_trace_id": "1-6515d315-07fbcb5e693988c6480a98e2" -} + "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)" + } + ] + } + } From d24a566a6755f876d944dcd7aa0470b530187689 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Tue, 10 Oct 2023 11:31:58 +0100 Subject: [PATCH 11/12] Addressing Ruben's feedback --- docs/core/logger.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index df42101f78e..72577f3c9f6 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -321,7 +321,7 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception #### Stack trace logging -By default, the Logger will automatically log the full stack trace in JSON format when using `logger.exception`. If you want to disable this feature, set `serialize_stacktrace=False` during initialization." +By default, the Logger will automatically includes 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" From 8c1831e1267dba618a940b3c7b03541dc16c4a27 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Tue, 10 Oct 2023 12:37:41 +0100 Subject: [PATCH 12/12] Addressing Ruben's feedback --- docs/core/logger.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 72577f3c9f6..237f48c006f 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -321,7 +321,7 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception #### Stack trace logging -By default, the Logger will automatically includes the full stack trace in JSON format when using `logger.exception`. If you want to disable this feature, set `serialize_stacktrace=False` during initialization." +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"