From f9ff57b68e8e40a9335a4a3e1278999c69648700 Mon Sep 17 00:00:00 2001 From: RogerZhang Date: Thu, 5 Oct 2023 21:42:26 +0000 Subject: [PATCH 1/9] fix simple yet troublesome error --- aws_lambda_powertools/logging/formatter.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index cf0a7598051..fd53155cd39 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -144,6 +144,8 @@ def __init__( if self.utc: self.converter = time.gmtime + else: + self.converter = time.localtime self.keys_combined = {**self._build_default_keys(), **kwargs} self.log_format.update(**self.keys_combined) From 3238be28c807c581ac854683f1b80acbd0d65d5b Mon Sep 17 00:00:00 2001 From: RogerZhang Date: Fri, 6 Oct 2023 02:52:57 +0000 Subject: [PATCH 2/9] fix timezone, add doc, add e2e test --- docs/core/logger.md | 16 ++++-- examples/logger/src/setting_utc_timestamp.py | 14 +++-- .../src/setting_utc_timestamp_output.json | 20 +++---- package-lock.json | 48 ---------------- package.json | 3 - tests/e2e/logger/handlers/tz_handler.py | 21 +++++++ tests/e2e/logger/test_logger.py | 56 +++++++++++++++++++ .../test_logger_powertools_formatter.py | 8 +++ 8 files changed, 115 insertions(+), 71 deletions(-) create mode 100644 tests/e2e/logger/handlers/tz_handler.py diff --git a/docs/core/logger.md b/docs/core/logger.md index 6fc48e8898f..13280983a48 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -39,7 +39,7 @@ Your Logger will include the following keys to your structured logging: | **level**: `str` | `INFO` | Logging level | | **location**: `str` | `collect.handler:1` | Source code location where statement was executed | | **message**: `Any` | `Collecting payment` | Unserializable JSON values are casted as `str` | -| **timestamp**: `str` | `2021-05-03 10:20:19,650+0200` | Timestamp with milliseconds, by default uses local timezone | +| **timestamp**: `str` | `2021-05-03 10:20:19,650+0000` | Timestamp with milliseconds, by default uses default lambda timezone (UTC) | | **service**: `str` | `payment` | Service name defined, by default `service_undefined` | | **xray_trace_id**: `str` | `1-5759e988-bd862e3fe1be46a994272793` | When [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"}, it shows X-Ray Trace ID | | **sampling_rate**: `float` | `0.1` | When enabled, it shows sampling rate in percentage e.g. 10% | @@ -567,17 +567,21 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or --8<-- "examples/logger/src/reordering_log_keys_output.json" ``` -#### Setting timestamp to UTC +#### Setting timestamp to custom Timezone -By default, this Logger and standard logging library emits records using local time timestamp. You can override this behavior via `utc` parameter: +By default, this Logger and standard logging library emits records using default lambda time(UTC) timestamp. You can enforce this behavior via `utc` parameter. -=== "setting_utc_timestamp.py" +However, if you want to use your preferred timezone to format your log instead, you can use the timezone environment variable `TZ`, either set it as Lambda Environment Variable. Or setup this value directly in your Lambda Hander. - ```python hl_lines="6" +=== "setting_custom_timezone.py" + + ```python hl_lines="8 11" --8<-- "examples/logger/src/setting_utc_timestamp.py" ``` -=== "setting_utc_timestamp_output.json" + 1. if you set TZ in lambda runtime, time.tzset() need to be called. You don't need it when setting TZ in lambda environment variable + +=== "setting_custom_timezone_output.json" ```json hl_lines="6 13" --8<-- "examples/logger/src/setting_utc_timestamp_output.json" diff --git a/examples/logger/src/setting_utc_timestamp.py b/examples/logger/src/setting_utc_timestamp.py index a454e216d75..8ae6645cf99 100644 --- a/examples/logger/src/setting_utc_timestamp.py +++ b/examples/logger/src/setting_utc_timestamp.py @@ -1,7 +1,13 @@ +import os +import time + from aws_lambda_powertools import Logger -logger = Logger(service="payment") -logger.info("Local time") +logger = Logger(service="payment", utc=True) +logger.info("utf time") + +os.environ["TZ"] = "US/Eastern" +time.tzset() # (1)! -logger_in_utc = Logger(service="order", utc=True) -logger_in_utc.info("GMT time zone") +logger_in_utc = Logger(service="order") +logger_in_utc.info("US eastern time") diff --git a/examples/logger/src/setting_utc_timestamp_output.json b/examples/logger/src/setting_utc_timestamp_output.json index 80083fbf61b..07d1042f216 100644 --- a/examples/logger/src/setting_utc_timestamp_output.json +++ b/examples/logger/src/setting_utc_timestamp_output.json @@ -1,16 +1,16 @@ [ { - "level": "INFO", - "location": ":4", - "message": "Local time", - "timestamp": "2022-06-24 11:39:49,421+0200", - "service": "payment" + "level":"INFO", + "location":":6", + "message":"utf time", + "timestamp":"2023-10-06 02:46:54,097+0000", + "service":"payment" }, { - "level": "INFO", - "location": ":7", - "message": "GMT time zone", - "timestamp": "2022-06-24 09:39:49,421+0100", - "service": "order" + "level":"INFO", + "location":":12", + "message":"US eastern time", + "timestamp":"2023-10-05 22:46:54,097-0400", + "service":"order" } ] diff --git a/package-lock.json b/package-lock.json index 0ef0c6f3cc8..97a672caec6 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,38 +9,6 @@ "version": "1.0.0", "dependencies": { "package-lock.json": "^1.0.0" - }, - "devDependencies": { - "aws-cdk": "^2.99.1" - } - }, - "node_modules/aws-cdk": { - "version": "2.99.1", - "resolved": "https://registry.npmjs.org/aws-cdk/-/aws-cdk-2.99.1.tgz", - "integrity": "sha512-uWg4xhBrHNoRMlEgvWzr0MacJ92dLFeJ5AvT7nruxrgShU1fgt/Rsxw1WCXSASaVUsIUGgtO+P89x8cRU2nf7w==", - "dev": true, - "bin": { - "cdk": "bin/cdk" - }, - "engines": { - "node": ">= 14.15.0" - }, - "optionalDependencies": { - "fsevents": "2.3.2" - } - }, - "node_modules/fsevents": { - "version": "2.3.2", - "resolved": "https://registry.npmjs.org/fsevents/-/fsevents-2.3.2.tgz", - "integrity": "sha512-xiqMQR4xAeHTuB9uWm+fFRcIOgKBMiOBP+eXiyT7jsgVCq1bkVygt00oASowB7EdtpOHaaPgKt812P9ab+DDKA==", - "dev": true, - "hasInstallScript": true, - "optional": true, - "os": [ - "darwin" - ], - "engines": { - "node": "^8.16.0 || ^10.6.0 || >=11.0.0" } }, "node_modules/package-lock.json": { @@ -50,22 +18,6 @@ } }, "dependencies": { - "aws-cdk": { - "version": "2.99.1", - "resolved": "https://registry.npmjs.org/aws-cdk/-/aws-cdk-2.99.1.tgz", - "integrity": "sha512-uWg4xhBrHNoRMlEgvWzr0MacJ92dLFeJ5AvT7nruxrgShU1fgt/Rsxw1WCXSASaVUsIUGgtO+P89x8cRU2nf7w==", - "dev": true, - "requires": { - "fsevents": "2.3.2" - } - }, - "fsevents": { - "version": "2.3.2", - "resolved": "https://registry.npmjs.org/fsevents/-/fsevents-2.3.2.tgz", - "integrity": "sha512-xiqMQR4xAeHTuB9uWm+fFRcIOgKBMiOBP+eXiyT7jsgVCq1bkVygt00oASowB7EdtpOHaaPgKt812P9ab+DDKA==", - "dev": true, - "optional": true - }, "package-lock.json": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/package-lock.json/-/package-lock.json-1.0.0.tgz", diff --git a/package.json b/package.json index abaf3c87910..60d21e9e422 100644 --- a/package.json +++ b/package.json @@ -1,9 +1,6 @@ { "name": "aws-lambda-powertools-python-e2e", "version": "1.0.0", - "devDependencies": { - "aws-cdk": "^2.99.1" - }, "dependencies": { "package-lock.json": "^1.0.0" } diff --git a/tests/e2e/logger/handlers/tz_handler.py b/tests/e2e/logger/handlers/tz_handler.py new file mode 100644 index 00000000000..c872ac62f11 --- /dev/null +++ b/tests/e2e/logger/handlers/tz_handler.py @@ -0,0 +1,21 @@ +import os +import time + +from aws_lambda_powertools import Logger + + +def lambda_handler(event, context): + utc, datefmt, tz = event.get("utc", False), event.get("datefmt", None), event.get("tz", None) + if tz: + os.environ["TZ"] = tz + time.tzset() + + logger = Logger(service=f"{utc}-{datefmt}-{tz}", utc=utc, datefmt=datefmt) + if logger.handlers[0].formatter.converter == time.localtime: + loggerType = "localtime_converter" + elif logger.handlers[0].formatter.converter == time.gmtime: + loggerType = "gmtime_converter" + else: + loggerType = "unknown" + logger.info(loggerType) + return "success" diff --git a/tests/e2e/logger/test_logger.py b/tests/e2e/logger/test_logger.py index 80379125d11..6240a316dde 100644 --- a/tests/e2e/logger/test_logger.py +++ b/tests/e2e/logger/test_logger.py @@ -1,4 +1,6 @@ import json +import os +import time from uuid import uuid4 import pytest @@ -17,6 +19,16 @@ def basic_handler_fn_arn(infrastructure: dict) -> str: return infrastructure.get("BasicHandlerArn", "") +@pytest.fixture +def tz_handler_fn(infrastructure: dict) -> str: + return infrastructure.get("TzHandler", "") + + +@pytest.fixture +def tz_handler_fn_arn(infrastructure: dict) -> str: + return infrastructure.get("TzHandlerArn", "") + + @pytest.mark.xdist_group(name="logger") def test_basic_lambda_logs_visible(basic_handler_fn, basic_handler_fn_arn): # GIVEN @@ -36,3 +48,47 @@ def test_basic_lambda_logs_visible(basic_handler_fn, basic_handler_fn_arn): assert len(logs.get_cold_start_log()) == 1 assert len(logs.get_log(key=custom_key)) == 2 assert logs.have_keys(*LOGGER_LAMBDA_CONTEXT_KEYS) is True + + +# test on combination of utc,tz,datefmt params +@pytest.mark.xdist_group(name="logger") +@pytest.mark.parametrize("utc", [False, True]) +@pytest.mark.parametrize("tz", ["US/Eastern", "UTC", "Asia/Shanghai"]) +@pytest.mark.parametrize("datefmt", ["%z", None]) +def test_lambda_tz(tz_handler_fn, tz_handler_fn_arn, utc, tz, datefmt): + # GIVEN + payload = json.dumps({"utc": utc, "tz": tz, "datefmt": datefmt}) + + # WHEN + _, execution_time = data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) + data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) + + # THEN + logs = data_fetcher.get_logs( + function_name=tz_handler_fn, + start_time=execution_time, + minimum_log_entries=1, + filter_expression='{ $.service = "' + f"{utc}-{datefmt}-{tz}" + '" }', + ) + result_list = logs.logs + + assert len(result_list) > 0 + result = result_list[0] + + # When UTC + if utc: + # then use gmt converter + assert result.message == "gmtime_converter" + # When not UTC + else: + # then use local time converter + assert result.message == "localtime_converter" + + if utc: + assert result.timestamp[-5:] == "+0000" + else: + os.environ["TZ"] = tz + time.tzset() + assert result.timestamp[-5:] == time.strftime("%z", time.localtime()) + + print(result) diff --git a/tests/functional/test_logger_powertools_formatter.py b/tests/functional/test_logger_powertools_formatter.py index 61c3f76efd4..b74c2875345 100644 --- a/tests/functional/test_logger_powertools_formatter.py +++ b/tests/functional/test_logger_powertools_formatter.py @@ -294,6 +294,14 @@ def test_log_in_utc(service_name): assert logger._logger.handlers[0].formatter.converter == time.gmtime +def test_log_wo_utc(service_name): + # GIVEN a logger where UTC is false + logger = Logger(service=service_name, utc=False) + + # THEN logging formatter time converter should use localtime fn + assert logger._logger.handlers[0].formatter.converter == time.localtime + + @pytest.mark.parametrize("message", ["hello", 1.10, {}, [], True, object()]) def test_logging_various_primitives(stdout, service_name, message): # GIVEN a logger with default settings From 331123b83236ec3f1b63db8d6dc8d0f5bfd4d3c4 Mon Sep 17 00:00:00 2001 From: RogerZhang Date: Fri, 6 Oct 2023 02:56:11 +0000 Subject: [PATCH 3/9] fix line number --- docs/core/logger.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 13280983a48..e97ca227f41 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -571,11 +571,14 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or By default, this Logger and standard logging library emits records using default lambda time(UTC) timestamp. You can enforce this behavior via `utc` parameter. -However, if you want to use your preferred timezone to format your log instead, you can use the timezone environment variable `TZ`, either set it as Lambda Environment Variable. Or setup this value directly in your Lambda Hander. +However, if you want to use your preferred timezone to format your log instead, you can use the timezone environment variable `TZ`: Either set it as Lambda Environment Variable. Or setup this value directly in your Lambda Hander. + +???+ tip + `TZ` environment variable will be ingnored if `utc` is set to `True` === "setting_custom_timezone.py" - ```python hl_lines="8 11" + ```python hl_lines="9 12" --8<-- "examples/logger/src/setting_utc_timestamp.py" ``` From cb5f25a01d4b5cb439212f57330ebb09ef459c33 Mon Sep 17 00:00:00 2001 From: RogerZhang Date: Mon, 9 Oct 2023 21:53:11 +0000 Subject: [PATCH 4/9] update tz in to utc, address leandro comment --- docs/core/logger.md | 17 +++++++++-------- .../logger/src/append_keys_extra_output.json | 2 +- .../logger/src/append_keys_kwargs_output.json | 2 +- examples/logger/src/append_keys_output.json | 2 +- .../src/bring_your_own_formatter_output.json | 2 +- examples/logger/src/clear_state_event_one.json | 2 +- examples/logger/src/clear_state_event_two.json | 2 +- examples/logger/src/date_formatting_output.json | 2 +- .../src/inject_lambda_context_output.json | 4 ++-- examples/logger/src/logger_reuse_output.json | 2 +- .../logger/src/logging_exceptions_output.json | 2 +- .../src/logging_uncaught_exceptions_output.json | 2 +- .../src/overriding_log_records_output.json | 4 ++-- examples/logger/src/remove_keys_output.json | 4 ++-- .../logger/src/reordering_log_keys_output.json | 4 ++-- .../logger/src/sampling_debug_logs_output.json | 4 ++-- .../src/set_correlation_id_jmespath_output.json | 2 +- .../src/set_correlation_id_method_output.json | 2 +- .../logger/src/set_correlation_id_output.json | 2 +- examples/logger/src/setting_utc_timestamp.py | 8 ++++---- .../src/setting_utc_timestamp_output.json | 12 ++++++------ .../src/unserializable_values_output.json | 2 +- package.json | 3 +++ 23 files changed, 46 insertions(+), 42 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index e97ca227f41..3f866e8a2f7 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -39,7 +39,7 @@ Your Logger will include the following keys to your structured logging: | **level**: `str` | `INFO` | Logging level | | **location**: `str` | `collect.handler:1` | Source code location where statement was executed | | **message**: `Any` | `Collecting payment` | Unserializable JSON values are casted as `str` | -| **timestamp**: `str` | `2021-05-03 10:20:19,650+0000` | Timestamp with milliseconds, by default uses default lambda timezone (UTC) | +| **timestamp**: `str` | `2021-05-03 10:20:19,650+0000` | Timestamp with milliseconds, by default uses default AWS Lambda timezone (UTC) | | **service**: `str` | `payment` | Service name defined, by default `service_undefined` | | **xray_trace_id**: `str` | `1-5759e988-bd862e3fe1be46a994272793` | When [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"}, it shows X-Ray Trace ID | | **sampling_rate**: `float` | `0.1` | When enabled, it shows sampling rate in percentage e.g. 10% | @@ -321,12 +321,12 @@ Logger can optionally log uncaught exceptions by setting `log_uncaught_exception ### Date formatting -Logger uses Python's standard logging date format with the addition of timezone: `2021-05-03 11:47:12,494+0200`. +Logger uses Python's standard logging date format with the addition of timezone: `2021-05-03 11:47:12,494+0000`. You can easily change the date format using one of the following parameters: * **`datefmt`**. You can pass any [strftime format codes](https://strftime.org/){target="_blank" rel="nofollow"}. Use `%F` if you need milliseconds. -* **`use_rfc3339`**. This flag will use a format compliant with both RFC3339 and ISO8601: `2022-10-27T16:27:43.738+02:00` +* **`use_rfc3339`**. This flag will use a format compliant with both RFC3339 and ISO8601: `2022-10-27T16:27:43.738+00:00` ???+ tip "Prefer using [datetime string formats](https://docs.python.org/3/library/datetime.html#strftime-and-strptime-format-codes){target="_blank" rel="nofollow"}?" Use `use_datetime_directive` flag along with `datefmt` to instruct Logger to use `datetime` instead of `time.strftime`. @@ -352,6 +352,7 @@ The following environment variables are available to configure Logger at a globa | **Event Logging** | Whether to log the incoming event. | `POWERTOOLS_LOGGER_LOG_EVENT` | `false` | | **Debug Sample Rate** | Sets the debug log sampling. | `POWERTOOLS_LOGGER_SAMPLE_RATE` | `0` | | **Disable Deduplication** | Disables log deduplication filter protection to use Pytest Live Log feature. | `POWERTOOLS_LOG_DEDUPLICATION_DISABLED` | `false` | +| **TZ** | Sets timezone when using Logger, e.g., `US/Eastern`. Timezone is defaulted to UTC when `TZ` is not set | `TZ` | `None` (UTC) | [`POWERTOOLS_LOGGER_LOG_EVENT`](#logging-incoming-event) can also be set on a per-method basis, and [`POWERTOOLS_LOGGER_SAMPLE_RATE`](#sampling-debug-logs) on a per-instance basis. These parameter values will override the environment variable value. @@ -448,7 +449,7 @@ If you prefer configuring it separately, or you'd want to bring this JSON Format | **`json_default`** | function to coerce unserializable values, when no custom serializer/deserializer is set | `str` | | **`datefmt`** | string directives (strftime) to format log timestamp | `%Y-%m-%d %H:%M:%S,%F%z`, where `%F` is a custom ms directive | | **`use_datetime_directive`** | format the `datefmt` timestamps using `datetime`, not `time` (also supports the custom `%F` directive for milliseconds) | `False` | -| **`utc`** | set logging timestamp to UTC | `False` | +| **`utc`** | enforce logging timestamp to UTC (ignore `TZ` environment variable) | `False` | | **`log_record_order`** | set order of log keys when logging | `["level", "location", "message", "timestamp"]` | | **`kwargs`** | key-value to be included in log messages | `None` | @@ -569,12 +570,12 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or #### Setting timestamp to custom Timezone -By default, this Logger and standard logging library emits records using default lambda time(UTC) timestamp. You can enforce this behavior via `utc` parameter. +By default, this Logger and the standard logging library emit records with the default AWS Lambda timestamp in UTC. -However, if you want to use your preferred timezone to format your log instead, you can use the timezone environment variable `TZ`: Either set it as Lambda Environment Variable. Or setup this value directly in your Lambda Hander. +However, if you want to use your preferred timezone to format your log instead, you can use the timezone environment variable `TZ`: Either set it as AWS Lambda environment variable, or setup this value directly in your Lambda function. ???+ tip - `TZ` environment variable will be ingnored if `utc` is set to `True` + `TZ` environment variable will be ignored if `utc` is set to `True` === "setting_custom_timezone.py" @@ -582,7 +583,7 @@ However, if you want to use your preferred timezone to format your log instead, --8<-- "examples/logger/src/setting_utc_timestamp.py" ``` - 1. if you set TZ in lambda runtime, time.tzset() need to be called. You don't need it when setting TZ in lambda environment variable + 1. if you set TZ in your Lambda function, `time.tzset()` need to be called. You don't need it when setting TZ in AWS Lambda environment variable === "setting_custom_timezone_output.json" diff --git a/examples/logger/src/append_keys_extra_output.json b/examples/logger/src/append_keys_extra_output.json index b25abb226a1..3d1c5ed5eaf 100644 --- a/examples/logger/src/append_keys_extra_output.json +++ b/examples/logger/src/append_keys_extra_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:9", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "request_id": "1123" } diff --git a/examples/logger/src/append_keys_kwargs_output.json b/examples/logger/src/append_keys_kwargs_output.json index cd888e5e2af..3923d3e66c4 100644 --- a/examples/logger/src/append_keys_kwargs_output.json +++ b/examples/logger/src/append_keys_kwargs_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:8", "message": "Collecting payment", - "timestamp": "2022-11-26 11:47:12,494+0200", + "timestamp": "2022-11-26 11:47:12,494+0000", "service": "payment", "request_id": "1123" } \ No newline at end of file diff --git a/examples/logger/src/append_keys_output.json b/examples/logger/src/append_keys_output.json index 1e6d38bf785..b4eb223484c 100644 --- a/examples/logger/src/append_keys_output.json +++ b/examples/logger/src/append_keys_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:11", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "order_id": "order_id_value" } diff --git a/examples/logger/src/bring_your_own_formatter_output.json b/examples/logger/src/bring_your_own_formatter_output.json index 19869b7b885..d23cbcb5721 100644 --- a/examples/logger/src/bring_your_own_formatter_output.json +++ b/examples/logger/src/bring_your_own_formatter_output.json @@ -1,7 +1,7 @@ { "level": "INFO", "location": ":16", - "timestamp": "2021-12-30 13:41:53,413+0100", + "timestamp": "2021-12-30 13:41:53,413+0000", "service": "payment", "event": "hello" } diff --git a/examples/logger/src/clear_state_event_one.json b/examples/logger/src/clear_state_event_one.json index 394624ed8f6..99d9b3c7484 100644 --- a/examples/logger/src/clear_state_event_one.json +++ b/examples/logger/src/clear_state_event_one.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:10", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "special_key": "debug_key", "cold_start": true, diff --git a/examples/logger/src/clear_state_event_two.json b/examples/logger/src/clear_state_event_two.json index 93f59b50f82..66c4893531d 100644 --- a/examples/logger/src/clear_state_event_two.json +++ b/examples/logger/src/clear_state_event_two.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:10", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": false, "function_name": "test", diff --git a/examples/logger/src/date_formatting_output.json b/examples/logger/src/date_formatting_output.json index 2d5ba1dff88..6adebb0de2a 100644 --- a/examples/logger/src/date_formatting_output.json +++ b/examples/logger/src/date_formatting_output.json @@ -3,7 +3,7 @@ "level": "INFO", "location": ":6", "message": "Collecting payment", - "timestamp": "2022-10-28T14:35:03.210+02:00", + "timestamp": "2022-10-28T14:35:03.210+00:00", "service": "payment" }, { diff --git a/examples/logger/src/inject_lambda_context_output.json b/examples/logger/src/inject_lambda_context_output.json index a9f2937dc09..a8fbe915667 100644 --- a/examples/logger/src/inject_lambda_context_output.json +++ b/examples/logger/src/inject_lambda_context_output.json @@ -3,7 +3,7 @@ "level": "INFO", "location": "collect.handler:9", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", @@ -18,7 +18,7 @@ "operation": "collect_payment", "charge_id": "ch_AZFlk2345C0" }, - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", diff --git a/examples/logger/src/logger_reuse_output.json b/examples/logger/src/logger_reuse_output.json index 9dbce381ea3..e771684b922 100644 --- a/examples/logger/src/logger_reuse_output.json +++ b/examples/logger/src/logger_reuse_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:12", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", diff --git a/examples/logger/src/logging_exceptions_output.json b/examples/logger/src/logging_exceptions_output.json index 8f3011e3a87..15831f9b776 100644 --- a/examples/logger/src/logging_exceptions_output.json +++ b/examples/logger/src/logging_exceptions_output.json @@ -2,7 +2,7 @@ "level": "ERROR", "location": "collect.handler:15", "message": "Received a HTTP 5xx error", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "exception_name": "RuntimeError", "exception": "Traceback (most recent call last):\n File \"\", line 2, in RuntimeError: Unable to fullfil request" diff --git a/examples/logger/src/logging_uncaught_exceptions_output.json b/examples/logger/src/logging_uncaught_exceptions_output.json index c8ff16e55b5..7952ba9e873 100644 --- a/examples/logger/src/logging_uncaught_exceptions_output.json +++ b/examples/logger/src/logging_uncaught_exceptions_output.json @@ -2,7 +2,7 @@ "level": "ERROR", "location": "log_uncaught_exception_hook:756", "message": "500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500", - "timestamp": "2022-11-16 13:51:29,198+0100", + "timestamp": "2022-11-16 13:51:29,198+0000", "service": "payment", "exception": "Traceback (most recent call last):\n File \"\", line 52, in \n handler({}, {})\n File \"\", line 17, in handler\n ret.raise_for_status()\n File \"/lib/python3.9/site-packages/requests/models.py\", line 1021, in raise_for_status\n raise HTTPError(http_error_msg, response=self)\nrequests.exceptions.HTTPError: 500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500", "exception_name": "HTTPError" diff --git a/examples/logger/src/overriding_log_records_output.json b/examples/logger/src/overriding_log_records_output.json index 676f36ca298..93910304c6e 100644 --- a/examples/logger/src/overriding_log_records_output.json +++ b/examples/logger/src/overriding_log_records_output.json @@ -3,13 +3,13 @@ "level": "INFO", "location": "[] overriding_log_records", "message": "Collecting payment", - "timestamp": "2022-10-28 14:40:43,801+0200", + "timestamp": "2022-10-28 14:40:43,801+0000", "service": "payment" }, { "level": "INFO", "message": "Calculating points", - "timestamp": "2022-10-28 14:40:43,801+0200", + "timestamp": "2022-10-28 14:40:43,801+0000", "service": "loyalty" } ] \ No newline at end of file diff --git a/examples/logger/src/remove_keys_output.json b/examples/logger/src/remove_keys_output.json index 4ec8740784e..ee89ed8e2a1 100644 --- a/examples/logger/src/remove_keys_output.json +++ b/examples/logger/src/remove_keys_output.json @@ -3,7 +3,7 @@ "level": "INFO", "location": "collect.handler:9", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "sample_key": "value" }, @@ -11,7 +11,7 @@ "level": "INFO", "location": "collect.handler:12", "message": "Collecting payment without sample key", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment" } ] diff --git a/examples/logger/src/reordering_log_keys_output.json b/examples/logger/src/reordering_log_keys_output.json index c89f7cb48bd..c0052808002 100644 --- a/examples/logger/src/reordering_log_keys_output.json +++ b/examples/logger/src/reordering_log_keys_output.json @@ -3,14 +3,14 @@ "message": "hello world", "level": "INFO", "location": ":11", - "timestamp": "2022-06-24 11:25:40,143+0200", + "timestamp": "2022-06-24 11:25:40,143+0000", "service": "payment" }, { "request_id": "123", "level": "INFO", "location": ":12", - "timestamp": "2022-06-24 11:25:40,144+0200", + "timestamp": "2022-06-24 11:25:40,144+0000", "service": "order", "message": "hello universe" } diff --git a/examples/logger/src/sampling_debug_logs_output.json b/examples/logger/src/sampling_debug_logs_output.json index dbeb28edb8a..a889b538bc7 100644 --- a/examples/logger/src/sampling_debug_logs_output.json +++ b/examples/logger/src/sampling_debug_logs_output.json @@ -3,7 +3,7 @@ "level": "DEBUG", "location": "collect.handler:7", "message": "Verifying whether order_id is present", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", @@ -16,7 +16,7 @@ "level": "INFO", "location": "collect.handler:7", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", diff --git a/examples/logger/src/set_correlation_id_jmespath_output.json b/examples/logger/src/set_correlation_id_jmespath_output.json index 0744a0fc8d1..3ba6a90b684 100644 --- a/examples/logger/src/set_correlation_id_jmespath_output.json +++ b/examples/logger/src/set_correlation_id_jmespath_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:11", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", diff --git a/examples/logger/src/set_correlation_id_method_output.json b/examples/logger/src/set_correlation_id_method_output.json index f78d26740ae..c1f336c5390 100644 --- a/examples/logger/src/set_correlation_id_method_output.json +++ b/examples/logger/src/set_correlation_id_method_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:13", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "correlation_id": "correlation_id_value" } diff --git a/examples/logger/src/set_correlation_id_output.json b/examples/logger/src/set_correlation_id_output.json index 3cc205e32e2..95b497a9500 100644 --- a/examples/logger/src/set_correlation_id_output.json +++ b/examples/logger/src/set_correlation_id_output.json @@ -2,7 +2,7 @@ "level": "INFO", "location": "collect.handler:10", "message": "Collecting payment", - "timestamp": "2021-05-03 11:47:12,494+0200", + "timestamp": "2021-05-03 11:47:12,494+0000", "service": "payment", "cold_start": true, "function_name": "test", diff --git a/examples/logger/src/setting_utc_timestamp.py b/examples/logger/src/setting_utc_timestamp.py index 8ae6645cf99..7f893823677 100644 --- a/examples/logger/src/setting_utc_timestamp.py +++ b/examples/logger/src/setting_utc_timestamp.py @@ -3,11 +3,11 @@ from aws_lambda_powertools import Logger -logger = Logger(service="payment", utc=True) -logger.info("utf time") +logger_in_utc = Logger(service="payment") +logger_in_utc.info("Logging with default AWS Lambda timezone: UTC time") os.environ["TZ"] = "US/Eastern" time.tzset() # (1)! -logger_in_utc = Logger(service="order") -logger_in_utc.info("US eastern time") +logger = Logger(service="order") +logger.info("Logging with US Eastern timezone") diff --git a/examples/logger/src/setting_utc_timestamp_output.json b/examples/logger/src/setting_utc_timestamp_output.json index 07d1042f216..4e35bf48450 100644 --- a/examples/logger/src/setting_utc_timestamp_output.json +++ b/examples/logger/src/setting_utc_timestamp_output.json @@ -1,16 +1,16 @@ [ { "level":"INFO", - "location":":6", - "message":"utf time", - "timestamp":"2023-10-06 02:46:54,097+0000", + "location":":7", + "message":"Logging with default AWS Lambda timezone: UTC time", + "timestamp":"2023-10-09 21:33:55,733+0000", "service":"payment" }, { "level":"INFO", - "location":":12", - "message":"US eastern time", - "timestamp":"2023-10-05 22:46:54,097-0400", + "location":":13", + "message":"Logging with US Eastern timezone", + "timestamp":"2023-10-09 17:33:55,734-0400", "service":"order" } ] diff --git a/examples/logger/src/unserializable_values_output.json b/examples/logger/src/unserializable_values_output.json index ed7770cab03..744fd82a219 100644 --- a/examples/logger/src/unserializable_values_output.json +++ b/examples/logger/src/unserializable_values_output.json @@ -5,6 +5,6 @@ "ingestion_time": "2022-06-24T10:12:09.526365", "serialize_me": "" }, - "timestamp": "2022-06-24 12:12:09,526+0200", + "timestamp": "2022-06-24 12:12:09,526+0000", "service": "payment" } diff --git a/package.json b/package.json index 60d21e9e422..abaf3c87910 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,9 @@ { "name": "aws-lambda-powertools-python-e2e", "version": "1.0.0", + "devDependencies": { + "aws-cdk": "^2.99.1" + }, "dependencies": { "package-lock.json": "^1.0.0" } From ba765732ce0c332c3ce2da870ff1b23f04ad1fef Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Tue, 10 Oct 2023 15:54:29 +0100 Subject: [PATCH 5/9] Small changes --- docs/core/logger.md | 6 ++++-- tests/functional/test_logger_powertools_formatter.py | 10 ++++++---- 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 3f866e8a2f7..84bd9fc08ad 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -570,9 +570,11 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or #### Setting timestamp to custom Timezone -By default, this Logger and the standard logging library emit records with the default AWS Lambda timestamp in UTC. +By default, this Logger and the standard logging library emit records with the default AWS Lambda timestamp in **UTC**. -However, if you want to use your preferred timezone to format your log instead, you can use the timezone environment variable `TZ`: Either set it as AWS Lambda environment variable, or setup this value directly in your Lambda function. + +If you prefer to log in a specific timezone, you can configure it by setting the `TZ` environment variable. You can do this either as an AWS Lambda environment variable or directly within your Lambda function settings. [Click here](https://docs.aws.amazon.com/lambda/latest/dg/configuration-envvars.html#configuration-envvars-runtime){target="_blank"} for a comprehensive list of available Lambda environment variables. + ???+ tip `TZ` environment variable will be ignored if `utc` is set to `True` diff --git a/tests/functional/test_logger_powertools_formatter.py b/tests/functional/test_logger_powertools_formatter.py index b74c2875345..eee053d8f55 100644 --- a/tests/functional/test_logger_powertools_formatter.py +++ b/tests/functional/test_logger_powertools_formatter.py @@ -291,15 +291,17 @@ def test_log_in_utc(service_name): logger = Logger(service=service_name, utc=True) # THEN logging formatter time converter should use gmtime fn - assert logger._logger.handlers[0].formatter.converter == time.gmtime + assert logger.handlers[0].formatter.converter == time.gmtime -def test_log_wo_utc(service_name): +def test_log_with_localtime(service_name): # GIVEN a logger where UTC is false - logger = Logger(service=service_name, utc=False) + logger = Logger(service=service_name, utc=True) + + print(logger.handlers[0].formatter.converter) # THEN logging formatter time converter should use localtime fn - assert logger._logger.handlers[0].formatter.converter == time.localtime + assert logger.handlers[0].formatter.converter == time.localtime @pytest.mark.parametrize("message", ["hello", 1.10, {}, [], True, object()]) From bf94279f4522c6a38a4ff5534c4c05ffaf76a507 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Tue, 10 Oct 2023 16:13:01 +0100 Subject: [PATCH 6/9] Reverting test --- .../test_logger_powertools_formatter.py | 57 +------------------ 1 file changed, 1 insertion(+), 56 deletions(-) diff --git a/tests/functional/test_logger_powertools_formatter.py b/tests/functional/test_logger_powertools_formatter.py index bcf676ddb08..4ac92715395 100644 --- a/tests/functional/test_logger_powertools_formatter.py +++ b/tests/functional/test_logger_powertools_formatter.py @@ -6,27 +6,13 @@ import re import string import time -from collections import namedtuple import pytest from aws_lambda_powertools import Logger -from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter from aws_lambda_powertools.logging.formatters.datadog import DatadogLogFormatter -@pytest.fixture -def lambda_context(): - lambda_context = { - "function_name": "test", - "memory_limit_in_mb": 128, - "invoked_function_arn": "arn:aws:lambda:eu-west-1:809313241:function:test", - "aws_request_id": "52fdfc07-2182-154f-163f-5f0f9a621d72", - } - - return namedtuple("LambdaContext", lambda_context.keys())(*lambda_context.values()) - - @pytest.fixture def stdout(): return io.StringIO() @@ -310,9 +296,7 @@ def test_log_in_utc(service_name): def test_log_with_localtime(service_name): # GIVEN a logger where UTC is false - logger = Logger(service=service_name, utc=True) - - print(logger.handlers[0].formatter.converter) + logger = Logger(service=service_name, utc=False) # THEN logging formatter time converter should use localtime fn assert logger.handlers[0].formatter.converter == time.localtime @@ -374,42 +358,3 @@ def test_datadog_formatter_use_rfc3339_date(stdout, service_name): log = capture_logging_output(stdout) assert re.fullmatch(RFC3339_REGEX, log["timestamp"]) # "2022-10-27T17:42:26.841+0200" - - -def test_logger_logs_stack_trace_with_formatter_default_value(service_name, stdout): - # GIVEN a Logger instance with LambdaPowertoolsFormatter set explictly - # GIVE serialize_stacktrace default value = True - logger = Logger(service=service_name, stream=stdout, logger_formatter=LambdaPowertoolsFormatter()) - - # WHEN invoking a Lambda - def handler(event, context): - try: - raise ValueError("something went wrong") - except Exception: - logger.exception("Received an exception") - - # THEN we expect a "stack_trace" in log - handler({}, lambda_context) - log = capture_logging_output(stdout) - assert "stack_trace" in log - - -def test_logger_logs_stack_trace_with_formatter_non_default_value(service_name, stdout): - # GIVEN a Logger instance with serialize_stacktrace = False - logger = Logger( - service=service_name, - stream=stdout, - logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False), - ) - - # WHEN invoking a Lambda - def handler(event, context): - try: - raise ValueError("something went wrong") - except Exception: - logger.exception("Received an exception") - - # THEN we expect a "stack_trace" not in log - handler({}, lambda_context) - log = capture_logging_output(stdout) - assert "stack_trace" not in log From 97c71e5dbc4c34b586398363dce7faba48386680 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Tue, 10 Oct 2023 17:03:17 +0100 Subject: [PATCH 7/9] Adding the test again -- Git was crazy :D --- .../test_logger_powertools_formatter.py | 53 +++++++++++++++++++ 1 file changed, 53 insertions(+) diff --git a/tests/functional/test_logger_powertools_formatter.py b/tests/functional/test_logger_powertools_formatter.py index 4ac92715395..62f3f36c025 100644 --- a/tests/functional/test_logger_powertools_formatter.py +++ b/tests/functional/test_logger_powertools_formatter.py @@ -6,13 +6,27 @@ import re import string import time +from collections import namedtuple import pytest from aws_lambda_powertools import Logger +from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter from aws_lambda_powertools.logging.formatters.datadog import DatadogLogFormatter +@pytest.fixture +def lambda_context(): + lambda_context = { + "function_name": "test", + "memory_limit_in_mb": 128, + "invoked_function_arn": "arn:aws:lambda:eu-west-1:809313241:function:test", + "aws_request_id": "52fdfc07-2182-154f-163f-5f0f9a621d72", + } + + return namedtuple("LambdaContext", lambda_context.keys())(*lambda_context.values()) + + @pytest.fixture def stdout(): return io.StringIO() @@ -358,3 +372,42 @@ def test_datadog_formatter_use_rfc3339_date(stdout, service_name): log = capture_logging_output(stdout) assert re.fullmatch(RFC3339_REGEX, log["timestamp"]) # "2022-10-27T17:42:26.841+0200" + + +def test_logger_logs_stack_trace_with_formatter_default_value(service_name, stdout): + # GIVEN a Logger instance with LambdaPowertoolsFormatter set explictly + # GIVE serialize_stacktrace default value = True + logger = Logger(service=service_name, stream=stdout, logger_formatter=LambdaPowertoolsFormatter()) + + # WHEN invoking a Lambda + def handler(event, context): + try: + raise ValueError("something went wrong") + except Exception: + logger.exception("Received an exception") + + # THEN we expect a "stack_trace" in log + handler({}, lambda_context) + log = capture_logging_output(stdout) + assert "stack_trace" in log + + +def test_logger_logs_stack_trace_with_formatter_non_default_value(service_name, stdout): + # GIVEN a Logger instance with serialize_stacktrace = False + logger = Logger( + service=service_name, + stream=stdout, + logger_formatter=LambdaPowertoolsFormatter(serialize_stacktrace=False), + ) + + # WHEN invoking a Lambda + def handler(event, context): + try: + raise ValueError("something went wrong") + except Exception: + logger.exception("Received an exception") + + # THEN we expect a "stack_trace" not in log + handler({}, lambda_context) + log = capture_logging_output(stdout) + assert "stack_trace" not in log From b615bc44665d7687cefdc2b606295fb21b7640b3 Mon Sep 17 00:00:00 2001 From: RogerZhang Date: Wed, 11 Oct 2023 18:00:15 +0000 Subject: [PATCH 8/9] address Heitor comment on e2e test --- tests/e2e/logger/handlers/tz_handler.py | 6 +++ tests/e2e/logger/test_logger.py | 66 ++++++++++++++++--------- 2 files changed, 49 insertions(+), 23 deletions(-) diff --git a/tests/e2e/logger/handlers/tz_handler.py b/tests/e2e/logger/handlers/tz_handler.py index c872ac62f11..06f6cfbf846 100644 --- a/tests/e2e/logger/handlers/tz_handler.py +++ b/tests/e2e/logger/handlers/tz_handler.py @@ -7,15 +7,21 @@ def lambda_handler(event, context): utc, datefmt, tz = event.get("utc", False), event.get("datefmt", None), event.get("tz", None) if tz: + # set TZ envrionment variable to given tz param os.environ["TZ"] = tz time.tzset() + # init logger using given params logger = Logger(service=f"{utc}-{datefmt}-{tz}", utc=utc, datefmt=datefmt) + + # return the converter this Logger is using if logger.handlers[0].formatter.converter == time.localtime: loggerType = "localtime_converter" elif logger.handlers[0].formatter.converter == time.gmtime: loggerType = "gmtime_converter" else: loggerType = "unknown" + + # print the message to Cloudwatch, timestamp included logger.info(loggerType) return "success" diff --git a/tests/e2e/logger/test_logger.py b/tests/e2e/logger/test_logger.py index 6240a316dde..6a093951354 100644 --- a/tests/e2e/logger/test_logger.py +++ b/tests/e2e/logger/test_logger.py @@ -50,20 +50,20 @@ def test_basic_lambda_logs_visible(basic_handler_fn, basic_handler_fn_arn): assert logs.have_keys(*LOGGER_LAMBDA_CONTEXT_KEYS) is True -# test on combination of utc,tz,datefmt params +# test on combination of tz,datefmt params @pytest.mark.xdist_group(name="logger") -@pytest.mark.parametrize("utc", [False, True]) @pytest.mark.parametrize("tz", ["US/Eastern", "UTC", "Asia/Shanghai"]) @pytest.mark.parametrize("datefmt", ["%z", None]) -def test_lambda_tz(tz_handler_fn, tz_handler_fn_arn, utc, tz, datefmt): - # GIVEN +def test_lambda_tz_with_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): + # GIVEN UTC=True + utc = True payload = json.dumps({"utc": utc, "tz": tz, "datefmt": datefmt}) - # WHEN + # WHEN invoking sample hander using combination of timezone and date format _, execution_time = data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) - # THEN + # get log with matching service id from logger in sample handler logs = data_fetcher.get_logs( function_name=tz_handler_fn, start_time=execution_time, @@ -75,20 +75,40 @@ def test_lambda_tz(tz_handler_fn, tz_handler_fn_arn, utc, tz, datefmt): assert len(result_list) > 0 result = result_list[0] - # When UTC - if utc: - # then use gmt converter - assert result.message == "gmtime_converter" - # When not UTC - else: - # then use local time converter - assert result.message == "localtime_converter" - - if utc: - assert result.timestamp[-5:] == "+0000" - else: - os.environ["TZ"] = tz - time.tzset() - assert result.timestamp[-5:] == time.strftime("%z", time.localtime()) - - print(result) + # Then lambda handler use gmt converter, timezone always in UTC + assert result.message == "gmtime_converter" + assert result.timestamp[-5:] == "+0000" + + +# test on combination of tz,datefmt params on +@pytest.mark.xdist_group(name="logger") +@pytest.mark.parametrize("tz", ["US/Eastern", "UTC", "Asia/Shanghai"]) +@pytest.mark.parametrize("datefmt", ["%z", None]) +def test_lambda_tz_without_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): + # GIVEN UTC=False + utc = False + payload = json.dumps({"utc": utc, "tz": tz, "datefmt": datefmt}) + + # WHEN invoking sample handler using combination of timezone and date format + _, execution_time = data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) + data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) + + # get log with matching service id from logger in sample handler + logs = data_fetcher.get_logs( + function_name=tz_handler_fn, + start_time=execution_time, + minimum_log_entries=1, + filter_expression='{ $.service = "' + f"{utc}-{datefmt}-{tz}" + '" }', + ) + result_list = logs.logs + + assert len(result_list) > 0 + result = result_list[0] + + # then Lambda handler use localtime converter + assert result.message == "localtime_converter" + + # set Tz and assert result is the same as lambda output + os.environ["TZ"] = tz + time.tzset() + assert result.timestamp[-5:] == time.strftime("%z", time.localtime()) From 567fb0b817441bcc1cc9e6f517c314b221f68860 Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Thu, 12 Oct 2023 17:13:56 +0100 Subject: [PATCH 9/9] Adding more information in the e2e tests --- tests/e2e/logger/test_logger.py | 16 +++++++--------- 1 file changed, 7 insertions(+), 9 deletions(-) diff --git a/tests/e2e/logger/test_logger.py b/tests/e2e/logger/test_logger.py index 6a093951354..3aa2433b696 100644 --- a/tests/e2e/logger/test_logger.py +++ b/tests/e2e/logger/test_logger.py @@ -50,12 +50,11 @@ def test_basic_lambda_logs_visible(basic_handler_fn, basic_handler_fn_arn): assert logs.have_keys(*LOGGER_LAMBDA_CONTEXT_KEYS) is True -# test on combination of tz,datefmt params @pytest.mark.xdist_group(name="logger") @pytest.mark.parametrize("tz", ["US/Eastern", "UTC", "Asia/Shanghai"]) @pytest.mark.parametrize("datefmt", ["%z", None]) def test_lambda_tz_with_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): - # GIVEN UTC=True + # GIVEN: UTC is set to True, indicating that the Lambda function must use UTC. utc = True payload = json.dumps({"utc": utc, "tz": tz, "datefmt": datefmt}) @@ -63,7 +62,6 @@ def test_lambda_tz_with_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): _, execution_time = data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) - # get log with matching service id from logger in sample handler logs = data_fetcher.get_logs( function_name=tz_handler_fn, start_time=execution_time, @@ -75,17 +73,17 @@ def test_lambda_tz_with_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): assert len(result_list) > 0 result = result_list[0] - # Then lambda handler use gmt converter, timezone always in UTC + # THEN Make sure that the result list of logs is not empty, indicating that logs were collected + # THEN Make sure that the message in the first log entry indicates the use of "gmtime_converter" assert result.message == "gmtime_converter" assert result.timestamp[-5:] == "+0000" -# test on combination of tz,datefmt params on @pytest.mark.xdist_group(name="logger") @pytest.mark.parametrize("tz", ["US/Eastern", "UTC", "Asia/Shanghai"]) @pytest.mark.parametrize("datefmt", ["%z", None]) def test_lambda_tz_without_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): - # GIVEN UTC=False + # GIVEN: UTC is set to False, indicating that the Lambda function should not use UTC. utc = False payload = json.dumps({"utc": utc, "tz": tz, "datefmt": datefmt}) @@ -93,7 +91,6 @@ def test_lambda_tz_without_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): _, execution_time = data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) data_fetcher.get_lambda_response(lambda_arn=tz_handler_fn_arn, payload=payload) - # get log with matching service id from logger in sample handler logs = data_fetcher.get_logs( function_name=tz_handler_fn, start_time=execution_time, @@ -102,13 +99,14 @@ def test_lambda_tz_without_utc(tz_handler_fn, tz_handler_fn_arn, tz, datefmt): ) result_list = logs.logs + # THEN Make sure that the result list of logs is not empty, indicating that logs were collected + # THEN Make sure that the message in the first log entry indicates the use of "localtime_converter" + # THEN Make sure that the timestamp in the first log entry matches the current time in the specified timezone assert len(result_list) > 0 result = result_list[0] - # then Lambda handler use localtime converter assert result.message == "localtime_converter" - # set Tz and assert result is the same as lambda output os.environ["TZ"] = tz time.tzset() assert result.timestamp[-5:] == time.strftime("%z", time.localtime())