Skip to content

Emit multi-line logs with timestamps #92

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

Merged
merged 4 commits into from
Feb 16, 2023
Merged

Emit multi-line logs with timestamps #92

Changes from 1 commit
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.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 28 additions & 4 deletions tests/test_bootstrap.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -915,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 @@ -934,7 +936,11 @@ def test_log_error_framed_log_sink(self):
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 @@ -952,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 @@ -974,7 +982,11 @@ def test_log_error_indentation_framed_log_sink(self):
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 @@ -989,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 @@ -1011,12 +1025,17 @@ def test_log_error_empty_stacktrace_line_framed_log_sink(self):
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 @@ -1027,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 @@ -1042,7 +1062,11 @@ def test_log_error_invokeId_line_framed_log_sink(self):
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