Skip to content

Commit

Permalink
Merge pull request #92 from thenewguy39/main
Browse files Browse the repository at this point in the history 
Emit multi-line logs with timestamps
  • Loading branch information
@briensea
briensea committed Feb 16, 2023
2 parents 970e9c1 + 50fddc4 commit 97dee25
Show file tree
Hide file tree
Showing 2 changed files with 63 additions and 19 deletions.
22 changes: 14 additions & 8 deletions awslambdaric/bootstrap.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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):
Expand Down
60 changes: 49 additions & 11 deletions tests/test_bootstrap.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
import os
import re
import tempfile
import time
import traceback
import unittest
from io import StringIO
Expand Down Expand Up @@ -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):"
Expand All @@ -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)
Expand All @@ -951,13 +958,15 @@ 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:
err_to_log = bootstrap.make_error(
"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):"
Expand All @@ -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)
Expand All @@ -988,13 +1001,15 @@ 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:
err_to_log = bootstrap.make_error(
"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 "
Expand All @@ -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:
Expand All @@ -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 "
Expand All @@ -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)


Expand Down Expand Up @@ -1090,45 +1115,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)
Expand Down

0 comments on commit 97dee25

Please sign in to comment.