From 8576161f2255cfc7d877fba6f9b78ef0966c5e6d Mon Sep 17 00:00:00 2001 From: Simon Frank Date: Sun, 8 Sep 2024 01:02:38 -0400 Subject: [PATCH 01/12] Getting baseline thread safe keys working --- aws_lambda_powertools/logging/formatter.py | 73 +++++++++++++++++++++- aws_lambda_powertools/logging/logger.py | 12 ++++ 2 files changed, 84 insertions(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 48797f51e2a..55c48b62339 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -7,6 +7,7 @@ import time import traceback from abc import ABCMeta, abstractmethod +from contextvars import ContextVar from datetime import datetime, timezone from functools import partial from typing import TYPE_CHECKING, Any, Callable, Iterable @@ -50,17 +51,30 @@ class BasePowertoolsFormatter(logging.Formatter, metaclass=ABCMeta): def append_keys(self, **additional_keys) -> None: raise NotImplementedError() + def append_thread_local_keys(self, **additional_keys) -> None: + raise NotImplementedError() + def get_current_keys(self) -> dict[str, Any]: return {} + def get_current_thread_keys(self) -> Dict[str, Any]: + return {} + def remove_keys(self, keys: Iterable[str]) -> None: raise NotImplementedError() + def remove_thread_local_keys(self, keys: Iterable[str]) -> None: + raise NotImplementedError() + @abstractmethod def clear_state(self) -> None: """Removes any previously added logging keys""" raise NotImplementedError() + def clear_thread_local_keys(self) -> None: + """Removes any previously added logging keys in a specific thread""" + raise NotImplementedError() + class LambdaPowertoolsFormatter(BasePowertoolsFormatter): """Powertools for AWS Lambda (Python) Logging formatter. @@ -236,17 +250,29 @@ def formatTime(self, record: logging.LogRecord, datefmt: str | None = None) -> s def append_keys(self, **additional_keys) -> None: self.log_format.update(additional_keys) + def append_thread_local_keys(self, **additional_keys) -> None: + set_context_keys(**additional_keys) + def get_current_keys(self) -> dict[str, Any]: return self.log_format + def get_current_thread_keys(self) -> Dict[str, Any]: + return _get_context().get() + def remove_keys(self, keys: Iterable[str]) -> None: for key in keys: self.log_format.pop(key, None) + def remove_thread_local_keys(self, keys: Iterable[str]) -> None: + remove_context_keys(keys) + def clear_state(self) -> None: self.log_format = dict.fromkeys(self.log_record_order) self.log_format.update(**self.keys_combined) + def clear_thread_local_keys(self) -> None: + clear_context_keys() + @staticmethod def _build_default_keys() -> dict[str, str]: return { @@ -349,10 +375,29 @@ def _extract_log_keys(self, log_record: logging.LogRecord) -> dict[str, Any]: # Iterate over a default or existing log structure # then replace any std log attribute e.g. '%(level)s' to 'INFO', '%(process)d to '4773' + # check if the value is a str if the key is a reserved attribute, the modulo operator only supports string # lastly add or replace incoming keys (those added within the constructor or .structure_logs method) for key, value in self.log_format.items(): if value and key in RESERVED_LOG_ATTRS: - formatted_log[key] = value % record_dict + if isinstance(value, str): + formatted_log[key] = value % record_dict + else: + raise ValueError( + "Logging keys that override reserved log attributes need to be type 'str', " + f"instead got '{type(value).__name__}'", + ) + else: + formatted_log[key] = value + + for key, value in _get_context().get().items(): + if value and key in RESERVED_LOG_ATTRS: + if isinstance(value, str): + formatted_log[key] = value % record_dict + else: + raise ValueError( + "Logging keys that override reserved log attributes need to be type 'str', " + f"instead got '{type(value).__name__}'", + ) else: formatted_log[key] = value @@ -370,3 +415,29 @@ def _strip_none_records(records: dict[str, Any]) -> dict[str, Any]: # Fetch current and future parameters from PowertoolsFormatter that should be reserved RESERVED_FORMATTER_CUSTOM_KEYS: list[str] = inspect.getfullargspec(LambdaPowertoolsFormatter).args[1:] + +# ContextVar for thread local keys +THREAD_LOCAL_KEYS = ContextVar("THREAD_LOCAL_KEYS", default={}) + + +def _get_context() -> ContextVar[dict[Any, Any]]: + return THREAD_LOCAL_KEYS + + +def clear_context_keys() -> None: + _get_context().set({}) + + +def set_context_keys(**kwargs: Dict[str, Any]) -> None: + context = _get_context() + context.set(context.get() | kwargs) + + +def remove_context_keys(keys: List[str]) -> None: + context = _get_context() + context_values = context.get() + + for k in keys: + context_values.pop(k, None) + + context.set(context_values) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 75a14c6ea2b..f7d68c36ee5 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -583,12 +583,24 @@ def debug( def append_keys(self, **additional_keys: object) -> None: self.registered_formatter.append_keys(**additional_keys) + def append_thread_local_keys(self, **additional_keys: object) -> None: + self.registered_formatter.append_thread_local_keys(**additional_keys) + def get_current_keys(self) -> dict[str, Any]: return self.registered_formatter.get_current_keys() + def get_current_thread_keys(self) -> Dict[str, Any]: + return self.registered_formatter.get_current_thread_keys() + def remove_keys(self, keys: Iterable[str]) -> None: self.registered_formatter.remove_keys(keys) + def remove_thread_local_keys(self, keys: Iterable[str]) -> None: + self.registered_formatter.remove_thread_local_keys(keys) + + def clear_thread_local_keys(self) -> None: + self.registered_formatter.clear_thread_local_keys() + def structure_logs(self, append: bool = False, formatter_options: dict | None = None, **keys) -> None: """Sets logging formatting to JSON. From 9eca9e12882bca173064cb48ecbdcd731ff2dd6e Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 02:46:35 -0400 Subject: [PATCH 02/12] Functional tests for thread safe keys --- aws_lambda_powertools/logging/formatter.py | 6 +- .../test_logger_powertools_formatter.py | 102 +++++++++++++++++- 2 files changed, 101 insertions(+), 7 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 55c48b62339..e23ddadc04e 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -371,7 +371,7 @@ def _extract_log_keys(self, log_record: logging.LogRecord) -> dict[str, Any]: record_dict["asctime"] = self.formatTime(record=log_record) extras = {k: v for k, v in record_dict.items() if k not in RESERVED_LOG_ATTRS} - formatted_log = {} + formatted_log: Dict[str, Any] = {} # Iterate over a default or existing log structure # then replace any std log attribute e.g. '%(level)s' to 'INFO', '%(process)d to '4773' @@ -417,7 +417,7 @@ def _strip_none_records(records: dict[str, Any]) -> dict[str, Any]: RESERVED_FORMATTER_CUSTOM_KEYS: list[str] = inspect.getfullargspec(LambdaPowertoolsFormatter).args[1:] # ContextVar for thread local keys -THREAD_LOCAL_KEYS = ContextVar("THREAD_LOCAL_KEYS", default={}) +THREAD_LOCAL_KEYS: ContextVar[dict[Any, Any]] = ContextVar("THREAD_LOCAL_KEYS", default={}) def _get_context() -> ContextVar[dict[Any, Any]]: @@ -433,7 +433,7 @@ def set_context_keys(**kwargs: Dict[str, Any]) -> None: context.set(context.get() | kwargs) -def remove_context_keys(keys: List[str]) -> None: +def remove_context_keys(keys: Iterable[str]) -> None: context = _get_context() context_values = context.get() diff --git a/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py b/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py index fe47e72d596..2a307623f88 100644 --- a/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py +++ b/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py @@ -8,6 +8,7 @@ import string import time from collections import namedtuple +from threading import Thread import pytest @@ -40,7 +41,7 @@ def service_name(): def capture_logging_output(stdout): - return json.loads(stdout.getvalue().strip()) + return [json.loads(d.strip()) for d in stdout.getvalue().strip().split("\n")] @pytest.mark.parametrize("level", ["DEBUG", "WARNING", "ERROR", "INFO", "CRITICAL"]) @@ -370,7 +371,7 @@ def test_datadog_formatter_use_rfc3339_date(stdout, service_name): logger.info({}) # THEN the timestamp uses RFC3339 by default - log = capture_logging_output(stdout) + log = capture_logging_output(stdout)[0] assert re.fullmatch(RFC3339_REGEX, log["timestamp"]) # "2022-10-27T17:42:26.841+0200" @@ -389,7 +390,7 @@ def handler(event, context): # THEN we expect a "stack_trace" in log handler({}, lambda_context) - log = capture_logging_output(stdout) + log = capture_logging_output(stdout)[0] assert "stack_trace" in log @@ -410,5 +411,98 @@ def handler(event, context): # THEN we expect a "stack_trace" not in log handler({}, lambda_context) - log = capture_logging_output(stdout) + log = capture_logging_output(stdout)[0] assert "stack_trace" not in log + + +def test_thread_keys_encapsulation(service_name, stdout): + logger = Logger( + service=service_name, + stream=stdout, + ) + + def send_thread_message_with_key(message, keys): + logger.append_thread_local_keys(**keys) + logger.info(message) + + global_key = {"exampleKey": "globalKey"} + logger.append_keys(**global_key) + logger.info("global key added") + + thread1_keys = {"exampleThread1Key": "thread1"} + Thread(target=send_thread_message_with_key, args=("thread1", thread1_keys)).start() + thread2_keys = {"exampleThread2Key": "thread2"} + Thread(target=send_thread_message_with_key, args=("thread2", thread2_keys)).start() + + final_log_message = "final log, all thread keys gone" + logger.info(final_log_message) + + logs = capture_logging_output(stdout) + + assert logs[0].get("exampleKey") == "globalKey" + + assert logs[1].get("exampleKey") == "globalKey" + assert logs[1].get("exampleThread1Key") == "thread1" + assert logs[1].get("exampleThread2Key") is None + + assert logs[2].get("exampleKey") == "globalKey" + assert logs[2].get("exampleThread1Key") is None + assert logs[2].get("exampleThread2Key") == "thread2" + + assert logs[3].get("exampleKey") == "globalKey" + assert logs[3].get("exampleThread1Key") is None + assert logs[3].get("exampleThread2Key") is None + + +def test_remove_thread_key(service_name, stdout): + """ + Tests that global and thread safe logger keys work as expected + 1. Log with no keys attached + 2. Log with only global key + 3. Create two threads and validate: + - Keys added in one thread isn't in another + - Global keys are still present + 4. After threading is done, thread keys don't show up + """ + + logger = Logger( + service=service_name, + stream=stdout, + ) + + def send_message_with_key_and_without(message, keys): + logger.append_thread_local_keys(**keys) + logger.info(message) + logger.remove_thread_local_keys(keys.keys()) + logger.info(message) + + thread1_keys = {"exampleThread1Key": "thread1"} + Thread(target=send_message_with_key_and_without, args=("msg", thread1_keys)).start() + + logs = capture_logging_output(stdout) + + assert logs[0].get("exampleThread1Key") == "thread1" + assert logs[1].get("exampleThread1Key") is None + + +def test_clear_thread_key(service_name, stdout): + + logger = Logger( + service=service_name, + stream=stdout, + ) + + def send_message_with_key_and_clear(message, keys): + logger.append_thread_local_keys(**keys) + logger.info(message) + logger.clear_thread_local_keys() + logger.info(message) + + thread1_keys = {"exampleThread1Key": "thread1"} + Thread(target=send_message_with_key_and_clear, args=("msg", thread1_keys)).start() + + logs = capture_logging_output(stdout) + print(logs) + + assert logs[0].get("exampleThread1Key") == "thread1" + assert logs[1].get("exampleThread1Key") is None From 48125236775c5486fff23d9ddaab170a54e6176c Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 12:57:26 -0400 Subject: [PATCH 03/12] Updating documentation --- docs/core/logger.md | 68 ++++++++++++++++++- .../logger/src/append_thread_local_keys.py | 20 ++++++ .../src/append_thread_local_keys_output.json | 20 ++++++ .../logger/src/clear_thread_local_keys.py | 22 ++++++ .../src/clear_thread_local_keys_output.json | 34 ++++++++++ .../logger/src/remove_thread_local_keys.py | 22 ++++++ .../src/remove_thread_local_keys_output.json | 36 ++++++++++ 7 files changed, 221 insertions(+), 1 deletion(-) create mode 100644 examples/logger/src/append_thread_local_keys.py create mode 100644 examples/logger/src/append_thread_local_keys_output.json create mode 100644 examples/logger/src/clear_thread_local_keys.py create mode 100644 examples/logger/src/clear_thread_local_keys_output.json create mode 100644 examples/logger/src/remove_thread_local_keys.py create mode 100644 examples/logger/src/remove_thread_local_keys_output.json diff --git a/docs/core/logger.md b/docs/core/logger.md index 2a45ff08280..e53cb25859b 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -160,12 +160,14 @@ To ease routine tasks like extracting correlation ID from popular event sources, You can append additional keys using either mechanism: * Persist new keys across all future log messages via `append_keys` method +* Persist new keys across all future logs in a specific thread via `append_thread_local_keys` method + * Add additional keys on a per log message basis as a keyword=value, or via `extra` parameter #### append_keys method ???+ warning - `append_keys` is not thread-safe, please see [RFC](https://github.com/aws-powertools/powertools-lambda-python/issues/991){target="_blank"}. + `append_keys` is not thread-safe, use `append_thread_local_keys` instead You can append your own keys to your existing Logger via `append_keys(**additional_key_values)` method. @@ -186,6 +188,22 @@ You can append your own keys to your existing Logger via `append_keys(**addition 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. +#### append_thread_local_keys method + +You can append your own thread-local keys in your existing Logger via the `append_thread_local_keys` method + +=== "append_thread_local_keys.py" + + ```python hl_lines="10" + --8<-- "examples/logger/src/append_thread_local_keys.py" + ``` + +=== "append_thread_local_keys_output.json" + + ```json hl_lines="8 9 17 18" + --8<-- "examples/logger/src/append_thread_local_keys_output.json" + ``` + #### ephemeral metadata You can pass an arbitrary number of keyword arguments (kwargs) to all log level's methods, e.g. `logger.info, logger.warning`. @@ -228,6 +246,17 @@ It accepts any dictionary, and all keyword arguments will be added as part of th ### Removing additional keys +You can remove additional keys using either mechanism: + +* Remove new keys across all future log messages via `remove_keys` method +* Remove new keys across all future logs in a specific thread via `remove_thread_local_keys` method +* Remove **all** new keys across all future logs in a specific thread via `clear_thread_local_keys` method + +???+ danger + Keys added by `append_keys` can only be removed by `remove_keys` and thread-local keys added by `append_thread_local_key` can only be removed by `remove_thread_local_keys` or `clear_thread_local_keys`. Thread-local and normal logger keys are distinct values and can't be manipulated interchangably. + +#### remove_keys method + You can remove any additional key from Logger state using `remove_keys`. === "remove_keys.py" @@ -242,6 +271,40 @@ You can remove any additional key from Logger state using `remove_keys`. --8<-- "examples/logger/src/remove_keys_output.json" ``` +#### remove_thread_local_keys method + +You can remove any additional thread-local keys from Logger using either `remove_thread_local_keys` or `clear_thread_local_keys`. + +Use the `remove_thread_local_keys` method to remove a list of thread-local keys that were previously added using the `append_thread_local_keys` method. + +=== "remove_thread_local_keys.py" + + ```python hl_lines="12" + --8<-- "examples/logger/src/remove_thread_local_keys.py" + ``` + +=== "remove_thread_local_keys_output.json" + + ```json hl_lines="8 9 17 18 26 34" + --8<-- "examples/logger/src/remove_thread_local_keys_output.json" + ``` + +#### clear_thread_local_keys method + +Use the `clear_thread_local_keys` method to remove all thread-local keys that were previously added using the `append_thread_local_keys` method. + +=== "clear_thread_local_keys.py" + + ```python hl_lines="12" + --8<-- "examples/logger/src/clear_thread_local_keys.py" + ``` + +=== "clear_thread_local_keys_output.json" + + ```json hl_lines="8 9 17 18" + --8<-- "examples/logger/src/clear_thread_local_keys_output.json" + ``` + #### Clearing all state Logger is commonly initialized in the global scope. Due to [Lambda Execution Context reuse](https://docs.aws.amazon.com/lambda/latest/dg/runtimes-context.html){target="_blank"}, this means that custom keys can be persisted across invocations. If you want all custom keys to be deleted, you can use `clear_state=True` param in `inject_lambda_context` decorator. @@ -284,6 +347,9 @@ You can view all currently configured keys from the Logger state using the `get_ --8<-- "examples/logger/src/get_current_keys.py" ``` +???+ info + For thread-local additional logging keys, `use get_current_thread_keys` instead + ### Log levels The default log level is `INFO`. It can be set using the `level` constructor option, `setLevel()` method or by using the `POWERTOOLS_LOG_LEVEL` environment variable. diff --git a/examples/logger/src/append_thread_local_keys.py b/examples/logger/src/append_thread_local_keys.py new file mode 100644 index 00000000000..29d21739f4f --- /dev/null +++ b/examples/logger/src/append_thread_local_keys.py @@ -0,0 +1,20 @@ +import threading + +from aws_lambda_powertools import Logger +from aws_lambda_powertools.utilities.typing import LambdaContext + +logger = Logger() + + +def threaded_func(order_id): + logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) + logger.info("Collecting payment") + + +def lambda_handler(event: dict, context: LambdaContext) -> str: + order_ids = event.get("order_ids") + + threading.Thread(target=threaded_func, args=(order_ids[0],)).start() + threading.Thread(target=threaded_func, args=(order_ids[1],)).start() + + return "hello world" diff --git a/examples/logger/src/append_thread_local_keys_output.json b/examples/logger/src/append_thread_local_keys_output.json new file mode 100644 index 00000000000..bb4a9d2d556 --- /dev/null +++ b/examples/logger/src/append_thread_local_keys_output.json @@ -0,0 +1,20 @@ +[ + { + "level": "INFO", + "location": "threaded_func:11", + "message": "Collecting payment", + "timestamp": "2024-09-08 03:04:11,316-0400", + "service": "payment", + "order_id": "order_id_value_1", + "thread_id": "3507187776085958" + }, + { + "level": "INFO", + "location": "threaded_func:11", + "message": "Collecting payment", + "timestamp": "2024-09-08 03:04:11,316-0400", + "service": "payment", + "order_id": "order_id_value_2", + "thread_id": "140718447808512" + } +] \ No newline at end of file diff --git a/examples/logger/src/clear_thread_local_keys.py b/examples/logger/src/clear_thread_local_keys.py new file mode 100644 index 00000000000..ae4e4c964e8 --- /dev/null +++ b/examples/logger/src/clear_thread_local_keys.py @@ -0,0 +1,22 @@ +import threading + +from aws_lambda_powertools import Logger +from aws_lambda_powertools.utilities.typing import LambdaContext + +logger = Logger() + + +def threaded_func(order_id): + logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) + logger.info("Collecting payment") + logger.clear_thread_local_keys() + logger.info("Exiting thread") + + +def lambda_handler(event: dict, context: LambdaContext) -> str: + order_ids = event.get("order_ids") + + threading.Thread(target=threaded_func, args=(order_ids[0],)).start() + threading.Thread(target=threaded_func, args=(order_ids[1],)).start() + + return "hello world" diff --git a/examples/logger/src/clear_thread_local_keys_output.json b/examples/logger/src/clear_thread_local_keys_output.json new file mode 100644 index 00000000000..791e2afd45e --- /dev/null +++ b/examples/logger/src/clear_thread_local_keys_output.json @@ -0,0 +1,34 @@ +[ + { + "level": "INFO", + "location": "threaded_func:11", + "message": "Collecting payment", + "timestamp": "2024-09-08 12:26:10,648-0400", + "service": "payment", + "order_id": "order_id_value_1", + "thread_id": 140077070292544 + }, + { + "level": "INFO", + "location": "threaded_func:11", + "message": "Collecting payment", + "timestamp": "2024-09-08 12:26:10,649-0400", + "service": "payment", + "order_id": "order_id_value_2", + "thread_id": 140077061899840 + }, + { + "level": "INFO", + "location": "threaded_func:13", + "message": "Exiting thread", + "timestamp": "2024-09-08 12:26:10,649-0400", + "service": "payment" + }, + { + "level": "INFO", + "location": "threaded_func:13", + "message": "Exiting thread", + "timestamp": "2024-09-08 12:26:10,649-0400", + "service": "payment" + } +] diff --git a/examples/logger/src/remove_thread_local_keys.py b/examples/logger/src/remove_thread_local_keys.py new file mode 100644 index 00000000000..24e73b7d94b --- /dev/null +++ b/examples/logger/src/remove_thread_local_keys.py @@ -0,0 +1,22 @@ +import threading + +from aws_lambda_powertools import Logger +from aws_lambda_powertools.utilities.typing import LambdaContext + +logger = Logger() + + +def threaded_func(order_id): + logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) + logger.info("Collecting payment") + logger.remove_thread_local_keys(["order_id"]) + logger.info("Exiting thread") + + +def lambda_handler(event: dict, context: LambdaContext) -> str: + order_ids = event.get("order_ids") + + threading.Thread(target=threaded_func, args=(order_ids[0],)).start() + threading.Thread(target=threaded_func, args=(order_ids[1],)).start() + + return "hello world" diff --git a/examples/logger/src/remove_thread_local_keys_output.json b/examples/logger/src/remove_thread_local_keys_output.json new file mode 100644 index 00000000000..24ff93739b1 --- /dev/null +++ b/examples/logger/src/remove_thread_local_keys_output.json @@ -0,0 +1,36 @@ +[ + { + "level": "INFO", + "location": "threaded_func:11", + "message": "Collecting payment", + "timestamp": "2024-09-08 12:26:10,648-0400", + "service": "payment", + "order_id": "order_id_value_1", + "thread_id": 140077070292544 + }, + { + "level": "INFO", + "location": "threaded_func:11", + "message": "Collecting payment", + "timestamp": "2024-09-08 12:26:10,649-0400", + "service": "payment", + "order_id": "order_id_value_2", + "thread_id": 140077061899840 + }, + { + "level": "INFO", + "location": "threaded_func:13", + "message": "Exiting thread", + "timestamp": "2024-09-08 12:26:10,649-0400", + "service": "payment", + "thread_id": 140077070292544 + }, + { + "level": "INFO", + "location": "threaded_func:13", + "message": "Exiting thread", + "timestamp": "2024-09-08 12:26:10,649-0400", + "service": "payment", + "thread_id": 140077061899840 + } +] From cc05730d68c9bd6dfed9be4f8cba6ee2ba525a10 Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 13:13:00 -0400 Subject: [PATCH 04/12] Cleanup --- aws_lambda_powertools/logging/formatter.py | 2 +- .../test_logger_powertools_formatter.py | 34 ++++++++++++------- 2 files changed, 22 insertions(+), 14 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index e23ddadc04e..2f496bdaebf 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -371,7 +371,7 @@ def _extract_log_keys(self, log_record: logging.LogRecord) -> dict[str, Any]: record_dict["asctime"] = self.formatTime(record=log_record) extras = {k: v for k, v in record_dict.items() if k not in RESERVED_LOG_ATTRS} - formatted_log: Dict[str, Any] = {} + formatted_log = {} # Iterate over a default or existing log structure # then replace any std log attribute e.g. '%(level)s' to 'INFO', '%(process)d to '4773' diff --git a/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py b/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py index 2a307623f88..6e029edba29 100644 --- a/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py +++ b/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py @@ -434,8 +434,7 @@ def send_thread_message_with_key(message, keys): thread2_keys = {"exampleThread2Key": "thread2"} Thread(target=send_thread_message_with_key, args=("thread2", thread2_keys)).start() - final_log_message = "final log, all thread keys gone" - logger.info(final_log_message) + logger.info("final log, all thread keys gone") logs = capture_logging_output(stdout) @@ -455,16 +454,6 @@ def send_thread_message_with_key(message, keys): def test_remove_thread_key(service_name, stdout): - """ - Tests that global and thread safe logger keys work as expected - 1. Log with no keys attached - 2. Log with only global key - 3. Create two threads and validate: - - Keys added in one thread isn't in another - - Global keys are still present - 4. After threading is done, thread keys don't show up - """ - logger = Logger( service=service_name, stream=stdout, @@ -486,7 +475,6 @@ def send_message_with_key_and_without(message, keys): def test_clear_thread_key(service_name, stdout): - logger = Logger( service=service_name, stream=stdout, @@ -506,3 +494,23 @@ def send_message_with_key_and_clear(message, keys): assert logs[0].get("exampleThread1Key") == "thread1" assert logs[1].get("exampleThread1Key") is None + + +def test_get_thread_key(service_name, stdout): + logger = Logger( + service=service_name, + stream=stdout, + ) + + def send_message_with_key_and_get(message, keys): + logger.append_thread_local_keys(**keys) + logger.info(logger.get_current_thread_keys()) + + thread1_keys = {"exampleThread1Key": "thread1"} + Thread(target=send_message_with_key_and_get, args=("msg", thread1_keys)).start() + + logs = capture_logging_output(stdout) + print(logs) + + assert logs[0].get("exampleThread1Key") == "thread1" + assert logs[0].get("message") == thread1_keys From 6fb4413aa5c4e13d301653a7f285a31e71242756 Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 13:50:05 -0400 Subject: [PATCH 05/12] Small fixes for linting --- aws_lambda_powertools/logging/formatter.py | 2 +- examples/logger/src/append_thread_local_keys.py | 5 +++-- examples/logger/src/clear_thread_local_keys.py | 5 +++-- examples/logger/src/remove_thread_local_keys.py | 5 +++-- 4 files changed, 10 insertions(+), 7 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 2f496bdaebf..e23ddadc04e 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -371,7 +371,7 @@ def _extract_log_keys(self, log_record: logging.LogRecord) -> dict[str, Any]: record_dict["asctime"] = self.formatTime(record=log_record) extras = {k: v for k, v in record_dict.items() if k not in RESERVED_LOG_ATTRS} - formatted_log = {} + formatted_log: Dict[str, Any] = {} # Iterate over a default or existing log structure # then replace any std log attribute e.g. '%(level)s' to 'INFO', '%(process)d to '4773' diff --git a/examples/logger/src/append_thread_local_keys.py b/examples/logger/src/append_thread_local_keys.py index 29d21739f4f..e1faf2f7818 100644 --- a/examples/logger/src/append_thread_local_keys.py +++ b/examples/logger/src/append_thread_local_keys.py @@ -1,4 +1,5 @@ import threading +from typing import List from aws_lambda_powertools import Logger from aws_lambda_powertools.utilities.typing import LambdaContext @@ -6,13 +7,13 @@ logger = Logger() -def threaded_func(order_id): +def threaded_func(order_id: str): logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) logger.info("Collecting payment") def lambda_handler(event: dict, context: LambdaContext) -> str: - order_ids = event.get("order_ids") + order_ids: List[str] = event["order_ids"] threading.Thread(target=threaded_func, args=(order_ids[0],)).start() threading.Thread(target=threaded_func, args=(order_ids[1],)).start() diff --git a/examples/logger/src/clear_thread_local_keys.py b/examples/logger/src/clear_thread_local_keys.py index ae4e4c964e8..b750fdb0cf8 100644 --- a/examples/logger/src/clear_thread_local_keys.py +++ b/examples/logger/src/clear_thread_local_keys.py @@ -1,4 +1,5 @@ import threading +from typing import List from aws_lambda_powertools import Logger from aws_lambda_powertools.utilities.typing import LambdaContext @@ -6,7 +7,7 @@ logger = Logger() -def threaded_func(order_id): +def threaded_func(order_id: str): logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) logger.info("Collecting payment") logger.clear_thread_local_keys() @@ -14,7 +15,7 @@ def threaded_func(order_id): def lambda_handler(event: dict, context: LambdaContext) -> str: - order_ids = event.get("order_ids") + order_ids: List[str] = event["order_ids"] threading.Thread(target=threaded_func, args=(order_ids[0],)).start() threading.Thread(target=threaded_func, args=(order_ids[1],)).start() diff --git a/examples/logger/src/remove_thread_local_keys.py b/examples/logger/src/remove_thread_local_keys.py index 24e73b7d94b..ac83c8b48c0 100644 --- a/examples/logger/src/remove_thread_local_keys.py +++ b/examples/logger/src/remove_thread_local_keys.py @@ -1,4 +1,5 @@ import threading +from typing import List from aws_lambda_powertools import Logger from aws_lambda_powertools.utilities.typing import LambdaContext @@ -6,7 +7,7 @@ logger = Logger() -def threaded_func(order_id): +def threaded_func(order_id: str): logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) logger.info("Collecting payment") logger.remove_thread_local_keys(["order_id"]) @@ -14,7 +15,7 @@ def threaded_func(order_id): def lambda_handler(event: dict, context: LambdaContext) -> str: - order_ids = event.get("order_ids") + order_ids: List[str] = event["order_ids"] threading.Thread(target=threaded_func, args=(order_ids[0],)).start() threading.Thread(target=threaded_func, args=(order_ids[1],)).start() From 4a6423f363d157a64c9d46bc1873d0749b534aa7 Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 13:54:50 -0400 Subject: [PATCH 06/12] Clearing thread local keys with clear_state=True --- aws_lambda_powertools/logging/logger.py | 1 + poetry.toml | 2 ++ 2 files changed, 3 insertions(+) create mode 100644 poetry.toml diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index f7d68c36ee5..d7b68e44cf2 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -645,6 +645,7 @@ def structure_logs(self, append: bool = False, formatter_options: dict | None = # Mode 3 self.registered_formatter.clear_state() + self.registered_formatter.clear_thread_local_keys() self.registered_formatter.append_keys(**log_keys) def set_correlation_id(self, value: str | None) -> None: diff --git a/poetry.toml b/poetry.toml new file mode 100644 index 00000000000..ab1033bd372 --- /dev/null +++ b/poetry.toml @@ -0,0 +1,2 @@ +[virtualenvs] +in-project = true From 1ccd3b61966e13aedd9243bd708af79fdbfc0c50 Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 14:22:46 -0400 Subject: [PATCH 07/12] Cleaning up PR --- docs/core/logger.md | 6 +++--- poetry.toml | 2 -- 2 files changed, 3 insertions(+), 5 deletions(-) delete mode 100644 poetry.toml diff --git a/docs/core/logger.md b/docs/core/logger.md index e53cb25859b..cdfd60d2616 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -279,7 +279,7 @@ Use the `remove_thread_local_keys` method to remove a list of thread-local keys === "remove_thread_local_keys.py" - ```python hl_lines="12" + ```python hl_lines="13" --8<-- "examples/logger/src/remove_thread_local_keys.py" ``` @@ -295,7 +295,7 @@ Use the `clear_thread_local_keys` method to remove all thread-local keys that we === "clear_thread_local_keys.py" - ```python hl_lines="12" + ```python hl_lines="13" --8<-- "examples/logger/src/clear_thread_local_keys.py" ``` @@ -348,7 +348,7 @@ You can view all currently configured keys from the Logger state using the `get_ ``` ???+ info - For thread-local additional logging keys, `use get_current_thread_keys` instead + For thread-local additional logging keys, use `get_current_thread_keys` instead ### Log levels diff --git a/poetry.toml b/poetry.toml deleted file mode 100644 index ab1033bd372..00000000000 --- a/poetry.toml +++ /dev/null @@ -1,2 +0,0 @@ -[virtualenvs] -in-project = true From 06b989be626a3b6b8fda6c4cf83cca34d7942ac0 Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Sun, 8 Sep 2024 14:41:51 -0400 Subject: [PATCH 08/12] Small fixes to docs --- docs/core/logger.md | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index cdfd60d2616..b74f8a56b45 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -159,9 +159,8 @@ To ease routine tasks like extracting correlation ID from popular event sources, You can append additional keys using either mechanism: -* Persist new keys across all future log messages via `append_keys` method -* Persist new keys across all future logs in a specific thread via `append_thread_local_keys` method - +* New keys persist across all future log messages via `append_keys` method +* New keys persist across all future logs in a specific thread via `append_thread_local_keys` method * Add additional keys on a per log message basis as a keyword=value, or via `extra` parameter #### append_keys method @@ -194,7 +193,7 @@ You can append your own thread-local keys in your existing Logger via the `appen === "append_thread_local_keys.py" - ```python hl_lines="10" + ```python hl_lines="11" --8<-- "examples/logger/src/append_thread_local_keys.py" ``` From 179ef9acb307490ebc370eb122baed4f5838dd38 Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Mon, 9 Sep 2024 15:02:04 -0400 Subject: [PATCH 09/12] Fixing type annotations for THREAD_LOCAL_KEYS --- aws_lambda_powertools/logging/formatter.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index e23ddadc04e..f093ab81e4a 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -417,10 +417,10 @@ def _strip_none_records(records: dict[str, Any]) -> dict[str, Any]: RESERVED_FORMATTER_CUSTOM_KEYS: list[str] = inspect.getfullargspec(LambdaPowertoolsFormatter).args[1:] # ContextVar for thread local keys -THREAD_LOCAL_KEYS: ContextVar[dict[Any, Any]] = ContextVar("THREAD_LOCAL_KEYS", default={}) +THREAD_LOCAL_KEYS: ContextVar[dict[str, Any]] = ContextVar("THREAD_LOCAL_KEYS", default={}) -def _get_context() -> ContextVar[dict[Any, Any]]: +def _get_context() -> ContextVar[dict[str, Any]]: return THREAD_LOCAL_KEYS From 4b9e5ca4ec7a09dfd3722aab068419eeb99176fc Mon Sep 17 00:00:00 2001 From: SimonBFrank Date: Mon, 9 Sep 2024 15:11:37 -0400 Subject: [PATCH 10/12] Replacing '|' with {**dict1, **dict2} due to support of Python < 3.9 --- aws_lambda_powertools/logging/formatter.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index f093ab81e4a..4b4ddfe9faa 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -430,7 +430,7 @@ def clear_context_keys() -> None: def set_context_keys(**kwargs: Dict[str, Any]) -> None: context = _get_context() - context.set(context.get() | kwargs) + context.set({**context.get(), **kwargs}) def remove_context_keys(keys: Iterable[str]) -> None: From 497ac41c89c7d3deb7dea5db90f2d114b1906578 Mon Sep 17 00:00:00 2001 From: Simon Thulbourn Date: Fri, 27 Sep 2024 13:26:26 +0000 Subject: [PATCH 11/12] fix types from v2 to v3 --- aws_lambda_powertools/logging/formatter.py | 8 ++++---- aws_lambda_powertools/logging/logger.py | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 4b4ddfe9faa..ad6d3a8392f 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -57,7 +57,7 @@ def append_thread_local_keys(self, **additional_keys) -> None: def get_current_keys(self) -> dict[str, Any]: return {} - def get_current_thread_keys(self) -> Dict[str, Any]: + def get_current_thread_keys(self) -> dict[str, Any]: return {} def remove_keys(self, keys: Iterable[str]) -> None: @@ -256,7 +256,7 @@ def append_thread_local_keys(self, **additional_keys) -> None: def get_current_keys(self) -> dict[str, Any]: return self.log_format - def get_current_thread_keys(self) -> Dict[str, Any]: + def get_current_thread_keys(self) -> dict[str, Any]: return _get_context().get() def remove_keys(self, keys: Iterable[str]) -> None: @@ -371,7 +371,7 @@ def _extract_log_keys(self, log_record: logging.LogRecord) -> dict[str, Any]: record_dict["asctime"] = self.formatTime(record=log_record) extras = {k: v for k, v in record_dict.items() if k not in RESERVED_LOG_ATTRS} - formatted_log: Dict[str, Any] = {} + formatted_log: dict[str, Any] = {} # Iterate over a default or existing log structure # then replace any std log attribute e.g. '%(level)s' to 'INFO', '%(process)d to '4773' @@ -428,7 +428,7 @@ def clear_context_keys() -> None: _get_context().set({}) -def set_context_keys(**kwargs: Dict[str, Any]) -> None: +def set_context_keys(**kwargs: dict[str, Any]) -> None: context = _get_context() context.set({**context.get(), **kwargs}) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index d7b68e44cf2..cb8cfc06c34 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -589,7 +589,7 @@ def append_thread_local_keys(self, **additional_keys: object) -> None: def get_current_keys(self) -> dict[str, Any]: return self.registered_formatter.get_current_keys() - def get_current_thread_keys(self) -> Dict[str, Any]: + def get_current_thread_keys(self) -> dict[str, Any]: return self.registered_formatter.get_current_thread_keys() def remove_keys(self, keys: Iterable[str]) -> None: From 5ca395a09ffb10c15ee71d602f39c4d251f744ba Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Mon, 21 Oct 2024 20:11:21 +0100 Subject: [PATCH 12/12] Changing documentation and method names --- aws_lambda_powertools/logging/formatter.py | 48 ++++--- aws_lambda_powertools/logging/logger.py | 28 ++-- docs/core/event_handler/api_gateway.md | 3 +- docs/core/logger.md | 121 ++++++++++-------- ...cal_keys.py => thread_safe_append_keys.py} | 2 +- ...on => thread_safe_append_keys_output.json} | 0 ...ocal_keys.py => thread_safe_clear_keys.py} | 4 +- ...son => thread_safe_clear_keys_output.json} | 0 .../src/thread_safe_get_current_keys.py | 14 ++ ...cal_keys.py => thread_safe_remove_keys.py} | 4 +- ...on => thread_safe_remove_keys_output.json} | 0 .../event_handler/_pydantic/conftest.py | 4 +- .../test_logger_powertools_formatter.py | 22 ++-- 13 files changed, 145 insertions(+), 105 deletions(-) rename examples/logger/src/{append_thread_local_keys.py => thread_safe_append_keys.py} (85%) rename examples/logger/src/{append_thread_local_keys_output.json => thread_safe_append_keys_output.json} (100%) rename examples/logger/src/{clear_thread_local_keys.py => thread_safe_clear_keys.py} (81%) rename examples/logger/src/{clear_thread_local_keys_output.json => thread_safe_clear_keys_output.json} (100%) create mode 100644 examples/logger/src/thread_safe_get_current_keys.py rename examples/logger/src/{remove_thread_local_keys.py => thread_safe_remove_keys.py} (80%) rename examples/logger/src/{remove_thread_local_keys_output.json => thread_safe_remove_keys_output.json} (100%) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index ad6d3a8392f..07db499d1fc 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -51,27 +51,29 @@ class BasePowertoolsFormatter(logging.Formatter, metaclass=ABCMeta): def append_keys(self, **additional_keys) -> None: raise NotImplementedError() - def append_thread_local_keys(self, **additional_keys) -> None: - raise NotImplementedError() - def get_current_keys(self) -> dict[str, Any]: return {} - def get_current_thread_keys(self) -> dict[str, Any]: - return {} - def remove_keys(self, keys: Iterable[str]) -> None: raise NotImplementedError() - def remove_thread_local_keys(self, keys: Iterable[str]) -> None: - raise NotImplementedError() - @abstractmethod def clear_state(self) -> None: """Removes any previously added logging keys""" raise NotImplementedError() - def clear_thread_local_keys(self) -> None: + # These specific thread-safe methods are necessary to manage shared context in concurrent environments. + # They prevent race conditions and ensure data consistency across multiple threads. + def thread_safe_append_keys(self, **additional_keys) -> None: + raise NotImplementedError() + + def thread_safe_get_current_keys(self) -> dict[str, Any]: + return {} + + def thread_safe_remove_keys(self, keys: Iterable[str]) -> None: + raise NotImplementedError() + + def thread_safe_clear_keys(self) -> None: """Removes any previously added logging keys in a specific thread""" raise NotImplementedError() @@ -250,27 +252,33 @@ def formatTime(self, record: logging.LogRecord, datefmt: str | None = None) -> s def append_keys(self, **additional_keys) -> None: self.log_format.update(additional_keys) - def append_thread_local_keys(self, **additional_keys) -> None: - set_context_keys(**additional_keys) - def get_current_keys(self) -> dict[str, Any]: return self.log_format - def get_current_thread_keys(self) -> dict[str, Any]: - return _get_context().get() - def remove_keys(self, keys: Iterable[str]) -> None: for key in keys: self.log_format.pop(key, None) - def remove_thread_local_keys(self, keys: Iterable[str]) -> None: - remove_context_keys(keys) - def clear_state(self) -> None: self.log_format = dict.fromkeys(self.log_record_order) self.log_format.update(**self.keys_combined) - def clear_thread_local_keys(self) -> None: + # These specific thread-safe methods are necessary to manage shared context in concurrent environments. + # They prevent race conditions and ensure data consistency across multiple threads. + def thread_safe_append_keys(self, **additional_keys) -> None: + # Append additional key-value pairs to the context safely in a thread-safe manner. + set_context_keys(**additional_keys) + + def thread_safe_get_current_keys(self) -> dict[str, Any]: + # Retrieve the current context keys safely in a thread-safe manner. + return _get_context().get() + + def thread_safe_remove_keys(self, keys: Iterable[str]) -> None: + # Remove specified keys from the context safely in a thread-safe manner. + remove_context_keys(keys) + + def thread_safe_clear_keys(self) -> None: + # Clear all keys from the context safely in a thread-safe manner. clear_context_keys() @staticmethod diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index cb8cfc06c34..acefe9757c6 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -583,23 +583,29 @@ def debug( def append_keys(self, **additional_keys: object) -> None: self.registered_formatter.append_keys(**additional_keys) - def append_thread_local_keys(self, **additional_keys: object) -> None: - self.registered_formatter.append_thread_local_keys(**additional_keys) - def get_current_keys(self) -> dict[str, Any]: return self.registered_formatter.get_current_keys() - def get_current_thread_keys(self) -> dict[str, Any]: - return self.registered_formatter.get_current_thread_keys() - def remove_keys(self, keys: Iterable[str]) -> None: self.registered_formatter.remove_keys(keys) - def remove_thread_local_keys(self, keys: Iterable[str]) -> None: - self.registered_formatter.remove_thread_local_keys(keys) + # These specific thread-safe methods are necessary to manage shared context in concurrent environments. + # They prevent race conditions and ensure data consistency across multiple threads. + def thread_safe_append_keys(self, **additional_keys: object) -> None: + # Append additional key-value pairs to the context safely in a thread-safe manner. + self.registered_formatter.thread_safe_append_keys(**additional_keys) + + def thread_safe_get_current_keys(self) -> dict[str, Any]: + # Retrieve the current context keys safely in a thread-safe manner. + return self.registered_formatter.thread_safe_get_current_keys() + + def thread_safe_remove_keys(self, keys: Iterable[str]) -> None: + # Remove specified keys from the context safely in a thread-safe manner. + self.registered_formatter.thread_safe_remove_keys(keys) - def clear_thread_local_keys(self) -> None: - self.registered_formatter.clear_thread_local_keys() + def thread_safe_clear_keys(self) -> None: + # Clear all keys from the context safely in a thread-safe manner. + self.registered_formatter.thread_safe_clear_keys() def structure_logs(self, append: bool = False, formatter_options: dict | None = None, **keys) -> None: """Sets logging formatting to JSON. @@ -645,7 +651,7 @@ def structure_logs(self, append: bool = False, formatter_options: dict | None = # Mode 3 self.registered_formatter.clear_state() - self.registered_formatter.clear_thread_local_keys() + self.registered_formatter.thread_safe_clear_keys() self.registered_formatter.append_keys(**log_keys) def set_correlation_id(self, value: str | None) -> None: diff --git a/docs/core/event_handler/api_gateway.md b/docs/core/event_handler/api_gateway.md index cba8addfdd0..c4082b43ca2 100644 --- a/docs/core/event_handler/api_gateway.md +++ b/docs/core/event_handler/api_gateway.md @@ -128,11 +128,12 @@ Here's an example on how we can handle the `/todos` path. When using Amazon API Gateway HTTP API to front your Lambda functions, you can use `APIGatewayHttpResolver`. + ???+ note Using HTTP API v1 payload? Use `APIGatewayRestResolver` instead. `APIGatewayHttpResolver` defaults to v2 payload. - If you're using Terraform to deploy a HTTP API, note that it defaults the [payload_format_version](https://registry.terraform.io/providers/hashicorp/aws/latest/docs/resources/apigatewayv2_integration#payload_format_version){target="_blank" rel="nofollow"} value to 1.0 if not specified. + ```python hl_lines="5 11" title="Using HTTP API resolver" --8<-- "examples/event_handler_rest/src/getting_started_http_api_resolver.py" diff --git a/docs/core/logger.md b/docs/core/logger.md index b74f8a56b45..818d5a6589b 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -160,13 +160,13 @@ To ease routine tasks like extracting correlation ID from popular event sources, You can append additional keys using either mechanism: * New keys persist across all future log messages via `append_keys` method -* New keys persist across all future logs in a specific thread via `append_thread_local_keys` method * Add additional keys on a per log message basis as a keyword=value, or via `extra` parameter +* New keys persist across all future logs in a specific thread via `thread_safe_append_keys` method. Check [Working with thread-safe keys](#working-with-thread-safe-keys) section. #### append_keys method ???+ warning - `append_keys` is not thread-safe, use `append_thread_local_keys` instead + `append_keys` is not thread-safe, use [thread_safe_append_keys](#appending-thread-safe-additional-keys) instead You can append your own keys to your existing Logger via `append_keys(**additional_key_values)` method. @@ -187,22 +187,6 @@ You can append your own keys to your existing Logger via `append_keys(**addition 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. -#### append_thread_local_keys method - -You can append your own thread-local keys in your existing Logger via the `append_thread_local_keys` method - -=== "append_thread_local_keys.py" - - ```python hl_lines="11" - --8<-- "examples/logger/src/append_thread_local_keys.py" - ``` - -=== "append_thread_local_keys_output.json" - - ```json hl_lines="8 9 17 18" - --8<-- "examples/logger/src/append_thread_local_keys_output.json" - ``` - #### ephemeral metadata You can pass an arbitrary number of keyword arguments (kwargs) to all log level's methods, e.g. `logger.info, logger.warning`. @@ -248,11 +232,10 @@ It accepts any dictionary, and all keyword arguments will be added as part of th You can remove additional keys using either mechanism: * Remove new keys across all future log messages via `remove_keys` method -* Remove new keys across all future logs in a specific thread via `remove_thread_local_keys` method -* Remove **all** new keys across all future logs in a specific thread via `clear_thread_local_keys` method +* Remove keys persist across all future logs in a specific thread via `thread_safe_remove_keys` method. Check [Working with thread-safe keys](#working-with-thread-safe-keys) section. ???+ danger - Keys added by `append_keys` can only be removed by `remove_keys` and thread-local keys added by `append_thread_local_key` can only be removed by `remove_thread_local_keys` or `clear_thread_local_keys`. Thread-local and normal logger keys are distinct values and can't be manipulated interchangably. + Keys added by `append_keys` can only be removed by `remove_keys` and thread-local keys added by `thread_safe_append_keys` can only be removed by `thread_safe_remove_keys` or `thread_safe_clear_keys`. Thread-local and normal logger keys are distinct values and can't be manipulated interchangeably. #### remove_keys method @@ -270,40 +253,6 @@ You can remove any additional key from Logger state using `remove_keys`. --8<-- "examples/logger/src/remove_keys_output.json" ``` -#### remove_thread_local_keys method - -You can remove any additional thread-local keys from Logger using either `remove_thread_local_keys` or `clear_thread_local_keys`. - -Use the `remove_thread_local_keys` method to remove a list of thread-local keys that were previously added using the `append_thread_local_keys` method. - -=== "remove_thread_local_keys.py" - - ```python hl_lines="13" - --8<-- "examples/logger/src/remove_thread_local_keys.py" - ``` - -=== "remove_thread_local_keys_output.json" - - ```json hl_lines="8 9 17 18 26 34" - --8<-- "examples/logger/src/remove_thread_local_keys_output.json" - ``` - -#### clear_thread_local_keys method - -Use the `clear_thread_local_keys` method to remove all thread-local keys that were previously added using the `append_thread_local_keys` method. - -=== "clear_thread_local_keys.py" - - ```python hl_lines="13" - --8<-- "examples/logger/src/clear_thread_local_keys.py" - ``` - -=== "clear_thread_local_keys_output.json" - - ```json hl_lines="8 9 17 18" - --8<-- "examples/logger/src/clear_thread_local_keys_output.json" - ``` - #### Clearing all state Logger is commonly initialized in the global scope. Due to [Lambda Execution Context reuse](https://docs.aws.amazon.com/lambda/latest/dg/runtimes-context.html){target="_blank"}, this means that custom keys can be persisted across invocations. If you want all custom keys to be deleted, you can use `clear_state=True` param in `inject_lambda_context` decorator. @@ -538,6 +487,68 @@ You can use any of the following built-in JMESPath expressions as part of [injec | **APPLICATION_LOAD_BALANCER** | `'headers."x-amzn-trace-id"'` | ALB X-Ray Trace ID | | **EVENT_BRIDGE** | `"id"` | EventBridge Event ID | +### Working with thread-safe keys + +#### Appending thread-safe additional keys + +You can append your own thread-local keys in your existing Logger via the `thread_safe_append_keys` method + +=== "thread_safe_append_keys.py" + + ```python hl_lines="11" + --8<-- "examples/logger/src/thread_safe_append_keys.py" + ``` + +=== "thread_safe_append_keys_output.json" + + ```json hl_lines="8 9 17 18" + --8<-- "examples/logger/src/thread_safe_append_keys_output.json" + ``` + +#### Removing thread-safe additional keys + +You can remove any additional thread-local keys from Logger using either `thread_safe_remove_keys` or `thread_safe_clear_keys`. + +Use the `thread_safe_remove_keys` method to remove a list of thread-local keys that were previously added using the `thread_safe_append_keys` method. + +=== "thread_safe_remove_keys.py" + + ```python hl_lines="13" + --8<-- "examples/logger/src/thread_safe_remove_keys.py" + ``` + +=== "thread_safe_remove_keys_output.json" + + ```json hl_lines="8 9 17 18 26 34" + --8<-- "examples/logger/src/thread_safe_remove_keys_output.json" + ``` + +#### Clearing thread-safe additional keys + +Use the `thread_safe_clear_keys` method to remove all thread-local keys that were previously added using the `thread_safe_append_keys` method. + +=== "thread_safe_clear_keys.py" + + ```python hl_lines="13" + --8<-- "examples/logger/src/thread_safe_clear_keys.py" + ``` + +=== "thread_safe_clear_keys_output.json" + + ```json hl_lines="8 9 17 18" + --8<-- "examples/logger/src/thread_safe_clear_keys_output.json" + ``` + +#### Accessing thread-safe currently keys + +You can view all currently thread-local keys from the Logger state using the `thread_safe_get_current_keys()` method. This method is useful when you need to avoid overwriting keys that are already configured. + +=== "thread_safe_get_current_keys.py" + + ```python hl_lines="13" + --8<-- "examples/logger/src/thread_safe_get_current_keys.py" + ``` + ### Reusing Logger across your code Similar to [Tracer](./tracer.md#reusing-tracer-across-your-code){target="_blank"}, a new instance that uses the same `service` name will reuse a previous Logger instance. diff --git a/examples/logger/src/append_thread_local_keys.py b/examples/logger/src/thread_safe_append_keys.py similarity index 85% rename from examples/logger/src/append_thread_local_keys.py rename to examples/logger/src/thread_safe_append_keys.py index e1faf2f7818..716d5eef8b4 100644 --- a/examples/logger/src/append_thread_local_keys.py +++ b/examples/logger/src/thread_safe_append_keys.py @@ -8,7 +8,7 @@ def threaded_func(order_id: str): - logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) + logger.thread_safe_append_keys(order_id=order_id, thread_id=threading.get_ident()) logger.info("Collecting payment") diff --git a/examples/logger/src/append_thread_local_keys_output.json b/examples/logger/src/thread_safe_append_keys_output.json similarity index 100% rename from examples/logger/src/append_thread_local_keys_output.json rename to examples/logger/src/thread_safe_append_keys_output.json diff --git a/examples/logger/src/clear_thread_local_keys.py b/examples/logger/src/thread_safe_clear_keys.py similarity index 81% rename from examples/logger/src/clear_thread_local_keys.py rename to examples/logger/src/thread_safe_clear_keys.py index b750fdb0cf8..607e9766d0d 100644 --- a/examples/logger/src/clear_thread_local_keys.py +++ b/examples/logger/src/thread_safe_clear_keys.py @@ -8,9 +8,9 @@ def threaded_func(order_id: str): - logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) + logger.thread_safe_append_keys(order_id=order_id, thread_id=threading.get_ident()) logger.info("Collecting payment") - logger.clear_thread_local_keys() + logger.thread_safe_clear_keys() logger.info("Exiting thread") diff --git a/examples/logger/src/clear_thread_local_keys_output.json b/examples/logger/src/thread_safe_clear_keys_output.json similarity index 100% rename from examples/logger/src/clear_thread_local_keys_output.json rename to examples/logger/src/thread_safe_clear_keys_output.json diff --git a/examples/logger/src/thread_safe_get_current_keys.py b/examples/logger/src/thread_safe_get_current_keys.py new file mode 100644 index 00000000000..b9b67a20cf2 --- /dev/null +++ b/examples/logger/src/thread_safe_get_current_keys.py @@ -0,0 +1,14 @@ +from aws_lambda_powertools import Logger +from aws_lambda_powertools.utilities.typing import LambdaContext + +logger = Logger() + + +@logger.inject_lambda_context +def lambda_handler(event: dict, context: LambdaContext) -> str: + logger.info("Collecting payment") + + if "order" not in logger.thread_safe_get_current_keys(): + logger.thread_safe_append_keys(order=event.get("order")) + + return "hello world" diff --git a/examples/logger/src/remove_thread_local_keys.py b/examples/logger/src/thread_safe_remove_keys.py similarity index 80% rename from examples/logger/src/remove_thread_local_keys.py rename to examples/logger/src/thread_safe_remove_keys.py index ac83c8b48c0..b9e4c918daf 100644 --- a/examples/logger/src/remove_thread_local_keys.py +++ b/examples/logger/src/thread_safe_remove_keys.py @@ -8,9 +8,9 @@ def threaded_func(order_id: str): - logger.append_thread_local_keys(order_id=order_id, thread_id=threading.get_ident()) + logger.thread_safe_append_keys(order_id=order_id, thread_id=threading.get_ident()) logger.info("Collecting payment") - logger.remove_thread_local_keys(["order_id"]) + logger.thread_safe_remove_keys(["order_id"]) logger.info("Exiting thread") diff --git a/examples/logger/src/remove_thread_local_keys_output.json b/examples/logger/src/thread_safe_remove_keys_output.json similarity index 100% rename from examples/logger/src/remove_thread_local_keys_output.json rename to examples/logger/src/thread_safe_remove_keys_output.json diff --git a/tests/functional/event_handler/_pydantic/conftest.py b/tests/functional/event_handler/_pydantic/conftest.py index 1d38e2e26b1..6dd0b6d14a0 100644 --- a/tests/functional/event_handler/_pydantic/conftest.py +++ b/tests/functional/event_handler/_pydantic/conftest.py @@ -97,7 +97,7 @@ def pydanticv2_only(): def openapi30_schema(): from urllib.request import urlopen - f = urlopen("https://raw.githubusercontent.com/OAI/OpenAPI-Specification/main/schemas/v3.0/schema.json") + f = urlopen("https://spec.openapis.org/oas/3.0/schema/2021-09-28") data = json.loads(f.read().decode("utf-8")) return fastjsonschema.compile( data, @@ -109,7 +109,7 @@ def openapi30_schema(): def openapi31_schema(): from urllib.request import urlopen - f = urlopen("https://raw.githubusercontent.com/OAI/OpenAPI-Specification/main/schemas/v3.1/schema.json") + f = urlopen("https://spec.openapis.org/oas/3.1/schema/2022-10-07") data = json.loads(f.read().decode("utf-8")) return fastjsonschema.compile( data, diff --git a/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py b/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py index 6e029edba29..fdf4c0dd392 100644 --- a/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py +++ b/tests/functional/logger/required_dependencies/test_logger_powertools_formatter.py @@ -415,14 +415,14 @@ def handler(event, context): assert "stack_trace" not in log -def test_thread_keys_encapsulation(service_name, stdout): +def test_thread_safe_keys_encapsulation(service_name, stdout): logger = Logger( service=service_name, stream=stdout, ) def send_thread_message_with_key(message, keys): - logger.append_thread_local_keys(**keys) + logger.thread_safe_append_keys(**keys) logger.info(message) global_key = {"exampleKey": "globalKey"} @@ -453,16 +453,16 @@ def send_thread_message_with_key(message, keys): assert logs[3].get("exampleThread2Key") is None -def test_remove_thread_key(service_name, stdout): +def test_thread_safe_remove_key(service_name, stdout): logger = Logger( service=service_name, stream=stdout, ) def send_message_with_key_and_without(message, keys): - logger.append_thread_local_keys(**keys) + logger.thread_safe_append_keys(**keys) logger.info(message) - logger.remove_thread_local_keys(keys.keys()) + logger.thread_safe_remove_keys(keys.keys()) logger.info(message) thread1_keys = {"exampleThread1Key": "thread1"} @@ -474,16 +474,16 @@ def send_message_with_key_and_without(message, keys): assert logs[1].get("exampleThread1Key") is None -def test_clear_thread_key(service_name, stdout): +def test_thread_safe_clear_key(service_name, stdout): logger = Logger( service=service_name, stream=stdout, ) def send_message_with_key_and_clear(message, keys): - logger.append_thread_local_keys(**keys) + logger.thread_safe_append_keys(**keys) logger.info(message) - logger.clear_thread_local_keys() + logger.thread_safe_clear_keys() logger.info(message) thread1_keys = {"exampleThread1Key": "thread1"} @@ -496,15 +496,15 @@ def send_message_with_key_and_clear(message, keys): assert logs[1].get("exampleThread1Key") is None -def test_get_thread_key(service_name, stdout): +def test_thread_safe_getkey(service_name, stdout): logger = Logger( service=service_name, stream=stdout, ) def send_message_with_key_and_get(message, keys): - logger.append_thread_local_keys(**keys) - logger.info(logger.get_current_thread_keys()) + logger.thread_safe_append_keys(**keys) + logger.info(logger.thread_safe_get_current_keys()) thread1_keys = {"exampleThread1Key": "thread1"} Thread(target=send_message_with_key_and_get, args=("msg", thread1_keys)).start()