From ff4826e07c8084af5fc87cb46cbf1fc2bd73a922 Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Mon, 6 Jan 2025 15:56:49 -0500 Subject: [PATCH 1/3] move trace function into tracing.py --- lenskit/lenskit/logging/__init__.py | 27 +-------------------------- lenskit/lenskit/logging/tracing.py | 24 +++++++++++++++++++++++- 2 files changed, 24 insertions(+), 27 deletions(-) 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/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) From ab3e2f0fdbd345dde1130c1d81a6ab4bffbb1b9f Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Mon, 6 Jan 2025 16:58:03 -0500 Subject: [PATCH 2/3] add JSON logging support to logging configuration --- lenskit/lenskit/logging/config.py | 39 +++++++++++++++++++++++++++---- 1 file changed, 34 insertions(+), 5 deletions(-) diff --git a/lenskit/lenskit/logging/config.py b/lenskit/lenskit/logging/config.py index 873f5b2b1..9e21fec8f 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 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 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, ) From bcccbad9d81cccf6a5a449e9eb6729c40f5cb665 Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Mon, 6 Jan 2025 17:17:24 -0500 Subject: [PATCH 3/3] rename methods for consistency --- lenskit/lenskit/logging/config.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lenskit/lenskit/logging/config.py b/lenskit/lenskit/logging/config.py index 9e21fec8f..567454787 100644 --- a/lenskit/lenskit/logging/config.py +++ b/lenskit/lenskit/logging/config.py @@ -90,7 +90,7 @@ def effective_level(self) -> int: else: return self.level - def term_json(self, flag: bool = True): + def set_term_json(self, flag: bool = True): """ Configure logging to stream JSON lines to the stderr (useful for web services). """ @@ -119,7 +119,7 @@ def set_verbose(self, verbose: bool | int = True): else: self.level = logging.INFO - def log_file( + def set_log_file( self, path: os.PathLike[str], level: int | None = None, format: LogFormat = "json" ): """