fix: timestamp format in logs

awslambdaric/lambda_runtime_log_utils.py

@@ -1,13 +1,15 @@
 """
-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
 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 +82,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:

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
@@ -1250,7 +1251,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"}),
         ]
 

tests/test_lambda_runtime_log_utils.py

@@ -0,0 +1,102 @@
+"""
+Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+SPDX-License-Identifier: Apache-2.0
+"""
+
+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")