Service and Access Logging

[parano]

• Logging format design
• Logging configuration design
• API Server request/response logging
• Runner input/output logging

[ssheng]

Formats

Service Log

• This is your everyday app logs.
• Logs the console by default with the following format, and optionally to a file active.log controlled by configuration.

[%(asctime)s] %(levelname)s [%(component)s] [%(trace_id)s] [%(span_id)s] %(message)s

Example of logs related to a request.

[22:09:58] INFO     [api_service] [f04cbae0-71db-11ec-9e77-acde48001122] [aaebef7a-790b-11ec-9319-acde48001122] a quick brown fox jumps over a lazy dog 
           WARNING  [iris_runner] [754e4c62-71ec-11ec-af91-acde48001122] [b2b19b56-790b-11ec-9319-acde48001122] a quick brown fox jumps over a lazy dog 
           ERROR    [iris_runner] [f04d4d16-71db-11ec-9e77-acde48001122] [b982100a-790b-11ec-9319-acde48001122] a quick brown fox jumps over a lazy dog

Example of logs unrelated to requests, e.g. startup, shutdown logs, with trace ID empty.

[22:09:58] INFO     [api_service] [] [] a quick brown fox jumps over a lazy dog  
           WARNING  [iris_runner] [] [] a quick brown fox jumps over a lazy dog
           ERROR    [iris_runner] [] [] a quick brown fox jumps over a lazy dog

Access Log

• Human readable request and response metadata.
• Logs to console by default with the following format, and optionally logged to a the access.log file controlled by a config key.
• Implemented as an ASGI Middleware and disable Uvicorn’s native access log.

[%(asctime)s] %(levelname)s [%(name)s] [%(trace_id)s] [%(span_id)s] %(address)s:%(port)s %(request)s %(response)s %(latency)3fms

Example:

[01:08:46] INFO     [f04cbae0-71db-11ec-9e77-acde48001122] [aaebef7a-790b-11ec-9319-acde48001122] 127.0.0.1:60650 (scheme=http,method=POST,path=/classify,length=9) (status=200,length=1) 0.461423ms

Propagation

• Trace contexts like trace_id and span_id need to be propagated between different processes and coroutines.

• Configure a trace filters for each logger to include the trace contexts in the log record.

  from contextvars import ContextVar
  from logging import Filter
  
  class TraceFilter(Filter):
    def __init__(self):
          self.run_id_key = ContextVar("component_key", default="")
          self.request_id_key = ContextVar("request_id_key", default="")
          self.span_id_key = ContextVar("span_id_key", default="")
          self.trace_id_key = ContextVar("trace_id_key", default="")
  
    def filter(self, record):
      record.component = contextvars.get(component_key)
      record.request_id = contextvars.get(request_id_key)
      record.span_id = contextvars.get(span_id_key)
      record.trace_id = contextvars.get(trace_id_key)
      return Filter.filter(self, record)

• Logging formatter can include trace contexts in the format string.

Configuration

• Logging configuration will no longer be one-size-fit-all but context-aware.
  • CLI logging will be configured to log to console only and INFO+.
    • Remove timestamp, level, and other applicable format changes.
  • Bento server will configure logging during server startup.
    • Application logs (default: console=enabled, file=disabled)
    • Access logs (default: console=enabled, file=disabled)
  • SDK will not configure log explicitly but will respect the logging configuration of the user
• Configuration will enable bentoml prefixed loggers only and ignore all third party loggers.
  • Config option to enable 3rd party logs by level.
• Configuration format will not be configurable by users.
• Logging agents like promtail and fluent bit to stream logs to std::out.