Try to get a more reasonable stacklevel

tmt/checks/avc.py

@@ -142,8 +142,17 @@ def _output_logger(
         shift: int = 2,
         level: int = 3,
         topic: Optional[tmt.log.Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
-        logger.verbose(key=key, value=value, color=color, shift=shift, level=level, topic=topic)
+        logger.verbose(
+            key=key,
+            value=value,
+            color=color,
+            shift=shift,
+            level=level,
+            topic=topic,
+            stacklevel=stacklevel + 1,
+        )
 
     try:
         output = invocation.guest.execute(script, log=_output_logger, silent=True)

tmt/checks/dmesg.py

@@ -78,9 +78,16 @@ def _test_output_logger(
             shift: int = 2,
             level: int = 3,
             topic: Optional[tmt.log.Topic] = None,
+            stacklevel: int = 1,
         ) -> None:
             logger.verbose(
-                key=key, value=value, color=color, shift=shift, level=level, topic=topic
+                key=key,
+                value=value,
+                color=color,
+                shift=shift,
+                level=level,
+                topic=topic,
+                stacklevel=stacklevel + 1,
             )
 
         script = tmt.utils.ShellScript(f'{guest.facts.sudo_prefix} dmesg')

tmt/log.py

@@ -443,6 +443,7 @@ def __call__(
         shift: int = 0,
         level: int = 1,
         topic: Optional[Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         pass
 
@@ -764,6 +765,7 @@ def _log(
         level: int,
         details: LogRecordDetails,
         message: str = '',
+        stacklevel: int = 1,
     ) -> None:
         """
         Emit a log record describing the message and related properties.
@@ -794,7 +796,17 @@ def _log(
                 labels_padding=self.labels_padding,
             )
 
-        self._logger._log(level, message, (), extra={'details': details})
+        # stacklevel: This function is never called directly, instead it is called by one level
+        # higher e.g. `info`. So we escape at least 2 levels of the stack (this function, and its
+        # caller) + the requested stacklevel of the caller (default is the current caller of
+        # `info`)
+        self._logger._log(
+            level,
+            message,
+            (),
+            extra={'details': details},
+            stacklevel=stacklevel + 2,
+        )
 
     def print_format(
         self,
@@ -836,10 +848,12 @@ def info(
         color: 'tmt.utils.themes.Style' = None,
         shift: int = 0,
         topic: Optional[Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         self._log(
             logging.INFO,
             LogRecordDetails(key=key, value=value, color=color, shift=shift, message_topic=topic),
+            stacklevel=stacklevel,
         )
 
     def verbose(
@@ -850,6 +864,7 @@ def verbose(
         shift: int = 0,
         level: int = 1,
         topic: Optional[Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         self._log(
             logging.INFO,
@@ -861,6 +876,7 @@ def verbose(
                 message_verbosity_level=level,
                 message_topic=topic,
             ),
+            stacklevel=stacklevel,
         )
 
     def debug(
@@ -871,6 +887,7 @@ def debug(
         shift: int = 0,
         level: int = 1,
         topic: Optional[Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         self._log(
             logging.DEBUG,
@@ -882,33 +899,40 @@ def debug(
                 message_debug_level=level,
                 message_topic=topic,
             ),
+            stacklevel=stacklevel,
         )
 
     def warning(
         self,
         message: str,
         shift: int = 0,
+        stacklevel: int = 1,
     ) -> None:
         self._log(
             logging.WARNING,
             LogRecordDetails(key='warn', value=message, color='yellow', shift=shift),
+            stacklevel=stacklevel,
         )
 
     @deprecated("Use Logger.warning instead")
     def warn(
         self,
         message: str,
         shift: int,
+        stacklevel: int = 1,
     ) -> None:
-        return self.warning(message, shift)
+        return self.warning(message, shift, stacklevel=stacklevel + 1)
 
     def fail(
         self,
         message: str,
         shift: int = 0,
+        stacklevel: int = 1,
     ) -> None:
         self._log(
-            logging.ERROR, LogRecordDetails(key='fail', value=message, color='red', shift=shift)
+            logging.ERROR,
+            LogRecordDetails(key='fail', value=message, color='red', shift=shift),
+            stacklevel=stacklevel,
         )
 
     _bootstrap_logger: Optional['Logger'] = None

tmt/steps/execute/internal.py

@@ -375,9 +375,16 @@ def _test_output_logger(
             shift: int = 2,
             level: int = 3,
             topic: Optional[tmt.log.Topic] = None,
+            stacklevel: int = 1,
         ) -> None:
             logger.verbose(
-                key=key, value=value, color=color, shift=shift, level=level, topic=topic
+                key=key,
+                value=value,
+                color=color,
+                shift=shift,
+                level=level,
+                topic=topic,
+                stacklevel=stacklevel + 1,
             )
 
         # TODO: do we want timestamps? Yes, we do, leaving that for refactoring later,

tmt/utils/__init__.py

@@ -1302,7 +1302,7 @@ def run(
 
         # First, if we were given a message, emit it.
         if message:
-            logger.verbose(message, level=2)
+            logger.verbose(message, level=2, stacklevel=2)
 
         # For debugging, we want to save somewhere the actual command rather
         # than the provided "friendly". Emit the actual command to the debug
@@ -1312,7 +1312,7 @@ def run(
         # The friendly command version would be emitted only when we were not
         # asked to be quiet.
         if not silent and friendly_command:
-            (log or logger.verbose)("cmd", friendly_command, color="yellow", level=2)
+            (log or logger.verbose)("cmd", friendly_command, color="yellow", level=2, stacklevel=2)
 
         # Nothing more to do in dry mode
         if dry:
@@ -2188,12 +2188,20 @@ def info(
         color: 'tmt.utils.themes.Style' = None,
         shift: int = 0,
         topic: Optional[tmt.log.Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         """
         Show a message unless in quiet mode
         """
 
-        self._logger.info(key, value=value, color=color, shift=shift, topic=topic)
+        self._logger.info(
+            key,
+            value=value,
+            color=color,
+            shift=shift,
+            topic=topic,
+            stacklevel=stacklevel + 1,
+        )
 
     def verbose(
         self,
@@ -2203,14 +2211,23 @@ def verbose(
         shift: int = 0,
         level: int = 1,
         topic: Optional[tmt.log.Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         """
         Show message if in requested verbose mode level
 
         In quiet mode verbose messages are not displayed.
         """
 
-        self._logger.verbose(key, value=value, color=color, shift=shift, level=level, topic=topic)
+        self._logger.verbose(
+            key,
+            value=value,
+            color=color,
+            shift=shift,
+            level=level,
+            topic=topic,
+            stacklevel=stacklevel + 1,
+        )
 
     def debug(
         self,
@@ -2220,28 +2237,37 @@ def debug(
         shift: int = 0,
         level: int = 1,
         topic: Optional[tmt.log.Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         """
         Show message if in requested debug mode level
 
         In quiet mode debug messages are not displayed.
         """
 
-        self._logger.debug(key, value=value, color=color, shift=shift, level=level, topic=topic)
+        self._logger.debug(
+            key,
+            value=value,
+            color=color,
+            shift=shift,
+            level=level,
+            topic=topic,
+            stacklevel=stacklevel + 1,
+        )
 
-    def warn(self, message: str, shift: int = 0) -> None:
+    def warn(self, message: str, shift: int = 0, stacklevel: int = 1) -> None:
         """
         Show a yellow warning message on info level, send to stderr
         """
 
-        self._logger.warning(message, shift=shift)
+        self._logger.warning(message, shift=shift, stacklevel=stacklevel + 1)
 
-    def fail(self, message: str, shift: int = 0) -> None:
+    def fail(self, message: str, shift: int = 0, stacklevel: int = 1) -> None:
         """
         Show a red failure message on info level, send to stderr
         """
 
-        self._logger.fail(message, shift=shift)
+        self._logger.fail(message, shift=shift, stacklevel=stacklevel + 1)
 
     def _command_verbose_logger(
         self,
@@ -2251,6 +2277,7 @@ def _command_verbose_logger(
         shift: int = 1,
         level: int = 3,
         topic: Optional[tmt.log.Topic] = None,
+        stacklevel: int = 1,
     ) -> None:
         """
         Reports the executed command in verbose mode.
@@ -2259,7 +2286,15 @@ def _command_verbose_logger(
         default parameters are adjusted (to preserve the function type).
         """
 
-        self.verbose(key=key, value=value, color=color, shift=shift, level=level, topic=topic)
+        self.verbose(
+            key=key,
+            value=value,
+            color=color,
+            shift=shift,
+            level=level,
+            topic=topic,
+            stacklevel=stacklevel + 1,
+        )
 
     def run(
         self,