From a7d9001a7623517f106f1900b8964d69cdf3881f Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 30 Aug 2020 17:01:22 +0200 Subject: [PATCH 1/4] feat: add xray_trace_id key when tracing is active #137 --- aws_lambda_powertools/logging/formatter.py | 24 ++++++++++++---- tests/functional/test_aws_lambda_logging.py | 31 +++++++++++++++++++++ 2 files changed, 50 insertions(+), 5 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index bc7923d27eb..4965501a22a 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -1,5 +1,6 @@ import json import logging +import os class JsonFormatter(logging.Formatter): @@ -29,14 +30,27 @@ def __init__(self, **kwargs): # Set the default unserializable function, by default values will be cast as str. self.default_json_formatter = kwargs.pop("json_default", str) # Set the insertion order for the log messages - self.format_dict = dict.fromkeys(kwargs.pop("log_record_order", ["level", "location", "message", "timestamp"])) + self.format_dict = dict.fromkeys( + kwargs.pop("log_record_order", ["level", "location", "message", "xray_trace_id", "timestamp"]) + ) + self.reserved_keys = ["timestamp", "level", "location"] # Set the date format used by `asctime` super(JsonFormatter, self).__init__(datefmt=kwargs.pop("datefmt", None)) - self.reserved_keys = ["timestamp", "level", "location"] - self.format_dict.update( - {"level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", "timestamp": "%(asctime)s", **kwargs} - ) + self.format_dict.update(self._build_root_keys(**kwargs)) + + @staticmethod + def _build_root_keys(**kwargs): + xray_trace_id = os.getenv("_X_AMZN_TRACE_ID") + trace_id = xray_trace_id.split(";")[0].replace("Root=", "") if xray_trace_id else None + + return { + "level": "%(levelname)s", + "location": "%(funcName)s:%(lineno)d", + "xray_trace_id": trace_id, + "timestamp": "%(asctime)s", + **kwargs, + } def update_formatter(self, **kwargs): self.format_dict.update(kwargs) diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 290090ebe8b..c17b363e883 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -170,3 +170,34 @@ def test_log_dict_key_strip_nones(stdout): # THEN the keys should only include `level`, `message`, `service`, `sampling_rate` assert sorted(log_dict.keys()) == ["level", "message", "sampling_rate", "service"] + + +def test_log_dict_xray_is_present_when_tracing_is_enabled(stdout, monkeypatch): + # GIVEN a logger is initialized within a Lambda function with X-Ray enabled + trace_id = "1-5759e988-bd862e3fe1be46a994272793" + trace_header = f"Root={trace_id};Parent=53995c3f42cd8ad8;Sampled=1" + monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header) + logger = Logger(stream=stdout) + + # WHEN logging a message + logger.info("foo") + + log_dict: dict = json.loads(stdout.getvalue()) + + # THEN `xray_trace_id`` key should be present + assert log_dict["xray_trace_id"] == trace_id + + monkeypatch.delenv(name="_X_AMZN_TRACE_ID") + + +def test_log_dict_xray_is_not_present_when_tracing_is_disabled(stdout, monkeypatch): + # GIVEN a logger is initialized within a Lambda function with X-Ray disabled (default) + logger = Logger(stream=stdout) + + # WHEN logging a message + logger.info("foo") + + log_dict: dict = json.loads(stdout.getvalue()) + + # THEN `xray_trace_id`` key should not be present + assert "xray_trace_id" not in log_dict From 0356025c2627470c1eedf4002d058192045d3ab9 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 30 Aug 2020 17:23:06 +0200 Subject: [PATCH 2/4] docs: add xray_trace_id key --- docs/content/core/logger.mdx | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/docs/content/core/logger.mdx b/docs/content/core/logger.mdx index 7c977be4e97..5b8aef4b4e7 100644 --- a/docs/content/core/logger.mdx +++ b/docs/content/core/logger.mdx @@ -47,7 +47,7 @@ Logger(service="payment", level="INFO") ## Standard structured keys -Your Logger will always include the following keys to your structured logging: +Your Logger will include the following keys to your structured logging, by default: Key | Type | Example | Description ------------------------------------------------- | ------------------------------------------------- | --------------------------------------------------------------------------------- | ------------------------------------------------- @@ -57,6 +57,7 @@ Key | Type | Example | Description **service** | str | "payment" | Service name defined. "service_undefined" will be used if unknown **sampling_rate** | int | 0.1 | Debug logging sampling rate in percentage e.g. 10% in this case **message** | any | "Collecting payment" | Log statement value. Unserializable JSON values will be casted to string +**xray_trace_id** | str | "1-5759e988-bd862e3fe1be46a994272793" | X-Ray Trace ID when Lambda function has enabled Tracing ## Capturing Lambda context info @@ -304,7 +305,7 @@ This can be fixed by either ensuring both has the `service` value as `payment`, You might want to continue to use the same date formatting style, or override `location` to display the `package.function_name:line_number` as you previously had. -Logger allows you to either change the format or suppress the following keys altogether at the initialization: `location`, `timestamp`, `level`, and `datefmt` +Logger allows you to either change the format or suppress the following keys altogether at the initialization: `location`, `timestamp`, `level`, `xray_trace_id`, and `datefmt` ```python from aws_lambda_powertools import Logger @@ -316,7 +317,7 @@ logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s", datefmt="fa logger = Logger(stream=stdout, location=None) # highlight-line ``` -Alternatively, you can also change the order of the following log record keys via the `log_record_order` parameter: `level`, location`, message`, and timestamp` +Alternatively, you can also change the order of the following log record keys via the `log_record_order` parameter: `level`, `location`, `message`, `xray_trace_id`, and `timestamp` ```python from aws_lambda_powertools import Logger From ccd882fe07c649200a45fff59517134e00bca010 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 30 Aug 2020 21:14:07 +0200 Subject: [PATCH 3/4] fix: ensures xray_trace_id is refreshed --- aws_lambda_powertools/logging/formatter.py | 21 ++++++++++------- docs/content/core/logger.mdx | 4 ++-- tests/functional/test_aws_lambda_logging.py | 26 +++++++++++++++++++++ 3 files changed, 40 insertions(+), 11 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 4965501a22a..0b3cb62cc61 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -30,28 +30,28 @@ def __init__(self, **kwargs): # Set the default unserializable function, by default values will be cast as str. self.default_json_formatter = kwargs.pop("json_default", str) # Set the insertion order for the log messages - self.format_dict = dict.fromkeys( - kwargs.pop("log_record_order", ["level", "location", "message", "xray_trace_id", "timestamp"]) - ) + self.format_dict = dict.fromkeys(kwargs.pop("log_record_order", ["level", "location", "message", "timestamp"])) self.reserved_keys = ["timestamp", "level", "location"] # Set the date format used by `asctime` super(JsonFormatter, self).__init__(datefmt=kwargs.pop("datefmt", None)) self.format_dict.update(self._build_root_keys(**kwargs)) - @staticmethod - def _build_root_keys(**kwargs): - xray_trace_id = os.getenv("_X_AMZN_TRACE_ID") - trace_id = xray_trace_id.split(";")[0].replace("Root=", "") if xray_trace_id else None - + def _build_root_keys(self, **kwargs): return { "level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", - "xray_trace_id": trace_id, "timestamp": "%(asctime)s", **kwargs, } + @staticmethod + def _get_latest_trace_id(): + xray_trace_id = os.getenv("_X_AMZN_TRACE_ID") + trace_id = xray_trace_id.split(";")[0].replace("Root=", "") if xray_trace_id else None + + return trace_id + def update_formatter(self, **kwargs): self.format_dict.update(kwargs) @@ -90,6 +90,9 @@ def format(self, record): # noqa: A003 if record.exc_text: log_dict["exception"] = record.exc_text + # fetch latest X-Ray Trace ID, if any + log_dict.update({"xray_trace_id": self._get_latest_trace_id()}) + # Filter out top level key with values that are None log_dict = {k: v for k, v in log_dict.items() if v is not None} diff --git a/docs/content/core/logger.mdx b/docs/content/core/logger.mdx index 5b8aef4b4e7..0f8bb7fa9b9 100644 --- a/docs/content/core/logger.mdx +++ b/docs/content/core/logger.mdx @@ -305,7 +305,7 @@ This can be fixed by either ensuring both has the `service` value as `payment`, You might want to continue to use the same date formatting style, or override `location` to display the `package.function_name:line_number` as you previously had. -Logger allows you to either change the format or suppress the following keys altogether at the initialization: `location`, `timestamp`, `level`, `xray_trace_id`, and `datefmt` +Logger allows you to either change the format or suppress the following keys altogether at the initialization: `location`, `timestamp`, `level`, and `datefmt` ```python from aws_lambda_powertools import Logger @@ -317,7 +317,7 @@ logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s", datefmt="fa logger = Logger(stream=stdout, location=None) # highlight-line ``` -Alternatively, you can also change the order of the following log record keys via the `log_record_order` parameter: `level`, `location`, `message`, `xray_trace_id`, and `timestamp` +Alternatively, you can also change the order of the following log record keys via the `log_record_order` parameter: `level`, `location`, `message`, and `timestamp` ```python from aws_lambda_powertools import Logger diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index c17b363e883..79667f907fc 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -201,3 +201,29 @@ def test_log_dict_xray_is_not_present_when_tracing_is_disabled(stdout, monkeypat # THEN `xray_trace_id`` key should not be present assert "xray_trace_id" not in log_dict + + +def test_log_dict_xray_is_updated_when_tracing_id_changes(stdout, monkeypatch): + # GIVEN a logger is initialized within a Lambda function with X-Ray enabled + trace_id = "1-5759e988-bd862e3fe1be46a994272793" + trace_header = f"Root={trace_id};Parent=53995c3f42cd8ad8;Sampled=1" + monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header) + logger = Logger(stream=stdout) + + # WHEN logging a message + logger.info("foo") + + # and Trace ID changes to mimick a new invocation + trace_id_2 = "1-5759e988-bd862e3fe1be46a949393982437" + trace_header_2 = f"Root={trace_id_2};Parent=53995c3f42cd8ad8;Sampled=1" + monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header_2) + + logger.info("foo bar") + + log_dict, log_dict_2 = [json.loads(line.strip()) for line in stdout.getvalue().split("\n") if line] + + # THEN `xray_trace_id`` key should be different in both invocations + assert log_dict["xray_trace_id"] == trace_id + assert log_dict_2["xray_trace_id"] == trace_id_2 + + monkeypatch.delenv(name="_X_AMZN_TRACE_ID") From 20e7f3325a4bc79baf93e8f5068995f40b64231e Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 1 Sep 2020 17:13:07 +0200 Subject: [PATCH 4/4] fix: ensure debug log event has latest ctx --- aws_lambda_powertools/logging/logger.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 55b1b766427..3b188bdd9c4 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -235,14 +235,14 @@ def handler(event, context): @functools.wraps(lambda_handler) def decorate(event, context): + lambda_context = build_lambda_context_model(context) + cold_start = _is_cold_start() + self.structure_logs(append=True, cold_start=cold_start, **lambda_context.__dict__) + if log_event: logger.debug("Event received") self.info(event) - lambda_context = build_lambda_context_model(context) - cold_start = _is_cold_start() - - self.structure_logs(append=True, cold_start=cold_start, **lambda_context.__dict__) return lambda_handler(event, context) return decorate