emit multi-line logs with timestamps

Author: Rupayan Ghosh

awslambdaric/bootstrap.py

@@ -312,19 +312,19 @@ class FramedTelemetryLogSink(object):
     framing protocol so message boundaries can be determined. Each frame can be visualized as follows:
      <pre>
     {@code
-    +----------------------+------------------------+-----------------------+
-    | Frame Type - 4 bytes | Length (len) - 4 bytes | Message - 'len' bytes |
-    +----------------------+------------------------+-----------------------+
+    +----------------------+------------------------+---------------------+-----------------------+
+    | Frame Type - 4 bytes | Length (len) - 4 bytes | Timestamp - 8 bytes | Message - 'len' bytes |
+    +----------------------+------------------------+---------------------+-----------------------+
     }
     </pre>
-    The first 4 bytes indicate the type of the frame - log frames have a type defined as the hex value 0xa55a0001. The
-    second 4 bytes should indicate the message's length. The next 'len' bytes contain the message. The byte order is
-    big-endian.
+    The first 4 bytes indicate the type of the frame - log frames have a type defined as the hex value 0xa55a0003. The
+    second 4 bytes should indicate the message's length. The next 8 bytes should indicate the timestamp of the message.
+    The next 'len' bytes contain the message. The byte order is big-endian.
     """
 
     def __init__(self, fd):
         self.fd = int(fd)
-        self.frame_type = 0xA55A0001.to_bytes(4, "big")
+        self.frame_type = 0xA55A0003.to_bytes(4, "big")
 
     def __enter__(self):
         self.file = os.fdopen(self.fd, "wb", 0)
@@ -335,7 +335,8 @@ def __exit__(self, exc_type, exc_value, exc_tb):
 
     def log(self, msg):
         encoded_msg = msg.encode("utf8")
-        log_msg = self.frame_type + len(encoded_msg).to_bytes(4, "big") + encoded_msg
+        timestamp = int(time.time_ns() / 1000) # UNIX timestamp in microseconds
+        log_msg = self.frame_type + len(encoded_msg).to_bytes(4, "big") + timestamp.to_bytes(8, "big") + encoded_msg
         self.file.write(log_msg)
 
     def log_error(self, message_lines):

tests/test_bootstrap.py

@@ -7,6 +7,7 @@
 import os
 import re
 import tempfile
+import time
 import traceback
 import unittest
 from io import StringIO
@@ -1090,45 +1091,58 @@ def test_create_framed_telemetry_log_sinks(self):
     def test_single_frame(self):
         with NamedTemporaryFile() as temp_file:
             message = "hello world\nsomething on a new line!\n"
+            before = int(time.time_ns() / 1000)
             with bootstrap.FramedTelemetryLogSink(
                 os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
             ) as ls:
                 ls.log(message)
+            after = int(time.time_ns() / 1000)
             with open(temp_file.name, "rb") as f:
                 content = f.read()
 
                 frame_type = int.from_bytes(content[:4], "big")
-                self.assertEqual(frame_type, 0xA55A0001)
+                self.assertEqual(frame_type, 0xA55A0003)
 
                 length = int.from_bytes(content[4:8], "big")
                 self.assertEqual(length, len(message))
 
-                actual_message = content[8:].decode()
+                timestamp = int.from_bytes(content[8:16], "big")
+                self.assertTrue(before <= timestamp)
+                self.assertTrue(timestamp <= after)
+
+                actual_message = content[16:].decode()
                 self.assertEqual(actual_message, message)
 
     def test_multiple_frame(self):
         with NamedTemporaryFile() as temp_file:
             first_message = "hello world\nsomething on a new line!"
             second_message = "hello again\nhere's another message\n"
 
+            before = int(time.time_ns() / 1000)
             with bootstrap.FramedTelemetryLogSink(
                 os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
             ) as ls:
                 ls.log(first_message)
                 ls.log(second_message)
+            after = int(time.time_ns() / 1000)
 
             with open(temp_file.name, "rb") as f:
                 content = f.read()
                 pos = 0
                 for message in [first_message, second_message]:
                     frame_type = int.from_bytes(content[pos : pos + 4], "big")
-                    self.assertEqual(frame_type, 0xA55A0001)
+                    self.assertEqual(frame_type, 0xA55A0003)
                     pos += 4
 
                     length = int.from_bytes(content[pos : pos + 4], "big")
                     self.assertEqual(length, len(message))
                     pos += 4
 
+                    timestamp = int.from_bytes(content[pos : pos + 8], "big")
+                    self.assertTrue(before <= timestamp)
+                    self.assertTrue(timestamp <= after)
+                    pos += 8
+
                     actual_message = content[pos : pos + len(message)].decode()
                     self.assertEqual(actual_message, message)
                     pos += len(message)