Restructure test state finalization.

Finalizing the test state causes the loggers to be reset.  This also
meant that a failure during the teardown phase does not affect the test
outcome.

Changing this so the finalization always occurs after the teardown phase
and plug teardowns to gather their logs.

Author: arsharma1

openhtf/core/test_executor.py

@@ -74,6 +74,7 @@ def __init__(self, test_descriptor, execution_uid, test_start,
     self._exit_stack = None
     self.uid = execution_uid
     self.failure_exceptions = failure_exceptions
+    self._latest_outcome = None
 
   def stop(self):
     """Stop this test."""
@@ -150,21 +151,29 @@ def _thread_proc(self):
       # Full plug initialization happens _after_ the start trigger, as close to
       # test execution as possible, for the best chance of test equipment being
       # in a known-good state at the start of test execution.
-      if not self._initialize_plugs():
+      if self._initialize_plugs():
         return
 
       # Everything is set, set status and begin test execution.
       self._execute_test_phases(phase_exec)
 
   def _initialize_plugs(self, plug_types=None):
+    """Initialize plugs.
+
+    Args:
+      plug_types: optional list of plug classes to initialize.
+
+    Returns:
+      True if there was an error initializing the plugs.
+    """
     try:
       self.test_state.plug_manager.initialize_plugs(plug_types=plug_types)
-      return True
+      return False
     except Exception:  # pylint: disable=broad-except
-      # Exit early if plug initializaion failed.
-      self.test_state.finalize_on_failed_plug_initialization(
+      # Record the equivalent failure outcome and exit early.
+      self._latest_outcome = phase_executor.PhaseExecutionOutcome(
           phase_executor.ExceptionInfo(*sys.exc_info()))
-      return False
+      return True
 
   def _execute_test_start(self, phase_exec):
     """Run the start trigger phase, and check that the DUT ID is set after.
@@ -181,24 +190,35 @@ def _execute_test_start(self, phase_exec):
     """
     # Have the phase executor run the start trigger phase. Do partial plug
     # initialization for just the plugs needed by the start trigger phase.
-    if not self._initialize_plugs(
-        plug_types=[phase_plug.cls for phase_plug in self._test_start.plugs]):
+    if self._initialize_plugs(plug_types=[
+        phase_plug.cls for phase_plug in self._test_start.plugs]):
       return True
 
-    outcome = phase_exec.execute_phase(self._test_start)
-    if outcome.is_terminal:
-      self.test_state.finalize_from_phase_outcome(outcome)
+    self._latest_outcome = phase_exec.execute_phase(self._test_start)
+    if self._latest_outcome.is_terminal:
+      return True
 
     if self.test_state.test_record.dut_id is None:
       _LOG.warning('Start trigger did not set DUT ID. A later phase will need'
                    ' to do so to prevent a BlankDutIdError when the test ends.')
-    return outcome.is_terminal
+    return False
 
   def _execute_test_teardown(self, phase_exec):
     phase_exec.stop(timeout_s=conf.cancel_timeout_s)
     if self._do_teardown_function and self._teardown_function:
-      phase_exec.execute_phase(self._teardown_function)
+      outcome = phase_exec.execute_phase(self._teardown_function)
+      # Ignore teardown phase outcome if there is already a terminal error.
+      if not self._latest_outcome or not self._latest_outcome.is_terminal:
+        self._latest_outcome = outcome
+    # Plug teardown does not affect the test outcome.
     self.test_state.plug_manager.tear_down_plugs()
+
+    # Now finalize the test state.
+    if self._latest_outcome and self._latest_outcome.is_terminal:
+      self.test_state.finalize_from_phase_outcome(self._latest_outcome)
+    else:
+      self.test_state.finalize_normally()
+
     # Make sure if there was an error during test execution that the error
     # message is printed last and in a noticeable color so it doesn't get
     # scrolled off the screen or missed.
@@ -212,12 +232,9 @@ def _execute_test_phases(self, phase_exec):
 
     try:
       for phase in self._test_descriptor.phases:
-        outcome = phase_exec.execute_phase(phase)
-        if outcome.is_terminal:
-          self.test_state.finalize_from_phase_outcome(outcome)
+        self._latest_outcome = phase_exec.execute_phase(phase)
+        if self._latest_outcome.is_terminal:
           break
-      else:
-        self.test_state.finalize_normally()
     except KeyboardInterrupt:
       self.test_state.logger.info('KeyboardInterrupt caught, aborting test.')
       raise

openhtf/core/test_state.py

@@ -335,17 +335,6 @@ def finalize_from_phase_outcome(self, phase_execution_outcome):
                                            'A phase stopped the test run.')
       self._finalize(test_record.Outcome.FAIL)
 
-  def finalize_on_failed_plug_initialization(self, except_info):
-    if self._is_aborted():
-      return
-
-    self.logger.error('Finishing test execution early due to failed plug '
-                      'initialization.')
-    code = except_info.exc_type.__name__
-    description = str(except_info.exc_val)
-    self.test_record.add_outcome_details(code, description)
-    self._finalize(test_record.Outcome.ERROR)
-
   def finalize_normally(self):
     """Mark the state as finished.
 

test/core/exe_test.py

@@ -123,6 +123,18 @@ def fail_plug_phase(fail):
   del fail
 
 
+def blank_phase():
+  pass
+
+
+class TeardownError(Exception):
+  pass
+
+
+def teardown_fail():
+  raise TeardownError()
+
+
 class TestExecutor(unittest.TestCase):
 
   class TestDummyExceptionError(Exception):
@@ -288,7 +300,7 @@ def never_gonna_run_phase():
 
     test = openhtf.Test(never_gonna_run_phase)
     executor = core.TestExecutor(test.descriptor, 'uid', fail_plug_phase,
-                                 teardown_function=lambda: ev.set())  # pyling: disable=unnecessary-lambda
+                                 teardown_function=lambda: ev.set())  # pylint: disable=unnecessary-lambda
     executor.start()
     executor.wait()
     record = executor.test_state.test_record
@@ -299,6 +311,33 @@ def never_gonna_run_phase():
     self.assertFalse(ev.is_set())
     self.assertFalse(ev2.is_set())
 
+  def test_error_during_teardown(self):
+    test = openhtf.Test(blank_phase)
+    executor = core.TestExecutor(test.descriptor, 'uid', start_phase,
+                                 teardown_function=teardown_fail)
+    executor.start()
+    executor.wait()
+    record = executor.test_state.test_record
+    self.assertEqual(record.outcome, Outcome.ERROR)
+    self.assertEqual(record.outcome_details[0].code, TeardownError.__name__)
+
+  def test_log_during_teardown(self):
+    message = 'hello'
+
+    def teardown_log(test):
+      test.logger.info(message)
+
+    test = openhtf.Test(blank_phase)
+    executor = core.TestExecutor(test.descriptor, 'uid', start_phase,
+                                 teardown_function=teardown_log)
+    executor.start()
+    executor.wait()
+    record = executor.test_state.test_record
+    self.assertEqual(record.outcome, Outcome.PASS)
+    log_records = [log_record for log_record in record.log_records
+                   if log_record.message == message]
+    self.assertTrue(log_records)
+
 
 class TestPhaseExecutor(unittest.TestCase):