Format logs with call ID and one-line exceptions

Python exception backtraces were sent as multiple separate lines. This
is inconvenient for logging services like Papertrail and OCI Logging
which create a record for each line. This patch formats the backtrace
as a single line.

The Call ID is logged with all log lines. This makes it easier to
identify which log lines belong to which call.

The current time is no longer logged.  Log destinations such as
Papertrail and OCI Logging record and display the log event time, so
this information is redundant.

Author: Matt Curtis

fdk/log.py

@@ -15,6 +15,20 @@
 import logging
 import os
 import sys
+from contextvars import ContextVar
+
+
+__fn_request_id__ = ContextVar("fn_request_id", default=None)
+
+
+def set_request_id(rid):
+    __fn_request_id__.set(rid)
+
+
+class RequestFormatter(logging.Formatter):
+    def format(self, record):
+        record.fn_request_id = __fn_request_id__.get()
+        return super().format(record)
 
 
 def __setup_logger():
@@ -27,8 +41,8 @@ def __setup_logger():
         root.setLevel(logging.DEBUG)
 
     ch = logging.StreamHandler(sys.stderr)
-    formatter = logging.Formatter(
-        '%(asctime)s - '
+    formatter = RequestFormatter(
+        '%(fn_request_id)s - '
         '%(name)s - '
         '%(levelname)s - '
         '%(message)s'
@@ -48,3 +62,10 @@ def get_logger():
 
 def log(message):
     __log__.debug(message)
+
+
+__request_log__ = logging.getLogger('fn')
+
+
+def get_request_log():
+    return __request_log__

fdk/runner.py

@@ -81,6 +81,7 @@ async def handle_request(handler_code, format_def, **kwargs):
     """
     log.log("in handle_request")
     ctx, body = context.context_from_format(format_def, **kwargs)
+    log.set_request_id(ctx.CallID())
     log.log("context provisioned")
     try:
         response_data = await with_deadline(ctx, handler_code, body)
@@ -96,5 +97,8 @@ async def handle_request(handler_code, format_def, **kwargs):
 
     except (Exception, TimeoutError) as ex:
         log.log("exception appeared: {0}".format(ex))
-        traceback.print_exc(file=sys.stderr)
+        (exctype, value, tb) = sys.exc_info()
+        tb_flat = ''.join(
+            s.replace('\n', '\\n') for s in traceback.format_tb(tb))
+        log.get_request_log().error('{}:{}'.format(value, tb_flat))
         return errors.DispatchException(ctx, 502, str(ex)).response()