From 082679f67fc39a10e533104b1b5f4f93b2968dd6 Mon Sep 17 00:00:00 2001 From: Maxime David Date: Fri, 12 Jun 2026 12:26:54 +0000 Subject: [PATCH 1/6] fix: JsonFormatter datetime format to include milliseconds (#156) --- awslambdaric/lambda_runtime_log_utils.py | 7 +- tests/test_lambda_runtime_log_utils.py | 101 +++++++++++++++++++++++ 2 files changed, 107 insertions(+), 1 deletion(-) create mode 100644 tests/test_lambda_runtime_log_utils.py diff --git a/awslambdaric/lambda_runtime_log_utils.py b/awslambdaric/lambda_runtime_log_utils.py index 9ddbcfb..e8f826a 100644 --- a/awslambdaric/lambda_runtime_log_utils.py +++ b/awslambdaric/lambda_runtime_log_utils.py @@ -5,9 +5,10 @@ import json import logging import traceback +from datetime import datetime, timezone from enum import IntEnum -_DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%SZ" +_DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%S" _RESERVED_FIELDS = { "name", "msg", @@ -80,6 +81,10 @@ class JsonFormatter(logging.Formatter): def __init__(self): super().__init__(datefmt=_DATETIME_FORMAT) + def formatTime(self, record, datefmt=None): + dt = datetime.fromtimestamp(record.created, tz=timezone.utc) + return dt.strftime(_DATETIME_FORMAT + ".%f")[:-3] + "Z" + @staticmethod def __format_stacktrace(exc_info): if not exc_info: diff --git a/tests/test_lambda_runtime_log_utils.py b/tests/test_lambda_runtime_log_utils.py new file mode 100644 index 0000000..e9c5b04 --- /dev/null +++ b/tests/test_lambda_runtime_log_utils.py @@ -0,0 +1,101 @@ +""" +Copyright 2024 Amazon.com, Inc. or its affiliates. All Rights Reserved. +""" + +import logging +import json +import re +import time +import unittest + +from awslambdaric.lambda_runtime_log_utils import JsonFormatter + + +class TestJsonFormatterTimestamp(unittest.TestCase): + def setUp(self): + self.formatter = JsonFormatter() + self.logger = logging.getLogger("test") + self.logger.setLevel(logging.INFO) + + def test_timestamp_includes_milliseconds(self): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + output = self.formatter.format(record) + log_entry = json.loads(output) + timestamp = log_entry["timestamp"] + + pattern = r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$" + self.assertRegex( + timestamp, + pattern, + f"Timestamp '{timestamp}' does not match expected format YYYY-MM-DDTHH:MM:SS.mmmZ", + ) + + def test_timestamp_milliseconds_are_accurate(self): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + record.created = 1718838785.068 + output = self.formatter.format(record) + log_entry = json.loads(output) + + self.assertEqual(log_entry["timestamp"], "2024-06-19T23:13:05.068Z") + + def test_timestamp_zero_milliseconds(self): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + record.created = 1718838785.0 + output = self.formatter.format(record) + log_entry = json.loads(output) + + self.assertEqual(log_entry["timestamp"], "2024-06-19T23:13:05.000Z") + + def test_timestamps_differ_within_same_second(self): + record1 = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="first", + args=None, + exc_info=None, + ) + record1.created = 1718838785.100 + + record2 = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="second", + args=None, + exc_info=None, + ) + record2.created = 1718838785.200 + + output1 = json.loads(self.formatter.format(record1)) + output2 = json.loads(self.formatter.format(record2)) + + self.assertNotEqual(output1["timestamp"], output2["timestamp"]) + self.assertEqual(output1["timestamp"], "2024-06-19T23:13:05.100Z") + self.assertEqual(output2["timestamp"], "2024-06-19T23:13:05.200Z") From ec5372ffc69b511538fea68aa58e3e85447343a5 Mon Sep 17 00:00:00 2001 From: Maxime David Date: Fri, 12 Jun 2026 12:29:00 +0000 Subject: [PATCH 2/6] fix: tests --- tests/test_bootstrap.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 1eb2bb0..27e5cf7 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -1250,7 +1250,7 @@ def tearDownClass(cls): def test_handler_setup(self, *_): test_cases = [ (62, 0xA55A0003, 46, {}), - (133, 0xA55A001A, 117, {"AWS_LAMBDA_LOG_FORMAT": "JSON"}), + (137, 0xA55A001A, 121, {"AWS_LAMBDA_LOG_FORMAT": "JSON"}), (62, 0xA55A001B, 46, {"AWS_LAMBDA_LOG_LEVEL": "INFO"}), ] From e9520b31e638c47412899cfb0907917534db94d4 Mon Sep 17 00:00:00 2001 From: Maxime David Date: Fri, 12 Jun 2026 12:57:43 +0000 Subject: [PATCH 3/6] fix: headers --- awslambdaric/lambda_runtime_log_utils.py | 3 ++- tests/test_bootstrap.py | 3 ++- tests/test_lambda_runtime_log_utils.py | 3 ++- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/awslambdaric/lambda_runtime_log_utils.py b/awslambdaric/lambda_runtime_log_utils.py index e8f826a..b684da2 100644 --- a/awslambdaric/lambda_runtime_log_utils.py +++ b/awslambdaric/lambda_runtime_log_utils.py @@ -1,5 +1,6 @@ """ -Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. +SPDX-License-Identifier: Apache-2.0 """ import json diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 27e5cf7..4420300 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -1,5 +1,6 @@ """ -Copyright 2019 Amazon.com, Inc. or its affiliates. All Rights Reserved. +Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. +SPDX-License-Identifier: Apache-2.0 """ import importlib diff --git a/tests/test_lambda_runtime_log_utils.py b/tests/test_lambda_runtime_log_utils.py index e9c5b04..90b880b 100644 --- a/tests/test_lambda_runtime_log_utils.py +++ b/tests/test_lambda_runtime_log_utils.py @@ -1,5 +1,6 @@ """ -Copyright 2024 Amazon.com, Inc. or its affiliates. All Rights Reserved. +Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. +SPDX-License-Identifier: Apache-2.0 """ import logging From 389ec8cec5da0b5f91588e7ad47810477822e649 Mon Sep 17 00:00:00 2001 From: Davide Melfi Date: Thu, 25 Jun 2026 21:41:52 +0100 Subject: [PATCH 4/6] chore: add .gitignore for pyenv/uv --- .gitignore | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/.gitignore b/.gitignore index 0899fc1..4b6d162 100644 --- a/.gitignore +++ b/.gitignore @@ -93,10 +93,10 @@ target/ profile_default/ ipython_config.py -# pyenv -# For a library or package, you might want to ignore these files since the code is -# intended to run in multiple environments; otherwise, check them in: -# .python-version +# pyenv / uv +.python-version +pyproject.toml +uv.lock # pipenv # According to pypa/pipenv#598, it is recommended to include Pipfile.lock in version control. From 4cddb14dc3fa2922559bdb44c34147e37376c3ea Mon Sep 17 00:00:00 2001 From: Davide Melfi Date: Thu, 25 Jun 2026 21:50:23 +0100 Subject: [PATCH 5/6] revert: "fix: JsonFormatter datetime format to include milliseconds (#156)" This reverts commit e47775d. --- awslambdaric/lambda_runtime_log_utils.py | 7 +----- tests/test_bootstrap.py | 2 +- tests/test_lambda_runtime_log_utils.py | 28 +++++++++++++----------- 3 files changed, 17 insertions(+), 20 deletions(-) diff --git a/awslambdaric/lambda_runtime_log_utils.py b/awslambdaric/lambda_runtime_log_utils.py index b684da2..69b1fde 100644 --- a/awslambdaric/lambda_runtime_log_utils.py +++ b/awslambdaric/lambda_runtime_log_utils.py @@ -6,10 +6,9 @@ import json import logging import traceback -from datetime import datetime, timezone from enum import IntEnum -_DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%S" +_DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%SZ" _RESERVED_FIELDS = { "name", "msg", @@ -82,10 +81,6 @@ class JsonFormatter(logging.Formatter): def __init__(self): super().__init__(datefmt=_DATETIME_FORMAT) - def formatTime(self, record, datefmt=None): - dt = datetime.fromtimestamp(record.created, tz=timezone.utc) - return dt.strftime(_DATETIME_FORMAT + ".%f")[:-3] + "Z" - @staticmethod def __format_stacktrace(exc_info): if not exc_info: diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 4420300..2704877 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -1251,7 +1251,7 @@ def tearDownClass(cls): def test_handler_setup(self, *_): test_cases = [ (62, 0xA55A0003, 46, {}), - (137, 0xA55A001A, 121, {"AWS_LAMBDA_LOG_FORMAT": "JSON"}), + (133, 0xA55A001A, 117, {"AWS_LAMBDA_LOG_FORMAT": "JSON"}), (62, 0xA55A001B, 46, {"AWS_LAMBDA_LOG_LEVEL": "INFO"}), ] diff --git a/tests/test_lambda_runtime_log_utils.py b/tests/test_lambda_runtime_log_utils.py index 90b880b..e395027 100644 --- a/tests/test_lambda_runtime_log_utils.py +++ b/tests/test_lambda_runtime_log_utils.py @@ -18,7 +18,7 @@ def setUp(self): self.logger = logging.getLogger("test") self.logger.setLevel(logging.INFO) - def test_timestamp_includes_milliseconds(self): + def test_timestamp_format_is_second_precision_with_z(self): record = logging.LogRecord( name="test", level=logging.INFO, @@ -32,14 +32,14 @@ def test_timestamp_includes_milliseconds(self): log_entry = json.loads(output) timestamp = log_entry["timestamp"] - pattern = r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$" + pattern = r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}Z$" self.assertRegex( timestamp, pattern, - f"Timestamp '{timestamp}' does not match expected format YYYY-MM-DDTHH:MM:SS.mmmZ", + f"Timestamp '{timestamp}' does not match expected format YYYY-MM-DDTHH:MM:SSZ", ) - def test_timestamp_milliseconds_are_accurate(self): + def test_timestamp_value_is_accurate(self): record = logging.LogRecord( name="test", level=logging.INFO, @@ -53,9 +53,12 @@ def test_timestamp_milliseconds_are_accurate(self): output = self.formatter.format(record) log_entry = json.loads(output) - self.assertEqual(log_entry["timestamp"], "2024-06-19T23:13:05.068Z") + expected = time.strftime( + "%Y-%m-%dT%H:%M:%SZ", self.formatter.converter(record.created) + ) + self.assertEqual(log_entry["timestamp"], expected) - def test_timestamp_zero_milliseconds(self): + def test_timestamp_does_not_include_milliseconds(self): record = logging.LogRecord( name="test", level=logging.INFO, @@ -65,13 +68,14 @@ def test_timestamp_zero_milliseconds(self): args=None, exc_info=None, ) - record.created = 1718838785.0 + record.created = 1718838785.999 output = self.formatter.format(record) log_entry = json.loads(output) - self.assertEqual(log_entry["timestamp"], "2024-06-19T23:13:05.000Z") + self.assertNotIn(".", log_entry["timestamp"]) + self.assertTrue(log_entry["timestamp"].endswith("Z")) - def test_timestamps_differ_within_same_second(self): + def test_timestamps_same_within_same_second(self): record1 = logging.LogRecord( name="test", level=logging.INFO, @@ -92,11 +96,9 @@ def test_timestamps_differ_within_same_second(self): args=None, exc_info=None, ) - record2.created = 1718838785.200 + record2.created = 1718838785.900 output1 = json.loads(self.formatter.format(record1)) output2 = json.loads(self.formatter.format(record2)) - self.assertNotEqual(output1["timestamp"], output2["timestamp"]) - self.assertEqual(output1["timestamp"], "2024-06-19T23:13:05.100Z") - self.assertEqual(output2["timestamp"], "2024-06-19T23:13:05.200Z") + self.assertEqual(output1["timestamp"], output2["timestamp"]) From 0474a9386d2697dee6d24bc207a907acbfd0e87f Mon Sep 17 00:00:00 2001 From: Davide Melfi Date: Thu, 25 Jun 2026 22:32:16 +0100 Subject: [PATCH 6/6] feat: adding AWS_LAMBDA_LOG_TIMESTAMP_PRECISION env This is done to support millisecond precision timestamp in the structured logs in cloudwatch as requested in #156. Changing directly to millisecond is a potentially breaking change, so we agreed on supporting this environmental variable on this version of the RIC. We'll remove the support in RIC v5, defaulting to milisecond. --- awslambdaric/bootstrap.py | 6 +- awslambdaric/lambda_runtime_log_utils.py | 31 +++++- tests/test_lambda_runtime_log_utils.py | 133 +++++++++++++++++++++-- 3 files changed, 154 insertions(+), 16 deletions(-) diff --git a/awslambdaric/bootstrap.py b/awslambdaric/bootstrap.py index f54ca1a..010912e 100644 --- a/awslambdaric/bootstrap.py +++ b/awslambdaric/bootstrap.py @@ -14,10 +14,10 @@ from .lambda_runtime_client import LambdaRuntimeClient from .lambda_runtime_exception import FaultException from .lambda_runtime_log_utils import ( - _DATETIME_FORMAT, _DEFAULT_FRAME_TYPE, _JSON_FRAME_TYPES, _TEXT_FRAME_TYPES, + _format_timestamp, JsonFormatter, LogFormat, _format_log_level, @@ -106,9 +106,7 @@ def replace_line_indentation(line, indent_char, new_indent_char): def log_error(error_result, log_sink): error_result = { - "timestamp": time.strftime( - _DATETIME_FORMAT, logging.Formatter.converter(time.time()) - ), + "timestamp": _format_timestamp(time.time()), "log_level": "ERROR", **error_result, } diff --git a/awslambdaric/lambda_runtime_log_utils.py b/awslambdaric/lambda_runtime_log_utils.py index 69b1fde..ef6fde2 100644 --- a/awslambdaric/lambda_runtime_log_utils.py +++ b/awslambdaric/lambda_runtime_log_utils.py @@ -5,10 +5,34 @@ import json import logging +import os import traceback +from datetime import datetime, timezone from enum import IntEnum -_DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%SZ" +# TODO(v5.0): Remove this env var check and make milliseconds the default. +# Once removed, _format_timestamp simplifies to just the millis branch. +_TIMESTAMP_PRECISION_MILLIS = ( + os.environ.get("AWS_LAMBDA_LOG_TIMESTAMP_PRECISION", "").lower() == "milliseconds" +) + + +def _format_timestamp(epoch_secs): + """Format a UTC timestamp in ISO 8601 format. + + Returns second precision by default (e.g. 2024-06-19T23:13:05Z), to avoid breaking changes. + When AWS_LAMBDA_LOG_TIMESTAMP_PRECISION=milliseconds, includes + milliseconds (e.g. 2024-06-19T23:13:05.068Z). + """ + dt = datetime.fromtimestamp(epoch_secs, tz=timezone.utc) + + if _TIMESTAMP_PRECISION_MILLIS: + millis = dt.microsecond // 1000 + return f"{dt:%Y-%m-%dT%H:%M:%S}.{millis:03d}Z" + + return f"{dt:%Y-%m-%dT%H:%M:%S}Z" + + _RESERVED_FIELDS = { "name", "msg", @@ -79,7 +103,10 @@ def _format_log_level(record: logging.LogRecord) -> int: class JsonFormatter(logging.Formatter): def __init__(self): - super().__init__(datefmt=_DATETIME_FORMAT) + super().__init__() + + def formatTime(self, record, datefmt=None): + return _format_timestamp(record.created) @staticmethod def __format_stacktrace(exc_info): diff --git a/tests/test_lambda_runtime_log_utils.py b/tests/test_lambda_runtime_log_utils.py index e395027..14ce3ce 100644 --- a/tests/test_lambda_runtime_log_utils.py +++ b/tests/test_lambda_runtime_log_utils.py @@ -3,20 +3,24 @@ SPDX-License-Identifier: Apache-2.0 """ +import importlib import logging import json -import re +import os import time import unittest +from unittest.mock import patch -from awslambdaric.lambda_runtime_log_utils import JsonFormatter - -class TestJsonFormatterTimestamp(unittest.TestCase): +class TestJsonFormatterTimestampDefaultPrecision(unittest.TestCase): def setUp(self): - self.formatter = JsonFormatter() - self.logger = logging.getLogger("test") - self.logger.setLevel(logging.INFO) + env = os.environ.copy() + env.pop("AWS_LAMBDA_LOG_TIMESTAMP_PRECISION", None) + with patch.dict(os.environ, env, clear=True): + import awslambdaric.lambda_runtime_log_utils as mod + + importlib.reload(mod) + self.formatter = mod.JsonFormatter() def test_timestamp_format_is_second_precision_with_z(self): record = logging.LogRecord( @@ -53,9 +57,7 @@ def test_timestamp_value_is_accurate(self): output = self.formatter.format(record) log_entry = json.loads(output) - expected = time.strftime( - "%Y-%m-%dT%H:%M:%SZ", self.formatter.converter(record.created) - ) + expected = time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(record.created)) self.assertEqual(log_entry["timestamp"], expected) def test_timestamp_does_not_include_milliseconds(self): @@ -102,3 +104,114 @@ def test_timestamps_same_within_same_second(self): output2 = json.loads(self.formatter.format(record2)) self.assertEqual(output1["timestamp"], output2["timestamp"]) + + +class TestJsonFormatterTimestampMillisecondPrecision(unittest.TestCase): + def setUp(self): + env = os.environ.copy() + env["AWS_LAMBDA_LOG_TIMESTAMP_PRECISION"] = "milliseconds" + with patch.dict(os.environ, env, clear=True): + import awslambdaric.lambda_runtime_log_utils as mod + + importlib.reload(mod) + self.formatter = mod.JsonFormatter() + + def test_timestamp_includes_milliseconds(self): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + output = self.formatter.format(record) + log_entry = json.loads(output) + timestamp = log_entry["timestamp"] + + pattern = r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$" + self.assertRegex( + timestamp, + pattern, + f"Timestamp '{timestamp}' does not match expected format YYYY-MM-DDTHH:MM:SS.mmmZ", + ) + + def test_timestamp_milliseconds_are_accurate(self): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + record.created = 1718838785.068 + output = self.formatter.format(record) + log_entry = json.loads(output) + + self.assertEqual(log_entry["timestamp"], "2024-06-19T23:13:05.068Z") + + def test_timestamp_zero_milliseconds(self): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + record.created = 1718838785.0 + output = self.formatter.format(record) + log_entry = json.loads(output) + + self.assertEqual(log_entry["timestamp"], "2024-06-19T23:13:05.000Z") + + def test_timestamps_differ_within_same_second(self): + record1 = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="first", + args=None, + exc_info=None, + ) + record1.created = 1718838785.100 + + record2 = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=1, + msg="second", + args=None, + exc_info=None, + ) + record2.created = 1718838785.200 + + output1 = json.loads(self.formatter.format(record1)) + output2 = json.loads(self.formatter.format(record2)) + + self.assertNotEqual(output1["timestamp"], output2["timestamp"]) + self.assertEqual(output1["timestamp"], "2024-06-19T23:13:05.100Z") + self.assertEqual(output2["timestamp"], "2024-06-19T23:13:05.200Z") + + +class TestTimestampPrecisionVersionGate(unittest.TestCase): + """Fails if we bump to v5+ without removing the seconds-precision path.""" + + def test_v5_must_remove_timestamp_precision_env_var(self): + from awslambdaric import __version__ + + major = int(__version__.split(".")[0]) + if major >= 5: + import awslambdaric.lambda_runtime_log_utils as mod + + self.assertFalse( + hasattr(mod, "_TIMESTAMP_PRECISION_MILLIS"), + "v5+: remove _TIMESTAMP_PRECISION_MILLIS and make milliseconds " + "the default. See TODO(v5.0) in lambda_runtime_log_utils.py", + )