Skip to content

Commit 97dee25

Browse files
brienseabriensea
authored
Merge pull request aws#92 from thenewguy39/main
Emit multi-line logs with timestamps
2 parents 970e9c1 + 50fddc4 commit 97dee25

File tree

2 files changed

+63
-19
lines changed

2 files changed

+63
-19
lines changed

‎awslambdaric/bootstrap.py‎

Lines changed: 14 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -312,19 +312,19 @@ class FramedTelemetryLogSink(object):
312312
framing protocol so message boundaries can be determined. Each frame can be visualized as follows:
313313
<pre>
314314
{@code
315-
+----------------------+------------------------+-----------------------+
316-
| Frame Type - 4 bytes | Length (len) - 4 bytes | Message - 'len' bytes |
317-
+----------------------+------------------------+-----------------------+
315+
+----------------------+------------------------+---------------------+-----------------------+
316+
| Frame Type - 4 bytes | Length (len) - 4 bytes | Timestamp - 8 bytes | Message - 'len' bytes |
317+
+----------------------+------------------------+---------------------+-----------------------+
318318
}
319319
</pre>
320-
The first 4 bytes indicate the type of the frame - log frames have a type defined as the hex value 0xa55a0001. The
321-
second 4 bytes should indicate the message's length. The next 'len' bytes contain the message. The byte order is
322-
big-endian.
320+
The first 4 bytes indicate the type of the frame - log frames have a type defined as the hex value 0xa55a0003. The
321+
second 4 bytes should indicate the message's length. The next 8 bytes should indicate the timestamp of the message.
322+
The next 'len' bytes contain the message. The byte order is big-endian.
323323
"""
324324

325325
def __init__(self, fd):
326326
self.fd = int(fd)
327-
self.frame_type = 0xA55A0001.to_bytes(4, "big")
327+
self.frame_type = 0xA55A0003.to_bytes(4, "big")
328328

329329
def __enter__(self):
330330
self.file = os.fdopen(self.fd, "wb", 0)
@@ -335,7 +335,13 @@ def __exit__(self, exc_type, exc_value, exc_tb):
335335

336336
def log(self, msg):
337337
encoded_msg = msg.encode("utf8")
338-
log_msg = self.frame_type + len(encoded_msg).to_bytes(4, "big") + encoded_msg
338+
timestamp = int(time.time_ns() / 1000) # UNIX timestamp in microseconds
339+
log_msg = (
340+
self.frame_type
341+
+ len(encoded_msg).to_bytes(4, "big")
342+
+ timestamp.to_bytes(8, "big")
343+
+ encoded_msg
344+
)
339345
self.file.write(log_msg)
340346

341347
def log_error(self, message_lines):

‎tests/test_bootstrap.py‎

Lines changed: 49 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
import os
88
import re
99
import tempfile
10+
import time
1011
import traceback
1112
import unittest
1213
from io import StringIO
@@ -914,11 +915,13 @@ def test_log_error_standard_log_sink(self, mock_stdout):
914915

915916
def test_log_error_framed_log_sink(self):
916917
with NamedTemporaryFile() as temp_file:
918+
before = int(time.time_ns() / 1000)
917919
with bootstrap.FramedTelemetryLogSink(
918920
os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
919921
) as log_sink:
920922
err_to_log = bootstrap.make_error("Error message", "ErrorType", None)
921923
bootstrap.log_error(err_to_log, log_sink)
924+
after = int(time.time_ns() / 1000)
922925

923926
expected_logged_error = (
924927
"[ERROR] ErrorType: Error message\nTraceback (most recent call last):"
@@ -928,12 +931,16 @@ def test_log_error_framed_log_sink(self):
928931
content = f.read()
929932

930933
frame_type = int.from_bytes(content[:4], "big")
931-
self.assertEqual(frame_type, 0xA55A0001)
934+
self.assertEqual(frame_type, 0xA55A0003)
932935

933936
length = int.from_bytes(content[4:8], "big")
934937
self.assertEqual(length, len(expected_logged_error.encode("utf8")))
935938

936-
actual_message = content[8:].decode()
939+
timestamp = int.from_bytes(content[8:16], "big")
940+
self.assertTrue(before <= timestamp)
941+
self.assertTrue(timestamp <= after)
942+
943+
actual_message = content[16:].decode()
937944
self.assertEqual(actual_message, expected_logged_error)
938945

939946
@patch("sys.stdout", new_callable=StringIO)
@@ -951,13 +958,15 @@ def test_log_error_indentation_standard_log_sink(self, mock_stdout):
951958

952959
def test_log_error_indentation_framed_log_sink(self):
953960
with NamedTemporaryFile() as temp_file:
961+
before = int(time.time_ns() / 1000)
954962
with bootstrap.FramedTelemetryLogSink(
955963
os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
956964
) as log_sink:
957965
err_to_log = bootstrap.make_error(
958966
"Error message", "ErrorType", [" line1 ", " line2 ", " "]
959967
)
960968
bootstrap.log_error(err_to_log, log_sink)
969+
after = int(time.time_ns() / 1000)
961970

962971
expected_logged_error = (
963972
"[ERROR] ErrorType: Error message\nTraceback (most recent call last):"
@@ -968,12 +977,16 @@ def test_log_error_indentation_framed_log_sink(self):
968977
content = f.read()
969978

970979
frame_type = int.from_bytes(content[:4], "big")
971-
self.assertEqual(frame_type, 0xA55A0001)
980+
self.assertEqual(frame_type, 0xA55A0003)
972981

973982
length = int.from_bytes(content[4:8], "big")
974983
self.assertEqual(length, len(expected_logged_error.encode("utf8")))
975984

976-
actual_message = content[8:].decode()
985+
timestamp = int.from_bytes(content[8:16], "big")
986+
self.assertTrue(before <= timestamp)
987+
self.assertTrue(timestamp <= after)
988+
989+
actual_message = content[16:].decode()
977990
self.assertEqual(actual_message, expected_logged_error)
978991

979992
@patch("sys.stdout", new_callable=StringIO)
@@ -988,13 +1001,15 @@ def test_log_error_empty_stacktrace_line_standard_log_sink(self, mock_stdout):
9881001

9891002
def test_log_error_empty_stacktrace_line_framed_log_sink(self):
9901003
with NamedTemporaryFile() as temp_file:
1004+
before = int(time.time_ns() / 1000)
9911005
with bootstrap.FramedTelemetryLogSink(
9921006
os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
9931007
) as log_sink:
9941008
err_to_log = bootstrap.make_error(
9951009
"Error message", "ErrorType", ["line1", "", "line2"]
9961010
)
9971011
bootstrap.log_error(err_to_log, log_sink)
1012+
after = int(time.time_ns() / 1000)
9981013

9991014
expected_logged_error = (
10001015
"[ERROR] ErrorType: Error message\nTraceback "
@@ -1005,17 +1020,22 @@ def test_log_error_empty_stacktrace_line_framed_log_sink(self):
10051020
content = f.read()
10061021

10071022
frame_type = int.from_bytes(content[:4], "big")
1008-
self.assertEqual(frame_type, 0xA55A0001)
1023+
self.assertEqual(frame_type, 0xA55A0003)
10091024

10101025
length = int.from_bytes(content[4:8], "big")
10111026
self.assertEqual(length, len(expected_logged_error))
10121027

1013-
actual_message = content[8:].decode()
1028+
timestamp = int.from_bytes(content[8:16], "big")
1029+
self.assertTrue(before <= timestamp)
1030+
self.assertTrue(timestamp <= after)
1031+
1032+
actual_message = content[16:].decode()
10141033
self.assertEqual(actual_message, expected_logged_error)
10151034

10161035
# Just to ensure we are not logging the requestId from error response, just sending in the response
10171036
def test_log_error_invokeId_line_framed_log_sink(self):
10181037
with NamedTemporaryFile() as temp_file:
1038+
before = int(time.time_ns() / 1000)
10191039
with bootstrap.FramedTelemetryLogSink(
10201040
os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
10211041
) as log_sink:
@@ -1026,6 +1046,7 @@ def test_log_error_invokeId_line_framed_log_sink(self):
10261046
"testrequestId",
10271047
)
10281048
bootstrap.log_error(err_to_log, log_sink)
1049+
after = int(time.time_ns() / 1000)
10291050

10301051
expected_logged_error = (
10311052
"[ERROR] ErrorType: Error message\nTraceback "
@@ -1036,12 +1057,16 @@ def test_log_error_invokeId_line_framed_log_sink(self):
10361057
content = f.read()
10371058

10381059
frame_type = int.from_bytes(content[:4], "big")
1039-
self.assertEqual(frame_type, 0xA55A0001)
1060+
self.assertEqual(frame_type, 0xA55A0003)
10401061

10411062
length = int.from_bytes(content[4:8], "big")
10421063
self.assertEqual(length, len(expected_logged_error))
10431064

1044-
actual_message = content[8:].decode()
1065+
timestamp = int.from_bytes(content[8:16], "big")
1066+
self.assertTrue(before <= timestamp)
1067+
self.assertTrue(timestamp <= after)
1068+
1069+
actual_message = content[16:].decode()
10451070
self.assertEqual(actual_message, expected_logged_error)
10461071

10471072

@@ -1090,45 +1115,58 @@ def test_create_framed_telemetry_log_sinks(self):
10901115
def test_single_frame(self):
10911116
with NamedTemporaryFile() as temp_file:
10921117
message = "hello world\nsomething on a new line!\n"
1118+
before = int(time.time_ns() / 1000)
10931119
with bootstrap.FramedTelemetryLogSink(
10941120
os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
10951121
) as ls:
10961122
ls.log(message)
1123+
after = int(time.time_ns() / 1000)
10971124
with open(temp_file.name, "rb") as f:
10981125
content = f.read()
10991126

11001127
frame_type = int.from_bytes(content[:4], "big")
1101-
self.assertEqual(frame_type, 0xA55A0001)
1128+
self.assertEqual(frame_type, 0xA55A0003)
11021129

11031130
length = int.from_bytes(content[4:8], "big")
11041131
self.assertEqual(length, len(message))
11051132

1106-
actual_message = content[8:].decode()
1133+
timestamp = int.from_bytes(content[8:16], "big")
1134+
self.assertTrue(before <= timestamp)
1135+
self.assertTrue(timestamp <= after)
1136+
1137+
actual_message = content[16:].decode()
11071138
self.assertEqual(actual_message, message)
11081139

11091140
def test_multiple_frame(self):
11101141
with NamedTemporaryFile() as temp_file:
11111142
first_message = "hello world\nsomething on a new line!"
11121143
second_message = "hello again\nhere's another message\n"
11131144

1145+
before = int(time.time_ns() / 1000)
11141146
with bootstrap.FramedTelemetryLogSink(
11151147
os.open(temp_file.name, os.O_CREAT | os.O_RDWR)
11161148
) as ls:
11171149
ls.log(first_message)
11181150
ls.log(second_message)
1151+
after = int(time.time_ns() / 1000)
11191152

11201153
with open(temp_file.name, "rb") as f:
11211154
content = f.read()
11221155
pos = 0
11231156
for message in [first_message, second_message]:
11241157
frame_type = int.from_bytes(content[pos : pos + 4], "big")
1125-
self.assertEqual(frame_type, 0xA55A0001)
1158+
self.assertEqual(frame_type, 0xA55A0003)
11261159
pos += 4
11271160

11281161
length = int.from_bytes(content[pos : pos + 4], "big")
11291162
self.assertEqual(length, len(message))
11301163
pos += 4
11311164

1165+
timestamp = int.from_bytes(content[pos : pos + 8], "big")
1166+
self.assertTrue(before <= timestamp)
1167+
self.assertTrue(timestamp <= after)
1168+
pos += 8
1169+
11321170
actual_message = content[pos : pos + len(message)].decode()
11331171
self.assertEqual(actual_message, message)
11341172
pos += len(message)

0 commit comments

Comments
 (0)