diff --git a/lenskit/lenskit/logging/__init__.py b/lenskit/lenskit/logging/__init__.py index c9a8a84c3..437d1f86c 100644 --- a/lenskit/lenskit/logging/__init__.py +++ b/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) diff --git a/lenskit/lenskit/logging/config.py b/lenskit/lenskit/logging/config.py index 873f5b2b1..567454787 100644 --- a/lenskit/lenskit/logging/config.py +++ b/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, ) diff --git a/lenskit/lenskit/logging/tracing.py b/lenskit/lenskit/logging/tracing.py index 182aea2e9..296ec6bfc 100644 --- a/lenskit/lenskit/logging/tracing.py +++ b/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)