From 1de06962d258fc5fe5dee142fc610e3008445884 Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Sat, 7 Dec 2024 12:12:41 -0500 Subject: [PATCH 1/4] automatically log worker process info --- lenskit/lenskit/logging/processors.py | 15 +++++++++++++++ lenskit/lenskit/logging/worker.py | 9 ++++++++- 2 files changed, 23 insertions(+), 1 deletion(-) diff --git a/lenskit/lenskit/logging/processors.py b/lenskit/lenskit/logging/processors.py index 1d7b2109..31b05784 100644 --- a/lenskit/lenskit/logging/processors.py +++ b/lenskit/lenskit/logging/processors.py @@ -2,6 +2,7 @@ LensKit logging processors. """ +import multiprocessing as mp from datetime import datetime from typing import Any @@ -32,3 +33,17 @@ def format_timestamp(logger: Any, method: str, event_dict: EventDict) -> EventDi return event_dict else: return event_dict + + +def add_process_info(logger: Any, method: str, event_dict: EventDict) -> EventDict: + """ + Add process info if it does not exist. + """ + + proc = mp.current_process() + if "pid" not in event_dict: + event_dict["pid"] = proc.pid + if "pname" not in event_dict: + event_dict["pname"] = proc.name + + return event_dict diff --git a/lenskit/lenskit/logging/worker.py b/lenskit/lenskit/logging/worker.py index da4171f2..293494eb 100644 --- a/lenskit/lenskit/logging/worker.py +++ b/lenskit/lenskit/logging/worker.py @@ -23,8 +23,10 @@ from .config import CORE_PROCESSORS, active_logging_config from .monitor import get_monitor +from .processors import add_process_info _active_context: WorkerContext | None = None +_log = structlog.stdlib.get_logger(__name__) @dataclass @@ -82,9 +84,13 @@ def start(self): root.setLevel(self.config.level) structlog.configure( - CORE_PROCESSORS + [self._log_handler.send_structlog], + [add_process_info] + + CORE_PROCESSORS + + [structlog.processors.ExceptionPrettyPrinter(), self._log_handler.send_structlog], + wrapper_class=structlog.make_filtering_bound_logger(self.config.level), logger_factory=structlog.stdlib.LoggerFactory(), ) + _log.debug("log context activated") def shutdown(self): root = getLogger() @@ -119,6 +125,7 @@ def handle(self, record: LogRecord) -> LogRecord | bool: # type: ignore # update messages for copyability if not hasattr(record, "message"): record.message = record.msg % record.args + record.exc_info = None record.exc_text = None record.stack_info = None From cf399799bc4ecd430d5bb5a41eedced661f9ec1a Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Sat, 7 Dec 2024 12:12:54 -0500 Subject: [PATCH 2/4] don't pre-bind logger --- lenskit/lenskit/parallel/pool.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lenskit/lenskit/parallel/pool.py b/lenskit/lenskit/parallel/pool.py index 6398cd22..47257e83 100644 --- a/lenskit/lenskit/parallel/pool.py +++ b/lenskit/lenskit/parallel/pool.py @@ -71,8 +71,8 @@ def __init__(self, *args: Any, **kwargs: Any): @override def run(self): - log = _log.bind(pid=self.pid, pname=self.name) with WorkerContext(self._log_config): + log = _log.bind(pid=self.pid, pname=self.name) log.info("multiprocessing worker started") super().run() From 9fbee9d474e430751d1cd86a570551b6601d83d1 Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Sat, 7 Dec 2024 12:13:07 -0500 Subject: [PATCH 3/4] fix worker startup log --- lenskit/lenskit/parallel/worker.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lenskit/lenskit/parallel/worker.py b/lenskit/lenskit/parallel/worker.py index b182a0c5..590b8a64 100644 --- a/lenskit/lenskit/parallel/worker.py +++ b/lenskit/lenskit/parallel/worker.py @@ -50,7 +50,7 @@ def initalize(cfg: WorkerConfig, ctx: ModelData) -> None: log.error("deserialization failed: %s", e) raise e - log.debug("worker %d ready (process %s)", os.getpid(), mp.current_process()) + log.debug("worker %d ready (process %s)", os.getpid(), mp.current_process().name) def worker(arg: Any) -> Any: From 87abf4c8f8890db333104a69ef94e8ec2f9d9d86 Mon Sep 17 00:00:00 2001 From: Michael Ekstrand Date: Sat, 7 Dec 2024 12:14:46 -0500 Subject: [PATCH 4/4] fix structopt log dispatch --- lenskit/lenskit/logging/monitor.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lenskit/lenskit/logging/monitor.py b/lenskit/lenskit/logging/monitor.py index 7d01b8fe..e3498db2 100644 --- a/lenskit/lenskit/logging/monitor.py +++ b/lenskit/lenskit/logging/monitor.py @@ -210,6 +210,6 @@ def _handle_log_message(self): logger = structlog.get_logger(name) data = json.loads(data) method = getattr(logger, data["method"]) - method(data["event"]) + method(**data["event"]) else: _log.error("invalid log backend")