From 3e1a75be0ec5108a1f8935fe3e0e46cf1a28fedf Mon Sep 17 00:00:00 2001 From: Tim Jenness Date: Tue, 7 Oct 2025 13:07:47 -0700 Subject: [PATCH 1/5] Add support for structlog in time_this output This allows the duration itself to be sent as an explicit keyword value rather than being embedded in the text. --- python/lsst/utils/logging.py | 25 +++++++++++++++++++++++- python/lsst/utils/timer.py | 38 +++++++++++++++++++++++++++++++----- tests/test_timer.py | 37 +++++++++++++++++++++++++++++++++++ 3 files changed, 94 insertions(+), 6 deletions(-) diff --git a/python/lsst/utils/logging.py b/python/lsst/utils/logging.py index 17d1d890..23b74f80 100644 --- a/python/lsst/utils/logging.py +++ b/python/lsst/utils/logging.py @@ -28,7 +28,7 @@ from collections.abc import Generator from contextlib import contextmanager from logging import LoggerAdapter -from typing import Any, TypeAlias +from typing import TYPE_CHECKING, Any, TypeAlias try: import lsst.log.utils as logUtils @@ -36,6 +36,12 @@ logUtils = None +if TYPE_CHECKING: + try: + from structlog.typing import BindableLogger + except ImportError: + BindableLogger: TypeAlias = Any # type: ignore[no-redef] + # log level for trace (verbose debug). TRACE = 5 logging.addLevelName(TRACE, "TRACE") @@ -45,6 +51,23 @@ logging.addLevelName(VERBOSE, "VERBOSE") +def _is_structlog_logger(logger: logging.Logger | LsstLogAdapter | BindableLogger) -> bool: + """Check if the given logger is a structlog logger.""" + try: + import structlog + except ImportError: + return False + + try: + # Returns a dict for structlog loggers; raises for stdlib logger + # objects. + structlog.get_context(logger) # type: ignore[arg-type] + return True + except Exception: + # In practice this is usually ValueError or AttributeError. + return False + + def _calculate_base_stacklevel(default: int, offset: int) -> int: """Calculate the default logging stacklevel to use. diff --git a/python/lsst/utils/timer.py b/python/lsst/utils/timer.py index f86a3405..6421c2fa 100644 --- a/python/lsst/utils/timer.py +++ b/python/lsst/utils/timer.py @@ -32,7 +32,7 @@ from astropy import units as u from .introspection import find_outside_stacklevel -from .logging import LsstLoggers +from .logging import LsstLoggers, _is_structlog_logger from .usage import _get_current_rusage, get_current_mem_usage, get_peak_mem_usage if TYPE_CHECKING: @@ -374,9 +374,10 @@ def time_this( level: int = logging.DEBUG, prefix: str | None = "timer", args: Iterable[Any] = (), + kwargs: dict[str, Any] | None = None, mem_usage: bool = False, mem_child: bool = False, - mem_unit: u.Quantity = u.byte, + mem_unit: u.Unit = u.byte, mem_fmt: str = ".0f", force_mem_usage: bool = False, ) -> Iterator[_TimerResult]: @@ -386,7 +387,8 @@ def time_this( ---------- log : `logging.Logger`, optional Logger to use to report the timer message. The root logger will - be used if none is given. + be used if none is given. Is also allowed to be a `structlog` bound + logger. msg : `str`, optional Context to include in log message. level : `int`, optional @@ -400,6 +402,11 @@ def time_this( args : iterable of any Additional parameters passed to the log command that should be written to ``msg``. + kwargs : `dict`, optional + Additional keyword parameters passed to the log command. If a Structlog + is used then these will be added to the structured data. Otherwise + they will be converted to a single string for inclusion in the log + message. mem_usage : `bool`, optional Flag indicating whether to include the memory usage in the report. Defaults, to False. Does nothing if the log message will not be @@ -424,10 +431,17 @@ def time_this( """ if log is None: log = logging.getLogger() - if prefix: + is_structlog = _is_structlog_logger(log) + if prefix and not is_structlog: + # Struct log loggers do not have a name property and so the prefix + # is not applied to them. log_name = f"{prefix}.{log.name}" if not isinstance(log, logging.RootLogger) else prefix log = logging.getLogger(log_name) + # Some structured data that can be used if we have been given a + # structlog logger. + structured_args: dict[str, Any] = {} + start = time.time() if mem_usage and not log.isEnabledFor(level): @@ -467,6 +481,7 @@ def time_this( # caller (1 is this file, 2 is contextlib, 3 is user) params += (": " if msg else "", duration) msg += "%sTook %.4f seconds" + structured_args["duration"] = duration if errmsg: params += (f" (timed code triggered exception of {errmsg!r})",) msg += "%s" @@ -502,7 +517,20 @@ def time_this( f", delta: {current_delta:{mem_fmt}}" f", peak delta: {peak_delta:{mem_fmt}}" ) - log.log(level, msg, *params, stacklevel=3) + structured_args["mem_current_usage"] = float(current_usage.value) + structured_args["mem_current_delta"] = float(current_delta.value) + structured_args["mem_peak_delta"] = float(peak_delta.value) + if not is_structlog: + # Can only use the structured content if we have structlog logger + # but stacklevel is only supported by standard loggers. + structured_args = {"stacklevel": 3} + if kwargs is not None: + msg += " %s" + params += ("; ".join(f"{k}={v!r}" for k, v in kwargs.items()),) + elif kwargs: + structured_args.update(kwargs) + + log.log(level, msg, *params, **structured_args) @contextmanager diff --git a/tests/test_timer.py b/tests/test_timer.py index afec7413..17a30049 100644 --- a/tests/test_timer.py +++ b/tests/test_timer.py @@ -319,6 +319,22 @@ def testTimer(self): self.assertIn("Took", cm.output[0]) self.assertIn(msg % test_num, cm.output[0]) + # Now with kwargs. + msg = "Test message %d" + test_num = 42 + logname = "test" + kwargs = {"extra_info": "extra", "value": 3} + with self.assertLogs(level="DEBUG") as cm: + with time_this( + log=logging.getLogger(logname), msg=msg, args=(test_num,), kwargs=kwargs, prefix=None + ): + pass + self.assertEqual(cm.records[0].name, logname) + self.assertIn("Took", cm.output[0]) + self.assertIn(msg % test_num, cm.output[0]) + self.assertIn("extra_info='extra'", cm.output[0]) + self.assertIn("value=3", cm.output[0]) + # Prefix the logger. prefix = "prefix" with self.assertLogs(level="DEBUG") as cm: @@ -374,6 +390,27 @@ def test_time_this_return(self): self.assertGreater(timer.duration, 0.0) self.assertIsInstance(timer.mem_current_usage, float) + def test_structlog(self): + """Test that the timer works with structlog loggers.""" + try: + import structlog + from structlog.testing import capture_logs + except ImportError: + self.skipTest("structlog is not installed") + + msg = "Test message %d" + test_num = 42 + kwargs = {"extra_info": "extra", "value": 3} + + with capture_logs() as cap: + slog = structlog.get_logger("structlog_timer") + with time_this(log=slog, msg=msg, args=(test_num,), kwargs=kwargs): + pass + self.assertEqual(cap[0]["value"], 3) + self.assertEqual(cap[0]["extra_info"], "extra") + self.assertGreaterEqual(cap[0]["duration"], 0.0) + self.assertIn("Test message 42", cap[0]["event"]) + class ProfileTestCase(unittest.TestCase): """Test profiling decorator.""" From 22121f82c3658c61febb06f2e85e07c235ddcd5b Mon Sep 17 00:00:00 2001 From: Tim Jenness Date: Tue, 7 Oct 2025 13:16:05 -0700 Subject: [PATCH 2/5] Add structlog to dependencies on PyPI --- mypy.ini | 3 +++ pyproject.toml | 1 + requirements.txt | 1 + 3 files changed, 5 insertions(+) diff --git a/mypy.ini b/mypy.ini index f767ad26..bb1a1990 100644 --- a/mypy.ini +++ b/mypy.ini @@ -37,6 +37,9 @@ ignore_missing_imports = True [mypy-conda.cli.*] ignore_missing_imports = True +[mypy-structlog.*] +ignore_missing_imports = True + [mypy-lsst.*] ignore_missing_imports = True ignore_errors = True diff --git a/pyproject.toml b/pyproject.toml index bf996c6d..6fb6103a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -27,6 +27,7 @@ dependencies = [ "deprecated >= 1.2", "pyyaml >= 5.1", "astropy >= 5.0", + "structlog", "threadpoolctl", ] dynamic = ["version"] diff --git a/requirements.txt b/requirements.txt index f29f5de4..76afadeb 100644 --- a/requirements.txt +++ b/requirements.txt @@ -6,3 +6,4 @@ astropy >= 5.0 threadpoolctl matplotlib seaborn +structlog From 35f530cb3857ce4f6112512f8d1a5e3d29d4baea Mon Sep 17 00:00:00 2001 From: Tim Jenness Date: Tue, 7 Oct 2025 13:26:25 -0700 Subject: [PATCH 3/5] Pre-import structlog to see if it is available --- python/lsst/utils/logging.py | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/python/lsst/utils/logging.py b/python/lsst/utils/logging.py index 23b74f80..506173ed 100644 --- a/python/lsst/utils/logging.py +++ b/python/lsst/utils/logging.py @@ -35,6 +35,11 @@ except ImportError: logUtils = None +try: + from structlog import get_context as get_structlog_context +except ImportError: + get_structlog_context = None # type: ignore[assignment] + if TYPE_CHECKING: try: @@ -53,15 +58,13 @@ def _is_structlog_logger(logger: logging.Logger | LsstLogAdapter | BindableLogger) -> bool: """Check if the given logger is a structlog logger.""" - try: - import structlog - except ImportError: - return False + if get_structlog_context is None: + return False # type: ignore[unreachable] try: # Returns a dict for structlog loggers; raises for stdlib logger # objects. - structlog.get_context(logger) # type: ignore[arg-type] + get_structlog_context(logger) # type: ignore[arg-type] return True except Exception: # In practice this is usually ValueError or AttributeError. From c0187ad8b29e4ac40719ec17d464e676458ce450 Mon Sep 17 00:00:00 2001 From: Tim Jenness Date: Wed, 8 Oct 2025 09:47:27 -0700 Subject: [PATCH 4/5] Use TypeGuard to tell mypy the logger type --- python/lsst/utils/logging.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/python/lsst/utils/logging.py b/python/lsst/utils/logging.py index 506173ed..a8b03830 100644 --- a/python/lsst/utils/logging.py +++ b/python/lsst/utils/logging.py @@ -28,7 +28,7 @@ from collections.abc import Generator from contextlib import contextmanager from logging import LoggerAdapter -from typing import TYPE_CHECKING, Any, TypeAlias +from typing import TYPE_CHECKING, Any, TypeAlias, TypeGuard try: import lsst.log.utils as logUtils @@ -56,7 +56,9 @@ logging.addLevelName(VERBOSE, "VERBOSE") -def _is_structlog_logger(logger: logging.Logger | LsstLogAdapter | BindableLogger) -> bool: +def _is_structlog_logger( + logger: logging.Logger | LsstLogAdapter | BindableLogger, +) -> TypeGuard[BindableLogger]: """Check if the given logger is a structlog logger.""" if get_structlog_context is None: return False # type: ignore[unreachable] From 6a7f12e41dbf20c58d8d6ef64a26a843d70b483f Mon Sep 17 00:00:00 2001 From: Tim Jenness Date: Wed, 8 Oct 2025 15:30:14 -0700 Subject: [PATCH 5/5] Ignore sphinx errors from structlog --- doc/conf.py | 1 + 1 file changed, 1 insertion(+) diff --git a/doc/conf.py b/doc/conf.py index dbdc7a57..b0c73752 100644 --- a/doc/conf.py +++ b/doc/conf.py @@ -25,4 +25,5 @@ ("py:class", "unittest.case.TestCase"), # Sphinx can not see TestCase. ("py:obj", "deprecated.sphinx.deprecated"), # No intersphinx for deprecated package. ("py:class", "LsstLoggers"), # Sphinx does not understand type aliases + ("py:obj", "structlog"), # structlog does not have intersphinx mapping. ]