Ensure that logInfo reports the line from non-utils code

python/lsst/utils/timer.py

@@ -22,6 +22,7 @@
 import resource
 import time
 import datetime
+import traceback
 from contextlib import contextmanager
 
 from typing import (
@@ -72,6 +73,32 @@ def _add_to_metadata(metadata: MutableMapping, name: str, value: Any) -> None:
     metadata[name].append(value)
 
 
+def _find_outside_stacklevel():
+    """Find the stack level corresponding to caller code outside of this
+    module.
+
+    This can be passed directly to `logging.Logger.log()` to ensure
+    that log messages are issued as if they are coming from caller code.
+
+    Returns
+    -------
+    stacklevel : `int`
+        The stack level to use to refer a caller outside of this module.
+        The stack is adjusted to take the call to this function into account.
+    """
+    stacklevel = 1  # the default for `Logger.log`
+    stack = traceback.extract_stack()
+    for i, s in enumerate(reversed(stack)):
+        if "lsst/utils" not in s.filename:
+            # 0 will be this function.
+            # 1 will be the caller which will be the default for `Logger.log`
+            # and so does not need adjustment.
+            stacklevel = i
+            break
+
+    return stacklevel
+
+
 def logPairs(obj: Any, pairs: Collection[Tuple[str, Any]], logLevel: int = logging.DEBUG,
              metadata: Optional[MutableMapping] = None,
              logger: Optional[logging.Logger] = None) -> None:
@@ -115,7 +142,10 @@ def logPairs(obj: Any, pairs: Collection[Tuple[str, Any]], logLevel: int = loggi
             _add_to_metadata(metadata, name, value)
         strList.append(f"{name}={value}")
     if logger is not None:
-        logging.getLogger("timer." + logger.name).log(logLevel, "; ".join(strList))
+        # Want the file associated with this log message to be that
+        # of the caller.
+        stacklevel = _find_outside_stacklevel()
+        logging.getLogger("timer." + logger.name).log(logLevel, "; ".join(strList), stacklevel=stacklevel)
 
 
 def logInfo(obj: Any, prefix: str, logLevel: int = logging.DEBUG,

tests/test_timer.py

@@ -13,12 +13,15 @@
 import logging
 import time
 import datetime
+import os.path
 from dataclasses import dataclass
 
 from lsst.utils.timer import timeMethod, logPairs, time_this
 
 log = logging.getLogger("test_timer")
 
+THIS_FILE = os.path.basename(__file__)
+
 # Only use this in a single test but needs to be associated
 # with the function up front.
 test_metadata = {}
@@ -66,6 +69,7 @@ def testLogPairs(self):
             logPairs(None, pairs, logLevel=logging.INFO, logger=logger, metadata=metadata)
         self.assertEqual(len(cm.output), 1, cm.output)
         self.assertTrue(cm.output[0].endswith("name1=0; name2=1"), cm.output)
+        self.assertEqual(cm.records[0].filename, THIS_FILE, "log message should originate from here")
         self.assertEqual(metadata, {"name1": [0], "name2": [1]})
 
     def assertTimer(self, duration, task):
@@ -81,8 +85,9 @@ def assertTimer(self, duration, task):
 
         if has_logger:
             counter += 1
-            with self.assertLogs("timer.task", level=logging.DEBUG):
+            with self.assertLogs("timer.task", level=logging.DEBUG) as cm:
                 task.sleeper(duration)
+            self.assertEqual(cm.records[0].filename, THIS_FILE, "log message should originate from here")
 
         if has_metadata:
             self.assertEqual(len(task.metadata["sleeperStartUserTime"]), counter)
@@ -117,8 +122,9 @@ def testDecorated(self):
         decorated_sleeper_nothing(self, duration)
 
         # Use a function decorated for logging.
-        with self.assertLogs("timer.test_timer", level=logging.DEBUG):
+        with self.assertLogs("timer.test_timer", level=logging.DEBUG) as cm:
             decorated_sleeper_logger(self, duration)
+        self.assertEqual(cm.records[0].filename, THIS_FILE, "log message should originate from here")
 
         # And adjust the log level
         with self.assertLogs("timer.test_timer", level=logging.INFO):
@@ -143,15 +149,15 @@ def testTimer(self):
                 pass
         self.assertEqual(cm.records[0].name, "timer")
         self.assertEqual(cm.records[0].levelname, "DEBUG")
-        self.assertEqual(cm.records[0].filename, "test_timer.py")
+        self.assertEqual(cm.records[0].filename, THIS_FILE)
 
         with self.assertLogs(level="DEBUG") as cm:
             with time_this(prefix=None):
                 pass
         self.assertEqual(cm.records[0].name, "root")
         self.assertEqual(cm.records[0].levelname, "DEBUG")
         self.assertIn("Took", cm.output[0])
-        self.assertEqual(cm.records[0].filename, "test_timer.py")
+        self.assertEqual(cm.records[0].filename, THIS_FILE)
 
         # Change logging level
         with self.assertLogs(level="INFO") as cm: