Internal change (#1037)

PiperOrigin-RevId: 474850134

Author: tan01

openhtf/core/phase_executor.py

@@ -30,7 +30,6 @@
 framework.
 """
 
-import logging
 import pstats
 import sys
 import threading
@@ -63,9 +62,6 @@
     target='%s.DEFAULT_PHASE_TIMEOUT_S' % __name__,
     help='Test phase timeout in seconds')
 
-# TODO(arsharma): Use the test state logger.
-_LOG = logging.getLogger(__name__)
-
 
 @attr.s(slots=True, frozen=True)
 class ExceptionInfo(object):
@@ -170,7 +166,8 @@ def __init__(self, phase_desc: phase_descriptor.PhaseDescriptor,
                subtest_rec: Optional[test_record.SubtestRecord]):
     super(PhaseExecutorThread, self).__init__(
         name='<PhaseExecutorThread: (phase_desc.name)>',
-        run_with_profiling=run_with_profiling)
+        run_with_profiling=run_with_profiling,
+        logger=test_state.state_logger.getChild('phase_executor_thread'))
     self._phase_desc = phase_desc
     self._test_state = test_state
     self._subtest_rec = subtest_rec
@@ -238,6 +235,7 @@ class PhaseExecutor(object):
 
   def __init__(self, test_state: 'htf_test_state.TestState'):
     self.test_state = test_state
+    self.logger = test_state.state_logger.getChild('phase_executor')
     # This lock exists to prevent stop() calls from being ignored if called when
     # _execute_phase_once is setting up the next phase thread.
     self._current_phase_thread_lock = threading.Lock()
@@ -267,8 +265,7 @@ def execute_phase(
       requested and successfully ran for this phase execution.
     """
     repeat_count = 1
-    repeat_limit = (phase.options.repeat_limit or
-                    DEFAULT_RETRIES)
+    repeat_limit = (phase.options.repeat_limit or DEFAULT_RETRIES)
     while not self._stopping.is_set():
       is_last_repeat = repeat_count >= repeat_limit
       phase_execution_outcome, profile_stats = self._execute_phase_once(
@@ -277,9 +274,8 @@ def execute_phase(
       # Give 3 default retries for timeout phase.
       # Force repeat up to the repeat limit if force_repeat is set.
       if ((phase_execution_outcome.is_timeout and
-           phase.options.repeat_on_timeout) or
-          phase_execution_outcome.is_repeat or
-          phase.options.force_repeat) and not is_last_repeat:
+           phase.options.repeat_on_timeout) or phase_execution_outcome.is_repeat
+          or phase.options.force_repeat) and not is_last_repeat:
         repeat_count += 1
         continue
 
@@ -297,18 +293,18 @@ def _execute_phase_once(
     """Executes the given phase, returning a PhaseExecutionOutcome."""
     # Check this before we create a PhaseState and PhaseRecord.
     if phase_desc.options.run_if and not phase_desc.options.run_if():
-      _LOG.debug('Phase %s skipped due to run_if returning falsey.',
-                 phase_desc.name)
+      self.logger.debug('Phase %s skipped due to run_if returning falsey.',
+                        phase_desc.name)
       return PhaseExecutionOutcome(phase_descriptor.PhaseResult.SKIP), None
 
     override_result = None
     with self.test_state.running_phase_context(phase_desc) as phase_state:
       if subtest_rec:
-        _LOG.debug('Executing phase %s under subtest %s', phase_desc.name,
-                   subtest_rec.name)
+        self.logger.debug('Executing phase %s under subtest %s',
+                          phase_desc.name, subtest_rec.name)
         phase_state.set_subtest_name(subtest_rec.name)
       else:
-        _LOG.debug('Executing phase %s', phase_desc.name)
+        self.logger.debug('Executing phase %s', phase_desc.name)
       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
@@ -328,7 +324,7 @@ def _execute_phase_once(
 
       phase_state.result = phase_thread.join_or_die()
       if phase_state.result.is_repeat and is_last_repeat:
-        _LOG.error('Phase returned REPEAT, exceeding repeat_limit.')
+        self.logger.error('Phase returned REPEAT, exceeding repeat_limit.')
         phase_state.hit_repeat_limit = True
         override_result = PhaseExecutionOutcome(
             phase_descriptor.PhaseResult.STOP)
@@ -337,15 +333,15 @@ def _execute_phase_once(
     # Refresh the result in case a validation for a partially set measurement
     # or phase diagnoser raised an exception.
     result = override_result or phase_state.result
-    _LOG.debug('Phase %s finished with result %s', phase_desc.name,
-               result.phase_result)
+    self.logger.debug('Phase %s finished with result %s', phase_desc.name,
+                      result.phase_result)
     return (result,
             phase_thread.get_profile_stats() if run_with_profiling else None)
 
   def skip_phase(self, phase_desc: phase_descriptor.PhaseDescriptor,
                  subtest_rec: Optional[test_record.SubtestRecord]) -> None:
     """Skip a phase, but log a record of it."""
-    _LOG.debug('Automatically skipping phase %s', phase_desc.name)
+    self.logger.debug('Automatically skipping phase %s', phase_desc.name)
     with self.test_state.running_phase_context(phase_desc) as phase_state:
       if subtest_rec:
         phase_state.set_subtest_name(subtest_rec.name)
@@ -359,16 +355,16 @@ def evaluate_checkpoint(
     """Evaluate a checkpoint, returning a PhaseExecutionOutcome."""
     if subtest_rec:
       subtest_name = subtest_rec.name
-      _LOG.debug('Evaluating checkpoint %s under subtest %s', checkpoint.name,
-                 subtest_name)
+      self.logger.debug('Evaluating checkpoint %s under subtest %s',
+                        checkpoint.name, subtest_name)
     else:
-      _LOG.debug('Evaluating checkpoint %s', checkpoint.name)
+      self.logger.debug('Evaluating checkpoint %s', checkpoint.name)
       subtest_name = None
     evaluated_millis = util.time_millis()
     try:
       outcome = PhaseExecutionOutcome(checkpoint.get_result(self.test_state))
-      _LOG.debug('Checkpoint %s result: %s', checkpoint.name,
-                 outcome.phase_result)
+      self.logger.debug('Checkpoint %s result: %s', checkpoint.name,
+                        outcome.phase_result)
       if outcome.is_fail_subtest and not subtest_rec:
         raise InvalidPhaseResultError(
             'Checkpoint returned FAIL_SUBTEST, but subtest not running.')
@@ -385,7 +381,7 @@ def evaluate_checkpoint(
   def skip_checkpoint(self, checkpoint: phase_branches.Checkpoint,
                       subtest_rec: Optional[test_record.SubtestRecord]) -> None:
     """Skip a checkpoint, but log a record of it."""
-    _LOG.debug('Automatically skipping checkpoint %s', checkpoint.name)
+    self.logger.debug('Automatically skipping checkpoint %s', checkpoint.name)
     subtest_name = subtest_rec.name if subtest_rec else None
     checkpoint_rec = test_record.CheckpointRecord.from_checkpoint(
         checkpoint, subtest_name,
@@ -417,11 +413,11 @@ def stop(
     if phase_thread.is_alive():
       phase_thread.kill()
 
-      _LOG.debug('Waiting for cancelled phase to exit: %s', phase_thread)
+      self.logger.debug('Waiting for cancelled phase to exit: %s', phase_thread)
       timeout = timeouts.PolledTimeout.from_seconds(timeout_s)
       while phase_thread.is_alive() and not timeout.has_expired():
         time.sleep(0.1)
-      _LOG.debug('Cancelled phase %s exit',
-                 "didn't" if phase_thread.is_alive() else 'did')
+      self.logger.debug('Cancelled phase %s exit',
+                        "didn't" if phase_thread.is_alive() else 'did')
     # Clear the currently running phase, whether it finished or timed out.
     self.test_state.stop_running_phase()

openhtf/core/test_descriptor.py

@@ -275,7 +275,8 @@ def abort_from_sig_int(self) -> None:
         self._executor.abort()
 
   def execute(self,
-              test_start: Optional[Union[phase_descriptor.PhaseT, Callable[[], str]]] = None,
+              test_start: Optional[Union[phase_descriptor.PhaseT,
+                                         Callable[[], str]]] = None,
               profile_filename: Optional[Text] = None) -> bool:
     """Starts the framework and executes the given test.
 
@@ -480,8 +481,8 @@ class TestApi(object):
     test_record: A reference to the output TestRecord for the currently running
       openhtf.Test.  Direct access to this attribute is *strongly* discouraged,
       but provided as a catch-all for interfaces not otherwise provided by
-      TestApi.  If you find yourself using this, please file a
-        feature request for an alternative at:
+      TestApi.  If you find yourself using this, please file a feature request
+      for an alternative at:
           https://github.com/google/openhtf/issues/new
   """
 
@@ -583,8 +584,7 @@ def get_measurement(
     return self._running_test_state.get_measurement(measurement_name)
 
   def get_measurement_strict(
-      self,
-      measurement_name: Text) -> test_state.ImmutableMeasurement:
+      self, measurement_name: Text) -> test_state.ImmutableMeasurement:
     """Get a copy of the test measurement from current or previous phase.
 
     Measurement and phase name uniqueness is not enforced, so this method will

openhtf/util/configuration.py

@@ -30,7 +30,7 @@
 
   CONF = configuration.CONF
 
-  ANITIMATTER_INTERMIX_CONSTANT = CONF.declare('antimatter_intermix_constant',
+  ANTIMATTER_INTERMIX_CONSTANT = CONF.declare('antimatter_intermix_constant',
       default_value=3.14159,
       description='Intermix constant calibrated for our warp core.')
 

openhtf/util/text.py

@@ -130,13 +130,14 @@ def StringFromMeasurement(measurement: openhtf.Measurement,
     return _ColorText(text, _BRIGHT_RED_STYLE) if colorize_text else text
   elif measurement.outcome == measurements.Outcome.FAIL:
     text = (f'| {measurement.name} failed because '
-            f'{measurement.measured_value.value} failed these checks: '
-            '{}'.format([str(v) for v in measurement.validators]))
+            f'{measurement.measured_value.value} failed these checks: ' +
+            str([str(v) for v in measurement.validators]))
     return _ColorText(text, _BRIGHT_RED_STYLE) if colorize_text else text
   elif measurement.marginal:
-    text = (f'| {measurement.name} is marginal because '
-            f'{measurement.measured_value.value} is marginal in these checks: '
-            '{}'.format([str(v) for v in measurement.validators]))
+    text = (
+        f'| {measurement.name} is marginal because '
+        f'{measurement.measured_value.value} is marginal in these checks: ' +
+        str([str(v) for v in measurement.validators]))
     return (_ColorText(text, str(colorama.Fore.YELLOW))
             if colorize_text else text)
   return f'| {measurement.name}: {measurement.measured_value.value}'

openhtf/util/threads.py

@@ -79,14 +79,15 @@ class is meant to be subclassed.  If you were to invoke this with
   during garbage collection.
   """
 
-  def __init__(self, *args, **kwargs):
+  def __init__(self, *args, logger: logging.Logger = _LOG, **kwargs):
     """Initializer for KillableThread.
 
     The keyword argument `run_with_profiling` is extracted from kwargs. If
     True, run this thread with profiling data collection.
 
     Args:
       *args: Passed to the base class.
+      logger: A logger for this class to use.
       **kwargs: Passed to the base class.
     """
     self._run_with_profiling = kwargs.pop('run_with_profiling',
@@ -98,6 +99,7 @@ def __init__(self, *args, **kwargs):
       self._profiler = cProfile.Profile()
     else:
       self._profiler = None
+    self._logger = logger
 
   def run(self):
     try:
@@ -109,11 +111,11 @@ def run(self):
         self._thread_proc()
     except Exception:  # pylint: disable=broad-except
       if not self._thread_exception(*sys.exc_info()):
-        _LOG.critical('Thread raised an exception: %s', self.name)
+        self._logger.critical('Thread raised an exception: %s', self.name)
         raise
     finally:
       self._thread_finished()
-      _LOG.debug('Thread finished: %s', self.name)
+      self._logger.debug('Thread finished: %s', self.name)
       if self._profiler is not None:
         self._profiler.disable()
 
@@ -161,11 +163,11 @@ def kill(self):
     """Terminates the current thread by raising an error."""
     self._killed.set()
     if not self.is_alive():
-      logging.debug('Cannot kill thread that is no longer running.')
+      self._logger.debug('Cannot kill thread that is no longer running.')
       return
     if not self._is_thread_proc_running():
-      logging.debug("Thread's _thread_proc function is no longer running, "
-                    'will not kill; letting thread exit gracefully.')
+      self._logger.debug("Thread's _thread_proc function is no longer running, "
+                         'will not kill; letting thread exit gracefully.')
       return
     self.async_raise(ThreadTerminationError)
 
@@ -176,8 +178,8 @@ def async_raise(self, exc_type):
 
     # If the thread has died we don't want to raise an exception so log.
     if not self.is_alive():
-      _LOG.debug('Not raising %s because thread %s (%s) is not alive', exc_type,
-                 self.name, self.ident)
+      self._logger.debug('Not raising %s because thread %s (%s) is not alive',
+                         exc_type, self.name, self.ident)
       return
 
     result = ctypes.pythonapi.PyThreadState_SetAsyncExc(

test/core/exe_test.py

@@ -258,6 +258,7 @@ def test_test_executor(self):
   def test_class_string(self):
     check_list = ['PhaseExecutorThread', 'phase_one']
     mock_test_state = mock.create_autospec(test_state.TestState)
+    mock_test_state.state_logger = logging.getLogger(__name__)
     phase_thread = phase_executor.PhaseExecutorThread(
         phase_one, mock_test_state, run_with_profiling=False, subtest_rec=None)
     name = str(phase_thread)

test/output/callbacks/callbacks_test.py

@@ -181,21 +181,23 @@ def test_outcome_colors(self):
   def test_empty_outcome(self):
     """Console Summary must not crash if phases have been skipped."""
     checkpoint = phase_branches.PhaseFailureCheckpoint.all_previous(
-      "cp", action=phase_descriptor.PhaseResult.FAIL_SUBTEST)
+        'cp', action=phase_descriptor.PhaseResult.FAIL_SUBTEST)
     phasegroup = phase_group.PhaseGroup(
-      lambda: htf.PhaseResult.FAIL_AND_CONTINUE,
-      lambda: htf.PhaseResult.SKIP,
-      checkpoint,
+        lambda: htf.PhaseResult.FAIL_AND_CONTINUE,
+        lambda: htf.PhaseResult.SKIP,
+        checkpoint,
     )
-    subtest = phase_collections.Subtest("st", phasegroup)
-    test = htf.Test(subtest)
+    subtest = phase_collections.Subtest('st', phasegroup)
+    test_instance = htf.Test(subtest)
 
     result_store = util.NonLocalResult()
+
     def _save_result(test_record):
       result_store.result = test_record
-    test.add_output_callbacks(
-        console_summary.ConsoleSummary(), _save_result)
 
-    test.execute()
-    assert not any("Traceback" in record.message
+    test_instance.add_output_callbacks(console_summary.ConsoleSummary(),
+                                       _save_result)
+
+    test_instance.execute()
+    assert not any('Traceback' in record.message
                    for record in result_store.result.log_records)

test/util/text_test.py

@@ -30,6 +30,7 @@
 from openhtf.util import test
 from openhtf.util import text
 from openhtf.util import threads
+from openhtf.util import validators
 
 # colorama makes these strings at runtime but pytype cannot infer this.
 _RED = typing.cast(str, colorama.Fore.RED)
@@ -148,6 +149,47 @@ def testStringFromMeasurement_SuccessfullyConvertsFailMeasurement(self):
         "| text_measurement_a failed because 5 failed these checks: ['x <= 3']")
     self.assertNotIn(text._BRIGHT_RED_STYLE, output)
 
+  def testStringFromMeasurement_SuccessfullyConvertsFailBracketedMeasurement(
+      self):
+    measurement = openhtf.Measurement('text_measurement_a').equals('hello')
+    measurement._measured_value = measurements.MeasuredValue(
+        'text_measurement_a')
+    measurement._measured_value.set('{hi}')
+    measurement.notify_value_set()
+    output = text.StringFromMeasurement(measurement)
+    self.assertEqual(output,
+                     ('| text_measurement_a failed because {hi} '
+                      "failed these checks: [\"'x' matches /^hello$/\"]"))
+    self.assertNotIn(text._BRIGHT_RED_STYLE, output)
+
+  def testStringFromMeasurement_SuccessfullyConvertsMarginalBracketedMeasurement(
+      self):
+
+    class LengthInRange(validators.InRange):
+
+      def __call__(self, value):
+        return super().__call__(len(value))
+
+      def is_marginal(self, value) -> bool:
+        return super().is_marginal(len(value))
+
+    # Length of 5 is pass, 4 or 6 is marginal.
+    validator = LengthInRange(
+        minimum=4, maximum=6, marginal_minimum=5, marginal_maximum=5)
+
+    measurement = openhtf.Measurement('text_measurement_a').with_validator(
+        validator)
+    measurement._measured_value = measurements.MeasuredValue(
+        'text_measurement_a')
+    measurement._measured_value.set('{hi}')
+    measurement.notify_value_set()
+    output = text.StringFromMeasurement(measurement)
+    self.assertEqual(
+        output,
+        ('| text_measurement_a is marginal because {hi} is marginal '
+         "in these checks: ['4 <= Marginal:5 <= x <= Marginal:5 <= 6']"))
+    self.assertNotIn(text._BRIGHT_RED_STYLE, output)
+
   def testStringFromMeasurement_SuccessfullyConvertsFailMeasurementColorized(
       self):
     measurement = openhtf.Measurement('text_measurement_a').in_range(maximum=3)