Log top level errors as JSON

Author: Artem Krivonos

awslambdaric/bootstrap.py

@@ -13,11 +13,16 @@
 from .lambda_context import LambdaContext
 from .lambda_runtime_client import LambdaRuntimeClient
 from .lambda_runtime_exception import FaultException
-from .lambda_runtime_log_utils import INVOCATION_LOGGING_CONTEXT, JsonFormatter
+from .lambda_runtime_log_utils import (
+    INVOCATION_LOGGING_CONTEXT,
+    JsonFormatter,
+    DATETIME_FORMAT,
+)
 from .lambda_runtime_marshaller import to_json
 
 ERROR_LOG_LINE_TERMINATE = "\r"
 ERROR_LOG_IDENT = "\u00a0"  # NO-BREAK SPACE U+00A0
+RUNTIME_ERROR_LOGGER_NAME = "system"
 
 
 def _get_handler(handler):
@@ -74,8 +79,15 @@ def result(*args):
     return result
 
 
-def make_error(error_message, error_type, stack_trace, invoke_id=None):
+def make_error(
+    error_message, error_type, stack_trace, invoke_id=None, level=logging.ERROR
+):
     result = {
+        "timestamp": time.strftime(
+            DATETIME_FORMAT, logging.Formatter.converter(time.time())
+        ),
+        "level": level,
+        "logger": RUNTIME_ERROR_LOGGER_NAME,
         "errorMessage": error_message if error_message else "",
         "errorType": error_type if error_type else "",
         "requestId": invoke_id if invoke_id is not None else "",
@@ -94,6 +106,19 @@ def replace_line_indentation(line, indent_char, new_indent_char):
 
 
 def log_error(error_result, log_sink):
+    if AWS_LAMBDA_LOG_FORMAT == "JSON":
+        log_error_json(error_result, log_sink)
+    else:
+        log_error_text(error_result, log_sink)
+
+
+def log_error_json(error_result, log_sink):
+    log_sink.log_error(
+        [to_json(error_result)], log_level=error_result.get("level", logging.ERROR)
+    )
+
+
+def log_error_text(error_result, log_sink):
     error_description = "[ERROR]"
 
     error_result_type = error_result.get("errorType")
@@ -120,7 +145,9 @@ def log_error(error_result, log_sink):
                         replace_line_indentation(trace_line, " ", ERROR_LOG_IDENT)
                     ]
 
-    log_sink.log_error(error_message_lines)
+    log_sink.log_error(
+        error_message_lines, log_level=error_result.get("level", logging.ERROR)
+    )
 
 
 def handle_event_request(
@@ -153,7 +180,9 @@ def handle_event_request(
         )
     except FaultException as e:
         xray_fault = make_xray_fault("LambdaValidationError", e.msg, os.getcwd(), [])
-        error_result = make_error(e.msg, e.exception_type, e.trace, invoke_id)
+        error_result = make_error(
+            e.msg, e.exception_type, e.trace, invoke_id, level=logging.FATAL
+        )
 
     except Exception:
         etype, value, tb = sys.exc_info()
@@ -222,7 +251,10 @@ def build_fault_result(exc_info, msg):
             break
 
     return make_error(
-        msg if msg else str(value), etype.__name__, traceback.format_list(tb_tuples)
+        msg if msg else str(value),
+        etype.__name__,
+        traceback.format_list(tb_tuples),
+        level=logging.FATAL,
     )
 
 
@@ -304,10 +336,10 @@ def __enter__(self):
     def __exit__(self, exc_type, exc_value, exc_tb):
         pass
 
-    def log(self, msg, log_level=None, log_format=None):
+    def log(self, msg, log_level=logging.NOTSET, log_format="TEXT"):
         sys.stdout.write(msg)
 
-    def log_error(self, message_lines):
+    def log_error(self, message_lines, log_level=logging.ERROR):
         error_message = ERROR_LOG_LINE_TERMINATE.join(message_lines) + "\n"
         sys.stdout.write(error_message)
 
@@ -377,9 +409,9 @@ def log(self, msg, log_level=logging.NOTSET, log_format="TEXT"):
         )
         self.file.write(log_msg)
 
-    def log_error(self, message_lines):
+    def log_error(self, message_lines, log_level=logging.ERROR):
         error_message = "\n".join(message_lines)
-        self.log(error_message, log_level=logging.FATAL)
+        self.log(error_message, log_level=log_level)
 
 
 def update_xray_env_variable(xray_trace_id):

awslambdaric/lambda_runtime_log_utils.py

@@ -7,6 +7,7 @@
 
 from .lambda_runtime_marshaller import to_json
 
+DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%SZ"
 RESERVED_FIELDS = {
     "name",
     "msg",
@@ -35,7 +36,7 @@
 
 class JsonFormatter(logging.Formatter):
     def __init__(self):
-        super().__init__(datefmt="%Y-%m-%dT%H:%M:%SZ", validate=False)
+        super().__init__(datefmt=DATETIME_FORMAT, validate=False)
 
     @staticmethod
     def format_stacktrace(exc_info):

tests/test_bootstrap.py

@@ -398,6 +398,8 @@ def raise_exception_handler(json_input, lambda_context):
                 )
 
         expected_response = {
+            "level": 50,
+            "logger": "system",
             "errorType": "FaultExceptionType",
             "errorMessage": "Fault exception msg",
             "requestId": "invoke_id",
@@ -417,6 +419,7 @@ def raise_exception_handler(json_input, lambda_context):
         )
         args, _ = self.lambda_runtime.post_invocation_error.call_args
         error_response = json.loads(args[1])
+        self.assertIsNotNone(error_response.pop("timestamp"))
         self.assertEqual(args[0], "invoke_id")
         self.assertEqual(error_response.items(), expected_response.items())
         self.assertEqual(
@@ -938,7 +941,7 @@ def test_log_error_framed_log_sink(self):
                 content = f.read()
 
                 frame_type = int.from_bytes(content[:4], "big")
-                self.assertEqual(frame_type, 0xA55A001B)
+                self.assertEqual(frame_type, 0xA55A0017)
 
                 length = int.from_bytes(content[4:8], "big")
                 self.assertEqual(length, len(expected_logged_error.encode("utf8")))
@@ -984,7 +987,7 @@ def test_log_error_indentation_framed_log_sink(self):
                 content = f.read()
 
                 frame_type = int.from_bytes(content[:4], "big")
-                self.assertEqual(frame_type, 0xA55A001B)
+                self.assertEqual(frame_type, 0xA55A0017)
 
                 length = int.from_bytes(content[4:8], "big")
                 self.assertEqual(length, len(expected_logged_error.encode("utf8")))
@@ -1027,7 +1030,7 @@ 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, 0xA55A001B)
+                self.assertEqual(frame_type, 0xA55A0017)
 
                 length = int.from_bytes(content[4:8], "big")
                 self.assertEqual(length, len(expected_logged_error))
@@ -1064,7 +1067,7 @@ 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, 0xA55A001B)
+                self.assertEqual(frame_type, 0xA55A0017)
 
                 length = int.from_bytes(content[4:8], "big")
                 self.assertEqual(length, len(expected_logged_error))