Merge pull request #591 from mdekstrand/feature/json-logging

Add support for 12Factor-style JSON logging

lenskit/lenskit/logging/__init__.py

@@ -2,15 +2,11 @@
 Logging, progress, and resource records.
 """
 
-import os
-from typing import Any
-
-import structlog
-
 from ._proxy import get_logger
 from .config import LoggingConfig, basic_logging
 from .progress import Progress, item_progress, set_progress_impl
 from .tasks import Task
+from .tracing import trace
 
 __all__ = [
     "LoggingConfig",
@@ -22,24 +18,3 @@
     "get_logger",
     "trace",
 ]
-
-_trace_debug = os.environ.get("LK_TRACE", "no").lower() == "debug"
-
-
-def trace(logger: structlog.stdlib.BoundLogger, *args: Any, **kwargs: Any):
-    """
-    Emit a trace-level message, if LensKit tracing is enabled.  Trace-level
-    messages are more fine-grained than debug-level messages, and you usually
-    don't want them.
-
-    This function does not work on the lazy proxies returned by
-    :func:`get_logger` and similar — it only works on bound loggers.
-
-    Stability:
-        Caller
-    """
-    meth = getattr(logger, "trace", None)
-    if meth is not None:
-        meth(*args, **kwargs)
-    elif _trace_debug:
-        logger.debug(*args, **kwargs)

lenskit/lenskit/logging/config.py

@@ -7,8 +7,10 @@
 import logging
 import os
 import re
+import sys
 import warnings
 from pathlib import Path
+from typing import Literal, TypeAlias
 
 import structlog
 
@@ -24,6 +26,7 @@
     structlog.stdlib.PositionalArgumentsFormatter(),
     structlog.processors.MaybeTimeStamper(),
 ]
+LogFormat: TypeAlias = Literal["json", "logfmt", "text"]
 
 _active_config: LoggingConfig | None = None
 
@@ -64,8 +67,10 @@ class LoggingConfig:  # pragma: nocover
     """
 
     level: int = logging.INFO
+    stream_json: bool = False
     file: Path | None = None
     file_level: int | None = None
+    file_format: LogFormat = "json"
 
     def __init__(self):
         # initialize configuration from environment variables
@@ -85,6 +90,12 @@ def effective_level(self) -> int:
         else:
             return self.level
 
+    def set_term_json(self, flag: bool = True):
+        """
+        Configure logging to stream JSON lines to the stderr (useful for web services).
+        """
+        self.stream_json = flag
+
     def set_verbose(self, verbose: bool | int = True):
         """
         Enable verbose logging.
@@ -108,12 +119,15 @@ def set_verbose(self, verbose: bool | int = True):
         else:
             self.level = logging.INFO
 
-    def log_file(self, path: os.PathLike[str], level: int | None = None):
+    def set_log_file(
+        self, path: os.PathLike[str], level: int | None = None, format: LogFormat = "json"
+    ):
         """
         Configure a log file.
         """
         self.file = Path(path)
         self.file_level = level
+        self.file_format = format
 
     def apply(self):
         """
@@ -123,8 +137,15 @@ def apply(self):
 
         setup_console()
         root = logging.getLogger()
-        term = ConsoleHandler()
-        term.setLevel(self.level)
+
+        if self.stream_json:
+            term = logging.StreamHandler(sys.stderr)
+            term.setLevel(self.level)
+            proc_fmt = structlog.processors.JSONRenderer()
+        else:
+            term = ConsoleHandler()
+            term.setLevel(self.level)
+            proc_fmt = structlog.dev.ConsoleRenderer(colors=term.supports_color)
 
         eff_lvl = self.effective_level
         structlog.configure(
@@ -136,7 +157,7 @@ def apply(self):
             processors=[
                 remove_internal,
                 format_timestamp,
-                structlog.dev.ConsoleRenderer(colors=term.supports_color),
+                proc_fmt,
             ],
             foreign_pre_chain=CORE_PROCESSORS,
         )
@@ -147,11 +168,19 @@ def apply(self):
         if self.file:
             file_level = self.file_level if self.file_level is not None else self.level
             file = logging.FileHandler(self.file, mode="w")
+
+            if self.file_format == "json":
+                proc_fmt = structlog.processors.JSONRenderer()
+            elif self.file_format == "logfmt":
+                proc_fmt = structlog.processors.LogfmtRenderer(key_order=["event", "timestamp"])
+            else:
+                proc_fmt = structlog.processors.KeyValueRenderer(key_order=["event", "timestamp"])
+
             ffmt = structlog.stdlib.ProcessorFormatter(
                 processors=[
                     remove_internal,
                     structlog.processors.ExceptionPrettyPrinter(),
-                    structlog.processors.JSONRenderer(),
+                    proc_fmt,
                 ],
                 foreign_pre_chain=CORE_PROCESSORS,
             )

lenskit/lenskit/logging/tracing.py

@@ -5,10 +5,32 @@
 from __future__ import annotations
 
 import logging
+import os
 from typing import Any
 
 import structlog
 
+_trace_debug = os.environ.get("LK_TRACE", "no").lower() == "debug"
+
+
+def trace(logger: structlog.stdlib.BoundLogger, *args: Any, **kwargs: Any):
+    """
+    Emit a trace-level message, if LensKit tracing is enabled.  Trace-level
+    messages are more fine-grained than debug-level messages, and you usually
+    don't want them.
+
+    This function does not work on the lazy proxies returned by
+    :func:`get_logger` and similar — it only works on bound loggers.
+
+    Stability:
+        Caller
+    """
+    meth = getattr(logger, "trace", None)
+    if meth is not None:
+        meth(*args, **kwargs)
+    elif _trace_debug:
+        logger.debug(*args, **kwargs)
+
 
 class TracingLogger(structlog.stdlib.BoundLogger):
     """
@@ -25,7 +47,7 @@ def trace(self, event: str | None, *args: Any, **kw: Any):
         if args:
             kw["positional_args"] = args
         try:
-            args, kwargs = self._process_event("trace", event, kw)
+            args, kwargs = self._process_event("trace", event, kw)  # type: ignore
         except structlog.DropEvent:
             return None
         self._logger.debug(*args, **kwargs)