Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Emit multi-line logs with timestamps #92

Merged
merged 4 commits into from
Feb 16, 2023
Merged

Emit multi-line logs with timestamps #92

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
cbb069b
emit multi-line logs with timestamps
Jan 9, 2023
4b74229
black formatting
Jan 18, 2023
dc221a6
fix tests
Jan 18, 2023
50fddc4
read timestamp in tests
Jan 18, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
22 changes: 14 additions & 8 deletions awslambdaric/bootstrap.py
View file
Open in desktop
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
Open in desktop
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)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: adding randomness into unit tests is discouraged. In this particular case it should not cause losing determinism, so it's fine to leave if here


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