DM-52711: Add support for structlog in time_this output

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.
 ]

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

pyproject.toml

@@ -27,6 +27,7 @@ dependencies = [
     "deprecated >= 1.2",
     "pyyaml >= 5.1",
     "astropy >= 5.0",
+    "structlog",
     "threadpoolctl",
 ]
 dynamic = ["version"]

python/lsst/utils/logging.py

@@ -28,13 +28,24 @@
 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, TypeGuard
 
 try:
     import lsst.log.utils as logUtils
 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:
+        from structlog.typing import BindableLogger
+    except ImportError:
+        BindableLogger: TypeAlias = Any  # type: ignore[no-redef]
 
 # log level for trace (verbose debug).
 TRACE = 5
@@ -45,6 +56,23 @@
 logging.addLevelName(VERBOSE, "VERBOSE")
 
 
+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]
+
+    try:
+        # Returns a dict for structlog loggers; raises for stdlib logger
+        # objects.
+        get_structlog_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.
 

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

requirements.txt

@@ -6,3 +6,4 @@ astropy >= 5.0
 threadpoolctl
 matplotlib
 seaborn
+structlog

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."""