diff --git a/awslambdaric/bootstrap.py b/awslambdaric/bootstrap.py index 3794e81..e7b9e5a 100644 --- a/awslambdaric/bootstrap.py +++ b/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:
     {@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 |
+    +----------------------+------------------------+---------------------+-----------------------+
     }
     
- 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,13 @@ 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): diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 777625e..edb0737 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -7,6 +7,7 @@ import os import re import tempfile +import time import traceback import unittest from io import StringIO @@ -914,11 +915,13 @@ def test_log_error_standard_log_sink(self, mock_stdout): def test_log_error_framed_log_sink(self): with NamedTemporaryFile() as temp_file: + before = int(time.time_ns() / 1000) with bootstrap.FramedTelemetryLogSink( os.open(temp_file.name, os.O_CREAT | os.O_RDWR) ) as log_sink: err_to_log = bootstrap.make_error("Error message", "ErrorType", None) bootstrap.log_error(err_to_log, log_sink) + after = int(time.time_ns() / 1000) expected_logged_error = ( "[ERROR] ErrorType: Error message\nTraceback (most recent call last):" @@ -928,12 +931,16 @@ def test_log_error_framed_log_sink(self): 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(expected_logged_error.encode("utf8"))) - 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, expected_logged_error) @patch("sys.stdout", new_callable=StringIO) @@ -951,6 +958,7 @@ def test_log_error_indentation_standard_log_sink(self, mock_stdout): def test_log_error_indentation_framed_log_sink(self): with NamedTemporaryFile() as temp_file: + before = int(time.time_ns() / 1000) with bootstrap.FramedTelemetryLogSink( os.open(temp_file.name, os.O_CREAT | os.O_RDWR) ) as log_sink: @@ -958,6 +966,7 @@ def test_log_error_indentation_framed_log_sink(self): "Error message", "ErrorType", [" line1 ", " line2 ", " "] ) bootstrap.log_error(err_to_log, log_sink) + after = int(time.time_ns() / 1000) expected_logged_error = ( "[ERROR] ErrorType: Error message\nTraceback (most recent call last):" @@ -968,12 +977,16 @@ def test_log_error_indentation_framed_log_sink(self): 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(expected_logged_error.encode("utf8"))) - 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, expected_logged_error) @patch("sys.stdout", new_callable=StringIO) @@ -988,6 +1001,7 @@ def test_log_error_empty_stacktrace_line_standard_log_sink(self, mock_stdout): def test_log_error_empty_stacktrace_line_framed_log_sink(self): with NamedTemporaryFile() as temp_file: + before = int(time.time_ns() / 1000) with bootstrap.FramedTelemetryLogSink( os.open(temp_file.name, os.O_CREAT | os.O_RDWR) ) as log_sink: @@ -995,6 +1009,7 @@ def test_log_error_empty_stacktrace_line_framed_log_sink(self): "Error message", "ErrorType", ["line1", "", "line2"] ) bootstrap.log_error(err_to_log, log_sink) + after = int(time.time_ns() / 1000) expected_logged_error = ( "[ERROR] ErrorType: Error message\nTraceback " @@ -1005,17 +1020,22 @@ def test_log_error_empty_stacktrace_line_framed_log_sink(self): 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(expected_logged_error)) - 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, expected_logged_error) # Just to ensure we are not logging the requestId from error response, just sending in the response def test_log_error_invokeId_line_framed_log_sink(self): with NamedTemporaryFile() as temp_file: + before = int(time.time_ns() / 1000) with bootstrap.FramedTelemetryLogSink( os.open(temp_file.name, os.O_CREAT | os.O_RDWR) ) as log_sink: @@ -1026,6 +1046,7 @@ def test_log_error_invokeId_line_framed_log_sink(self): "testrequestId", ) bootstrap.log_error(err_to_log, log_sink) + after = int(time.time_ns() / 1000) expected_logged_error = ( "[ERROR] ErrorType: Error message\nTraceback " @@ -1036,12 +1057,16 @@ def test_log_error_invokeId_line_framed_log_sink(self): 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(expected_logged_error)) - 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, expected_logged_error) @@ -1090,20 +1115,26 @@ 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): @@ -1111,24 +1142,31 @@ def test_multiple_frame(self): 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)