From b498b0b5acec29d99f0c5bf3bf4e5a8a0dc8df1c Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 15:10:29 -0800 Subject: [PATCH 1/8] feat(logging): inject correlation_id Prototype idea for correlation_id support in logger --- aws_lambda_powertools/logging/logger.py | 42 +++++++++++++++++++++++-- tests/functional/test_logger.py | 18 +++++++++++ 2 files changed, 57 insertions(+), 3 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 06285e73b82..f709d40bbe7 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -4,7 +4,9 @@ import os import random import sys -from typing import Any, Callable, Dict, Union +from typing import Any, Callable, Dict, Optional, Union + +import jmespath from ..shared import constants from ..shared.functions import resolve_env_var_choice, resolve_truthy_env_var_choice @@ -36,6 +38,27 @@ def _is_cold_start() -> bool: return cold_start +def _get_correlation_id_path(path: Union[str, int]) -> Optional[str]: + """ + + Parameters + ---------- + path : + JMESPath + Returns + ------- + str, optional + Returns the JMESPath + """ + if path is None: + return None + + # NOTE: We could have a enum of standard event types + # like "requestContext.requestId" or API Gateway Proxy Events + + return path + + # PyCharm does not support autocomplete via getattr # so we need to return to subclassing removed in #97 # All methods/properties continue to be proxied to inner logger @@ -204,7 +227,12 @@ def _configure_sampling(self): f"Please review POWERTOOLS_LOGGER_SAMPLE_RATE environment variable." ) - def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None): + def inject_lambda_context( + self, + lambda_handler: Callable[[Dict, Any], Any] = None, + log_event: bool = None, + correlation_id_path: Union[str, int] = None, + ): """Decorator to capture Lambda contextual info and inject into logger Parameters @@ -213,6 +241,8 @@ def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = Non Method to inject the lambda context log_event : bool, optional Instructs logger to log Lambda Event, by default False + correlation_id_path: str, optional + Can be a JMESPath or one of the standard ones Environment variables --------------------- @@ -251,11 +281,14 @@ def handler(event, context): # Return a partial function with args filled if lambda_handler is None: logger.debug("Decorator called with parameters") - return functools.partial(self.inject_lambda_context, log_event=log_event) + return functools.partial( + self.inject_lambda_context, log_event=log_event, correlation_id_path=correlation_id_path + ) log_event = resolve_truthy_env_var_choice( choice=log_event, env=os.getenv(constants.LOGGER_LOG_EVENT_ENV, "false") ) + correlation_id_path = _get_correlation_id_path(correlation_id_path) @functools.wraps(lambda_handler) def decorate(event, context): @@ -263,6 +296,9 @@ def decorate(event, context): cold_start = _is_cold_start() self.structure_logs(append=True, cold_start=cold_start, **lambda_context.__dict__) + if correlation_id_path: + self.structure_logs(append=True, correlation_id=jmespath.search(correlation_id_path, event)) + if log_event: logger.debug("Event received") self.info(event) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 2b4c7cf187e..91bd098a73a 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -437,3 +437,21 @@ def test_logger_exception_extract_exception_name(stdout, service_name): # THEN we expect a "exception_name" to be "ValueError" log = capture_logging_output(stdout) assert "ValueError" == log["exception_name"] + + +def test_logger_correlation_id(lambda_context, stdout, service_name): + # GIVEN + logger = Logger(service=service_name, stream=stdout) + request_id = "xxx" + mock_event = {"requestContext": {"requestId": request_id}} + + @logger.inject_lambda_context(correlation_id_path="requestContext.requestId") + def handler(_1, _2): + logger.info("Foo") + + # WHEN + handler(mock_event, lambda_context) + + # THEN + log = capture_logging_output(stdout) + assert request_id == log["correlation_id"] From 4bee95bf242e348e0d4a2188081882022c040bee Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 15:32:29 -0800 Subject: [PATCH 2/8] chore: Bump CI --- aws_lambda_powertools/logging/logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index f709d40bbe7..0356e72ff33 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -44,7 +44,7 @@ def _get_correlation_id_path(path: Union[str, int]) -> Optional[str]: Parameters ---------- path : - JMESPath + JMESPath expression to find the correlation_id Returns ------- str, optional @@ -242,7 +242,7 @@ def inject_lambda_context( log_event : bool, optional Instructs logger to log Lambda Event, by default False correlation_id_path: str, optional - Can be a JMESPath or one of the standard ones + JMESPath expression to find the correlation_id Environment variables --------------------- From 2e4e5215367bc98fd54bbc654c65e1ff6aa00566 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 22:46:07 -0800 Subject: [PATCH 3/8] feat(logger): Add set_correlation_id --- aws_lambda_powertools/logging/logger.py | 29 ++++++++--------- docs/core/logger.md | 41 +++++++++++++++++++++++++ tests/functional/test_logger.py | 6 ++-- 3 files changed, 56 insertions(+), 20 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 0356e72ff33..4b7ef49f5a2 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -6,8 +6,6 @@ import sys from typing import Any, Callable, Dict, Optional, Union -import jmespath - from ..shared import constants from ..shared.functions import resolve_env_var_choice, resolve_truthy_env_var_choice from .exceptions import InvalidLoggerSamplingRateError @@ -227,12 +225,7 @@ def _configure_sampling(self): f"Please review POWERTOOLS_LOGGER_SAMPLE_RATE environment variable." ) - def inject_lambda_context( - self, - lambda_handler: Callable[[Dict, Any], Any] = None, - log_event: bool = None, - correlation_id_path: Union[str, int] = None, - ): + def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None): """Decorator to capture Lambda contextual info and inject into logger Parameters @@ -241,8 +234,6 @@ def inject_lambda_context( Method to inject the lambda context log_event : bool, optional Instructs logger to log Lambda Event, by default False - correlation_id_path: str, optional - JMESPath expression to find the correlation_id Environment variables --------------------- @@ -281,14 +272,11 @@ def handler(event, context): # Return a partial function with args filled if lambda_handler is None: logger.debug("Decorator called with parameters") - return functools.partial( - self.inject_lambda_context, log_event=log_event, correlation_id_path=correlation_id_path - ) + return functools.partial(self.inject_lambda_context, log_event=log_event) log_event = resolve_truthy_env_var_choice( choice=log_event, env=os.getenv(constants.LOGGER_LOG_EVENT_ENV, "false") ) - correlation_id_path = _get_correlation_id_path(correlation_id_path) @functools.wraps(lambda_handler) def decorate(event, context): @@ -296,9 +284,6 @@ def decorate(event, context): cold_start = _is_cold_start() self.structure_logs(append=True, cold_start=cold_start, **lambda_context.__dict__) - if correlation_id_path: - self.structure_logs(append=True, correlation_id=jmespath.search(correlation_id_path, event)) - if log_event: logger.debug("Event received") self.info(event) @@ -332,6 +317,16 @@ def structure_logs(self, append: bool = False, **kwargs): # Set a new formatter for a logger handler handler.setFormatter(JsonFormatter(**self._default_log_keys, **kwargs)) + def set_correlation_id(self, value: str): + """Sets the correlation_id in the logging json + + Parameters + ---------- + value : str + Value for the correlation id + """ + self.structure_logs(append=True, correlation_id=value) + @staticmethod def _get_log_level(level: Union[str, int]) -> Union[str, int]: """ Returns preferred log level set by the customer in upper case """ diff --git a/docs/core/logger.md b/docs/core/logger.md index 2c5c347eadf..90e99b38405 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -188,6 +188,47 @@ You can append your own keys to your existing Logger via `structure_logs(append= This example will add `order_id` if its value is not empty, and in subsequent invocations where `order_id` might not be present it'll remove it from the logger. +#### set_correlation_id method + +You can set a correlation_id to your existing Logger via `set_correlation_id(value)` method. + +=== "collect.py" + + ```python hl_lines="8" + from aws_lambda_powertools import Logger + from aws_lambda_powertools.utilities.data_classes import APIGatewayProxyEvent + + logger = Logger() + + def handler(event, context): + event = APIGatewayProxyEvent(event) + logger.set_correlation_id(event.request_context.request_id) + logger.info("Collecting payment") + ... + ``` +=== "Example Event" + + ```json hl_lines="3" + { + "requestContext": { + "requestId": "correlation_id_value" + } + } + ``` +=== "Example CloudWatch Logs excerpt" + + ```json hl_lines="7" + { + "timestamp": "2020-05-24 18:17:33,774", + "level": "INFO", + "location": "collect.handler:1", + "service": "payment", + "sampling_rate": 0.0, + "correlation_id": "correlation_id_value", + "message": "Collecting payment" + } + ``` + #### extra parameter Extra parameter is available for all log levels' methods, as implemented in the standard logging library - e.g. `logger.info, logger.warning`. diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 91bd098a73a..417c3656ed9 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -442,11 +442,11 @@ def test_logger_exception_extract_exception_name(stdout, service_name): def test_logger_correlation_id(lambda_context, stdout, service_name): # GIVEN logger = Logger(service=service_name, stream=stdout) - request_id = "xxx" + request_id = "xxx-111-222" mock_event = {"requestContext": {"requestId": request_id}} - @logger.inject_lambda_context(correlation_id_path="requestContext.requestId") - def handler(_1, _2): + def handler(event, _): + logger.set_correlation_id(event["requestContext"]["requestId"]) logger.info("Foo") # WHEN From 00c084222a60c51a1d43b02b325cfada13bb44b2 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 22:50:43 -0800 Subject: [PATCH 4/8] chore: Remove _get_correlation_id_path --- aws_lambda_powertools/logging/logger.py | 23 +---------------------- 1 file changed, 1 insertion(+), 22 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 4b7ef49f5a2..c2e83ed2608 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -4,7 +4,7 @@ import os import random import sys -from typing import Any, Callable, Dict, Optional, Union +from typing import Any, Callable, Dict, Union from ..shared import constants from ..shared.functions import resolve_env_var_choice, resolve_truthy_env_var_choice @@ -36,27 +36,6 @@ def _is_cold_start() -> bool: return cold_start -def _get_correlation_id_path(path: Union[str, int]) -> Optional[str]: - """ - - Parameters - ---------- - path : - JMESPath expression to find the correlation_id - Returns - ------- - str, optional - Returns the JMESPath - """ - if path is None: - return None - - # NOTE: We could have a enum of standard event types - # like "requestContext.requestId" or API Gateway Proxy Events - - return path - - # PyCharm does not support autocomplete via getattr # so we need to return to subclassing removed in #97 # All methods/properties continue to be proxied to inner logger From dce201004e88b20f573fa082bd7cf0ce9bdd5475 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 23:17:57 -0800 Subject: [PATCH 5/8] feat(logging): Add correlation_id_path option --- aws_lambda_powertools/logging/logger.py | 15 +++++++++++++-- tests/functional/test_logger.py | 20 +++++++++++++++++++- 2 files changed, 32 insertions(+), 3 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index c2e83ed2608..98ecfc4c449 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -6,6 +6,8 @@ import sys from typing import Any, Callable, Dict, Union +import jmespath + from ..shared import constants from ..shared.functions import resolve_env_var_choice, resolve_truthy_env_var_choice from .exceptions import InvalidLoggerSamplingRateError @@ -204,7 +206,9 @@ def _configure_sampling(self): f"Please review POWERTOOLS_LOGGER_SAMPLE_RATE environment variable." ) - def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None): + def inject_lambda_context( + self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None, correlation_id_path: str = None + ): """Decorator to capture Lambda contextual info and inject into logger Parameters @@ -213,6 +217,8 @@ def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = Non Method to inject the lambda context log_event : bool, optional Instructs logger to log Lambda Event, by default False + correlation_id_path: str, optional + Optional JMESPath for the correlation_id Environment variables --------------------- @@ -251,7 +257,9 @@ def handler(event, context): # Return a partial function with args filled if lambda_handler is None: logger.debug("Decorator called with parameters") - return functools.partial(self.inject_lambda_context, log_event=log_event) + return functools.partial( + self.inject_lambda_context, log_event=log_event, correlation_id_path=correlation_id_path + ) log_event = resolve_truthy_env_var_choice( choice=log_event, env=os.getenv(constants.LOGGER_LOG_EVENT_ENV, "false") @@ -263,6 +271,9 @@ def decorate(event, context): cold_start = _is_cold_start() self.structure_logs(append=True, cold_start=cold_start, **lambda_context.__dict__) + if correlation_id_path: + self.set_correlation_id(jmespath.search(correlation_id_path, event)) + if log_event: logger.debug("Event received") self.info(event) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 417c3656ed9..e8597df41d4 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -439,7 +439,7 @@ def test_logger_exception_extract_exception_name(stdout, service_name): assert "ValueError" == log["exception_name"] -def test_logger_correlation_id(lambda_context, stdout, service_name): +def test_logger_set_correlation_id(lambda_context, stdout, service_name): # GIVEN logger = Logger(service=service_name, stream=stdout) request_id = "xxx-111-222" @@ -455,3 +455,21 @@ def handler(event, _): # THEN log = capture_logging_output(stdout) assert request_id == log["correlation_id"] + + +def test_logger_set_correlation_id_path(lambda_context, stdout, service_name): + # GIVEN + logger = Logger(service=service_name, stream=stdout) + request_id = "xxx-111-222" + mock_event = {"requestContext": {"requestId": request_id}} + + @logger.inject_lambda_context(correlation_id_path="requestContext.requestId") + def handler(event, context): + logger.info("Foo") + + # WHEN + handler(mock_event, lambda_context) + + # THEN + log = capture_logging_output(stdout) + assert request_id == log["correlation_id"] From 551b1cc80d344851de2812506b65250e1a8f8776 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 23:29:27 -0800 Subject: [PATCH 6/8] feat(logger): Add correlation_paths --- aws_lambda_powertools/logging/correlation_paths.py | 4 ++++ tests/functional/test_logger.py | 3 ++- 2 files changed, 6 insertions(+), 1 deletion(-) create mode 100644 aws_lambda_powertools/logging/correlation_paths.py diff --git a/aws_lambda_powertools/logging/correlation_paths.py b/aws_lambda_powertools/logging/correlation_paths.py new file mode 100644 index 00000000000..22dce48ff61 --- /dev/null +++ b/aws_lambda_powertools/logging/correlation_paths.py @@ -0,0 +1,4 @@ +"""Built-in correlation paths""" + +API_GATEWAY_REST = "requestContext.requestId" +API_GATEWAY_HTTP = API_GATEWAY_REST diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index e8597df41d4..ddf5ee226f5 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -9,6 +9,7 @@ import pytest from aws_lambda_powertools import Logger, Tracer +from aws_lambda_powertools.logging import correlation_paths from aws_lambda_powertools.logging.exceptions import InvalidLoggerSamplingRateError from aws_lambda_powertools.logging.logger import set_package_logger from aws_lambda_powertools.shared import constants @@ -463,7 +464,7 @@ def test_logger_set_correlation_id_path(lambda_context, stdout, service_name): request_id = "xxx-111-222" mock_event = {"requestContext": {"requestId": request_id}} - @logger.inject_lambda_context(correlation_id_path="requestContext.requestId") + @logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_REST) def handler(event, context): logger.info("Foo") From 6383fb431a419d0154fe865e065586f1e663cefa Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 23:36:55 -0800 Subject: [PATCH 7/8] feat(logger): Add more builtin correlation paths --- aws_lambda_powertools/logging/correlation_paths.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/aws_lambda_powertools/logging/correlation_paths.py b/aws_lambda_powertools/logging/correlation_paths.py index 22dce48ff61..73227754363 100644 --- a/aws_lambda_powertools/logging/correlation_paths.py +++ b/aws_lambda_powertools/logging/correlation_paths.py @@ -2,3 +2,5 @@ API_GATEWAY_REST = "requestContext.requestId" API_GATEWAY_HTTP = API_GATEWAY_REST +APPLICATION_LOAD_BALANCER = "headers.x-amzn-trace-id" +EVENT_BRIDGE = "id" From 495818972afd7fb1e281ade3234d31d1e24fbc66 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Tue, 9 Mar 2021 23:38:20 -0800 Subject: [PATCH 8/8] chore: Update docs/core/logger.md Co-authored-by: Heitor Lessa --- 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 90e99b38405..27cbd725f80 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -188,7 +188,7 @@ You can append your own keys to your existing Logger via `structure_logs(append= This example will add `order_id` if its value is not empty, and in subsequent invocations where `order_id` might not be present it'll remove it from the logger. -#### set_correlation_id method +#### Setting correlation ID You can set a correlation_id to your existing Logger via `set_correlation_id(value)` method.