From faec4ce49194f619513227173f0d7ab070156d15 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 8 Jun 2021 09:46:06 +0200 Subject: [PATCH 1/4] feat(logger): add option to clear state per invocation --- aws_lambda_powertools/logging/logger.py | 19 +++++-- docs/core/logger.md | 72 ++++++++++++++++++++++++- tests/functional/test_logger.py | 20 +++++++ 3 files changed, 106 insertions(+), 5 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 3231f30eccd..ca01a5762a0 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -260,12 +260,18 @@ def _configure_sampling(self): ) def inject_lambda_context( - self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None, correlation_id_path: str = None + self, + lambda_handler: Callable[[Dict, Any], Any] = None, + log_event: bool = None, + correlation_id_path: str = None, + clear_custom_keys: bool = False, ): """Decorator to capture Lambda contextual info and inject into logger Parameters ---------- + clear_custom_keys : bool, optional + Instructs logger to remove any custom keys previously added lambda_handler : Callable Method to inject the lambda context log_event : bool, optional @@ -311,7 +317,10 @@ def handler(event, context): 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 + self.inject_lambda_context, + log_event=log_event, + correlation_id_path=correlation_id_path, + clear_custom_keys=clear_custom_keys, ) log_event = resolve_truthy_env_var_choice( @@ -322,7 +331,11 @@ def handler(event, context): def decorate(event, context): lambda_context = build_lambda_context_model(context) cold_start = _is_cold_start() - self.append_keys(cold_start=cold_start, **lambda_context.__dict__) + + if clear_custom_keys: + self.structure_logs(cold_start=cold_start, **lambda_context.__dict__) + else: + self.append_keys(cold_start=cold_start, **lambda_context.__dict__) if correlation_id_path: self.set_correlation_id(jmespath.search(correlation_id_path, event)) diff --git a/docs/core/logger.md b/docs/core/logger.md index a544bf91e4b..d0e2f22a6d8 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -231,8 +231,9 @@ We provide [built-in JMESPath expressions](#built-in-correlation-id-expressions) ### Appending additional keys -!!! info "Keys might be persisted across invocations" - Always set additional keys as part of your handler to ensure they have the latest value. Additional keys are kept in memory as part of a Logger instance and might be reused in non-cold start scenarios. +!!! info "Custom keys are persisted across warm invocations" + Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with `clear_custom_keys=True`as explained above. + You can append additional keys using either mechanism: @@ -426,6 +427,73 @@ You can remove any additional key from Logger state using `remove_keys`. } ``` +#### Removing all custom keys + +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), this means that custom keys can be persisted across invocations. If you want all custom keys to be deleted, you can use `clear_custom_keys=True` param in `inject_lambda_context` decorator. + +!!! info + This is useful when you add multiple custom keys conditionally, instead of setting a default `None` value if not present. Any key with `None` value is automatically removed by Logger. + +!!! danger "This can have unintended side effects if you use Layers" + Lambda Layers code is imported before the Lambda handler. + + This means that `clear_custom_keys=True` will instruct Logger to remove any keys previously added before Lambda handler execution proceeds. + + You can either avoid running any code as part of Lambda Layers global scope, or override keys with their latest value as part of handler's execution. + +=== "collect.py" + + ```python hl_lines="5 8" + from aws_lambda_powertools import Logger + + logger = Logger(service="payment") + + @logger.inject_lambda_context(clear_custom_keys=True) + def handler(event, context): + if event.get("special_key"): + # Should only be available in the first request log + # as the second request doesn't contain `special_key` + logger.append_keys(debugging_key="value") + + logger.info("Collecting payment") + ``` + +=== "#1 request" + + ```json hl_lines="7" + { + "level": "INFO", + "location": "collect.handler:10", + "message": "Collecting payment", + "timestamp": "2021-05-03 11:47:12,494+0200", + "service": "payment", + "special_key": "debug_key", + "cold_start": true, + "lambda_function_name": "test", + "lambda_function_memory_size": 128, + "lambda_function_arn": "arn:aws:lambda:eu-west-1:12345678910:function:test", + "lambda_request_id": "52fdfc07-2182-154f-163f-5f0f9a621d72" + } + ``` + +=== "#2 request" + + ```json hl_lines="7" + { + "level": "INFO", + "location": "collect.handler:10", + "message": "Collecting payment", + "timestamp": "2021-05-03 11:47:12,494+0200", + "service": "payment", + "cold_start": false, + "lambda_function_name": "test", + "lambda_function_memory_size": 128, + "lambda_function_arn": "arn:aws:lambda:eu-west-1:12345678910:function:test", + "lambda_request_id": "52fdfc07-2182-154f-163f-5f0f9a621d72" + } + ``` + + ### Logging exceptions Use `logger.exception` method to log contextual information about exceptions. Logger will include `exception_name` and `exception` keys to aid troubleshooting and error enumeration. diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index ba6e82b72af..320c2ea1b7d 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -562,3 +562,23 @@ def handler(event, context): # THEN we should output to a file not stdout log = log_file.read_text() assert "custom handler" in log + + +def test_clear_keys_on_inject_lambda_context(lambda_context, stdout, service_name): + # GIVEN + logger = Logger(service=service_name, stream=stdout) + + # WHEN clear_custom_key is set and a key was conditionally added in the first invocation + @logger.inject_lambda_context(clear_custom_keys=True) + def handler(event, context): + if event.get("add_key"): + logger.append_keys(my_key="value") + logger.info("Foo") + + # THEN custom key should only exist in the first log + handler({"add_key": True}, lambda_context) + handler({}, lambda_context) + + first_log, second_log = capture_multiple_logging_statements_output(stdout) + assert "my_key" in first_log + assert "my_key" not in second_log From 9019f302cc19f7b4cb024f4640cf1ebff8add456 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 8 Jun 2021 09:56:18 +0200 Subject: [PATCH 2/4] refactor: rename to remove_custom_keys --- aws_lambda_powertools/logging/logger.py | 8 ++++---- docs/core/logger.md | 8 ++++---- tests/functional/test_logger.py | 4 ++-- 3 files changed, 10 insertions(+), 10 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index ca01a5762a0..ef64e0d502b 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -264,13 +264,13 @@ def inject_lambda_context( lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None, correlation_id_path: str = None, - clear_custom_keys: bool = False, + remove_custom_keys: bool = False, ): """Decorator to capture Lambda contextual info and inject into logger Parameters ---------- - clear_custom_keys : bool, optional + remove_custom_keys : bool, optional Instructs logger to remove any custom keys previously added lambda_handler : Callable Method to inject the lambda context @@ -320,7 +320,7 @@ def handler(event, context): self.inject_lambda_context, log_event=log_event, correlation_id_path=correlation_id_path, - clear_custom_keys=clear_custom_keys, + remove_custom_keys=remove_custom_keys, ) log_event = resolve_truthy_env_var_choice( @@ -332,7 +332,7 @@ def decorate(event, context): lambda_context = build_lambda_context_model(context) cold_start = _is_cold_start() - if clear_custom_keys: + if remove_custom_keys: self.structure_logs(cold_start=cold_start, **lambda_context.__dict__) else: self.append_keys(cold_start=cold_start, **lambda_context.__dict__) diff --git a/docs/core/logger.md b/docs/core/logger.md index d0e2f22a6d8..b2ac0bf568f 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -232,7 +232,7 @@ We provide [built-in JMESPath expressions](#built-in-correlation-id-expressions) ### Appending additional keys !!! info "Custom keys are persisted across warm invocations" - Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with `clear_custom_keys=True`as explained above. + Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with `remove_custom_keys=True`as explained above. You can append additional keys using either mechanism: @@ -429,7 +429,7 @@ You can remove any additional key from Logger state using `remove_keys`. #### Removing all custom keys -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), this means that custom keys can be persisted across invocations. If you want all custom keys to be deleted, you can use `clear_custom_keys=True` param in `inject_lambda_context` decorator. +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), this means that custom keys can be persisted across invocations. If you want all custom keys to be deleted, you can use `remove_custom_keys=True` param in `inject_lambda_context` decorator. !!! info This is useful when you add multiple custom keys conditionally, instead of setting a default `None` value if not present. Any key with `None` value is automatically removed by Logger. @@ -437,7 +437,7 @@ Logger is commonly initialized in the global scope. Due to [Lambda Execution Con !!! danger "This can have unintended side effects if you use Layers" Lambda Layers code is imported before the Lambda handler. - This means that `clear_custom_keys=True` will instruct Logger to remove any keys previously added before Lambda handler execution proceeds. + This means that `remove_custom_keys=True` will instruct Logger to remove any keys previously added before Lambda handler execution proceeds. You can either avoid running any code as part of Lambda Layers global scope, or override keys with their latest value as part of handler's execution. @@ -448,7 +448,7 @@ Logger is commonly initialized in the global scope. Due to [Lambda Execution Con logger = Logger(service="payment") - @logger.inject_lambda_context(clear_custom_keys=True) + @logger.inject_lambda_context(remove_custom_keys=True) def handler(event, context): if event.get("special_key"): # Should only be available in the first request log diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 320c2ea1b7d..10297ba5e39 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -568,8 +568,8 @@ def test_clear_keys_on_inject_lambda_context(lambda_context, stdout, service_nam # GIVEN logger = Logger(service=service_name, stream=stdout) - # WHEN clear_custom_key is set and a key was conditionally added in the first invocation - @logger.inject_lambda_context(clear_custom_keys=True) + # WHEN remove_custom_keys is set and a key was conditionally added in the first invocation + @logger.inject_lambda_context(remove_custom_keys=True) def handler(event, context): if event.get("add_key"): logger.append_keys(my_key="value") From d1b7c2208269bf7857e8b8e38aaa2f70726ec84d Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 8 Jun 2021 10:00:36 +0200 Subject: [PATCH 3/4] refactor: rename to clear_state --- aws_lambda_powertools/logging/logger.py | 8 ++++---- docs/core/logger.md | 10 +++++----- tests/functional/test_logger.py | 6 +++--- 3 files changed, 12 insertions(+), 12 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index ef64e0d502b..689409d9813 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -264,13 +264,13 @@ def inject_lambda_context( lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None, correlation_id_path: str = None, - remove_custom_keys: bool = False, + clear_state: bool = False, ): """Decorator to capture Lambda contextual info and inject into logger Parameters ---------- - remove_custom_keys : bool, optional + clear_state : bool, optional Instructs logger to remove any custom keys previously added lambda_handler : Callable Method to inject the lambda context @@ -320,7 +320,7 @@ def handler(event, context): self.inject_lambda_context, log_event=log_event, correlation_id_path=correlation_id_path, - remove_custom_keys=remove_custom_keys, + clear_state=clear_state, ) log_event = resolve_truthy_env_var_choice( @@ -332,7 +332,7 @@ def decorate(event, context): lambda_context = build_lambda_context_model(context) cold_start = _is_cold_start() - if remove_custom_keys: + if clear_state: self.structure_logs(cold_start=cold_start, **lambda_context.__dict__) else: self.append_keys(cold_start=cold_start, **lambda_context.__dict__) diff --git a/docs/core/logger.md b/docs/core/logger.md index b2ac0bf568f..675768b3de7 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -232,7 +232,7 @@ We provide [built-in JMESPath expressions](#built-in-correlation-id-expressions) ### Appending additional keys !!! info "Custom keys are persisted across warm invocations" - Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with `remove_custom_keys=True`as explained above. + Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with `clear_state=True`as explained above. You can append additional keys using either mechanism: @@ -427,9 +427,9 @@ You can remove any additional key from Logger state using `remove_keys`. } ``` -#### Removing all custom keys +#### 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), this means that custom keys can be persisted across invocations. If you want all custom keys to be deleted, you can use `remove_custom_keys=True` param in `inject_lambda_context` decorator. +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), 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. !!! info This is useful when you add multiple custom keys conditionally, instead of setting a default `None` value if not present. Any key with `None` value is automatically removed by Logger. @@ -437,7 +437,7 @@ Logger is commonly initialized in the global scope. Due to [Lambda Execution Con !!! danger "This can have unintended side effects if you use Layers" Lambda Layers code is imported before the Lambda handler. - This means that `remove_custom_keys=True` will instruct Logger to remove any keys previously added before Lambda handler execution proceeds. + This means that `clear_state=True` will instruct Logger to remove any keys previously added before Lambda handler execution proceeds. You can either avoid running any code as part of Lambda Layers global scope, or override keys with their latest value as part of handler's execution. @@ -448,7 +448,7 @@ Logger is commonly initialized in the global scope. Due to [Lambda Execution Con logger = Logger(service="payment") - @logger.inject_lambda_context(remove_custom_keys=True) + @logger.inject_lambda_context(clear_state=True) def handler(event, context): if event.get("special_key"): # Should only be available in the first request log diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 10297ba5e39..44249af6250 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -564,12 +564,12 @@ def handler(event, context): assert "custom handler" in log -def test_clear_keys_on_inject_lambda_context(lambda_context, stdout, service_name): +def test_clear_state_on_inject_lambda_context(lambda_context, stdout, service_name): # GIVEN logger = Logger(service=service_name, stream=stdout) - # WHEN remove_custom_keys is set and a key was conditionally added in the first invocation - @logger.inject_lambda_context(remove_custom_keys=True) + # WHEN clear_state is set and a key was conditionally added in the first invocation + @logger.inject_lambda_context(clear_state=True) def handler(event, context): if event.get("add_key"): logger.append_keys(my_key="value") From a6916762e40d12fafb23c9e23b048e56e3f30cdb Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 8 Jun 2021 10:23:44 +0200 Subject: [PATCH 4/4] docs: fix anchor --- 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 675768b3de7..45119ca51d6 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -232,7 +232,7 @@ We provide [built-in JMESPath expressions](#built-in-correlation-id-expressions) ### Appending additional keys !!! info "Custom keys are persisted across warm invocations" - Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with `clear_state=True`as explained above. + Always set additional keys as part of your handler to ensure they have the latest value, or explicitly clear them with [`clear_state=True`](#clearing-all-state). You can append additional keys using either mechanism: