Log filename, number and function name for the phase being executed

Example:
D 15:53:01 <test 81684> - Executing phase passing_phase (from passing_phase at phase_descriptor_test.py:92)
PiperOrigin-RevId: 666523034

openhtf/core/phase_descriptor.py

@@ -21,6 +21,8 @@
 import collections
 import enum
 import inspect
+import logging
+import os.path
 import pdb
 from typing import Any, Callable, Dict, Iterator, List, Optional, Sequence, Set, Text, TYPE_CHECKING, Type, Union
 
@@ -36,10 +38,13 @@
 from openhtf.core import test_record
 import openhtf.plugs
 from openhtf.util import data
+from openhtf.util import logs
 
 if TYPE_CHECKING:
   from openhtf.core import test_state  # pylint: disable=g-import-not-at-top
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class PhaseWrapError(Exception):
   """Error with phase wrapping."""
@@ -174,6 +179,8 @@ class PhaseDescriptor(phase_nodes.PhaseNode):
 
   Attributes:
     func: Function to be called (with TestApi as first argument).
+    func_location: Location of the function, as 'name at file:line' for
+      user-defined functions, or 'name <builtin>' for built-in functions.
     options: PhaseOptions instance.
     plugs: List of PhasePlug instances.
     measurements: List of Measurement objects.
@@ -185,6 +192,29 @@ class PhaseDescriptor(phase_nodes.PhaseNode):
   """
 
   func = attr.ib(type=PhaseCallableT)
+  func_location = attr.ib(type=Text)
+
+  @func_location.default
+  def _func_location(self):
+    """Assigns this field assuming func is a function or callable instance."""
+    obj = self.func
+    try:
+      name = obj.__name__
+    except AttributeError:
+      try:
+        name = obj.__class__.__name__
+      except AttributeError:
+        logs.log_once(_LOGGER.warning,
+                      'Cannot determine name of callable: %r', obj)
+        return '<unknown>'
+      obj = obj.__class__
+    try:
+      filename = os.path.basename(inspect.getsourcefile(obj))
+      line_number = inspect.getsourcelines(obj)[1]
+    except TypeError:
+      return name + ' <builtin>'
+    return f'{name} at {filename}:{line_number}'
+
   options = attr.ib(type=PhaseOptions, factory=PhaseOptions)
   plugs = attr.ib(type=List[base_plugs.PhasePlug], factory=list)
   measurements = attr.ib(type=List[core_measurements.Measurement], factory=list)

openhtf/core/phase_executor.py

@@ -310,11 +310,13 @@ def _execute_phase_once(
     override_result = None
     with self.test_state.running_phase_context(phase_desc) as phase_state:
       if subtest_rec:
-        self.logger.debug('Executing phase %s under subtest %s',
-                          phase_desc.name, subtest_rec.name)
+        self.logger.debug('Executing phase %s under subtest %s (from %s)',
+                          phase_desc.name, phase_desc.func_location,
+                          subtest_rec.name)
         phase_state.set_subtest_name(subtest_rec.name)
       else:
-        self.logger.debug('Executing phase %s', phase_desc.name)
+        self.logger.debug('Executing phase %s (from %s)', phase_desc.name,
+                          phase_desc.func_location)
       with self._current_phase_thread_lock:
         # Checking _stopping must be in the lock context, otherwise there is a
         # race condition: this thread checks _stopping and then switches to

openhtf/core/test_executor.py

@@ -327,10 +327,11 @@ def _execute_phase(self, phase: phase_descriptor.PhaseDescriptor,
                      subtest_rec: Optional[test_record.SubtestRecord],
                      in_teardown: bool) -> _ExecutorReturn:
     if subtest_rec:
-      self.logger.debug('Executing phase %s under subtest %s', phase.name,
-                        subtest_rec.name)
+      self.logger.debug('Executing phase %s (from %s) under subtest %s',
+                        phase.name, phase.func_location, subtest_rec.name)
     else:
-      self.logger.debug('Executing phase %s', phase.name)
+      self.logger.debug('Executing phase %s (from %s)', phase.name,
+                        phase.func_location)
 
     if not in_teardown and subtest_rec and subtest_rec.is_fail:
       self.phase_executor.skip_phase(phase, subtest_rec)

test/phase_descriptor_test.py

@@ -133,7 +133,8 @@ def test_multiple_phases(self):
     phase = openhtf.PhaseDescriptor.wrap_or_copy(plain_func)
     second_phase = openhtf.PhaseDescriptor.wrap_or_copy(phase)
     for field in attr.fields(type(phase)):
-      if field.name == 'func':
+      if field.name in [openhtf.PhaseDescriptor.func.__name__,
+                        openhtf.PhaseDescriptor.func_location.__name__]:
         continue
       self.assertIsNot(
           getattr(phase, field.name), getattr(second_phase, field.name))