Handle dimensioned measurement validation errors (#770)

Exceptions in dimensioned measurement validations occur in the Test
Executor thread, which measn they are not caught by the normal flow of
tests.  When those occur, the test will end and will be reported as a
PASS.

This commit changes that.  Now, an exception during a dimensioned
validation measurement validator function will set the phase result to
the raise exception if the phase result is not terminal.  The existing
result will be left in place if it is terminal; in this case, the
validator exception is logged with its stack dump to ensure that there
is still a record.

Author: arsharma1

openhtf/core/measurements.py

@@ -251,11 +251,17 @@ def _with_validator(*args, **kwargs):  # pylint: disable=invalid-name
   def validate(self):
     """Validate this measurement and update its 'outcome' field."""
     # PASS if all our validators return True, otherwise FAIL.
-    if all(v(self.measured_value.value) for v in self.validators):
-      self.outcome = Outcome.PASS
-    else:
+    try:
+      if all(v(self.measured_value.value) for v in self.validators):
+        self.outcome = Outcome.PASS
+      else:
+        self.outcome = Outcome.FAIL
+      return self
+    except Exception as e:  # pylint: disable=bare-except
+      _LOG.error('Validation for measurement %s raised an exception %s.',
+                 self.name, e)
       self.outcome = Outcome.FAIL
-    return self
+      raise
 
   def _asdict(self):
     """Convert this measurement to a dict of basic types."""

openhtf/core/phase_executor.py

@@ -57,6 +57,7 @@
 
 class ExceptionInfo(collections.namedtuple(
     'ExceptionInfo', ['exc_type', 'exc_val', 'exc_tb'])):
+  """Wrap the description of a raised exception and its traceback."""
 
   def _asdict(self):
     return {
@@ -235,9 +236,10 @@ def _execute_phase_once(self, phase_desc, is_last_repeat):
     # 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)
+                 phase_desc.name)
       return PhaseExecutionOutcome(openhtf.PhaseResult.SKIP)
 
+    override_result = None
     with self.test_state.running_phase_context(phase_desc) as phase_state:
       _LOG.debug('Executing phase %s', phase_desc.name)
       with self._current_phase_thread_lock:
@@ -256,13 +258,16 @@ def _execute_phase_once(self, phase_desc, is_last_repeat):
         phase_thread.start()
         self._current_phase_thread = phase_thread
 
-      result = phase_state.result = phase_thread.join_or_die()
+      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.')
         phase_state.hit_repeat_limit = True
-        result = PhaseExecutionOutcome(openhtf.PhaseResult.STOP)
+        override_result = PhaseExecutionOutcome(openhtf.PhaseResult.STOP)
       self._current_phase_thread = None
 
+    # Refresh the result in case a validation for a partially set measurement
+    # raised an exception.
+    result = override_result or phase_state.result
     _LOG.debug('Phase %s finished with result %s', phase_desc.name,
                result.phase_result)
     return result

openhtf/core/test_state.py

@@ -31,6 +31,7 @@
 import mimetypes
 import os
 import socket
+import sys
 import traceback
 
 from enum import Enum
@@ -519,7 +520,17 @@ def _finalize_measurements(self):
       measurement.set_notification_callback(None)
       # Validate multi-dimensional measurements now that we have all values.
       if measurement.outcome is measurements.Outcome.PARTIALLY_SET:
-        measurement.validate()
+        try:
+          measurement.validate()
+        except Exception:  # pylint: disable=broad-except
+          # Record the exception as the new result.
+          if self.phase_record.result.is_terminal:
+            _LOG.exception(
+                'Measurement validation raised an exception, but phase result '
+                'is already terminal; logging additional exception here.')
+          else:
+            self.phase_record.result = phase_executor.PhaseExecutionOutcome(
+                phase_executor.ExceptionInfo(*sys.exc_info()))
 
     # Set final values on the PhaseRecord.
     self.phase_record.measurements = self.measurements

test/core/measurements_test.py

@@ -34,6 +34,33 @@
                     'lineno', 'codeinfo', 'code_info', 'descriptor_id'}
 
 
+class BadValidatorError(Exception):
+  pass
+
+
+class BadPhaseError(Exception):
+  pass
+
+
+def bad_validator(value):
+  del value  # Unused.
+  raise BadValidatorError('This is a bad validator.')
+
+
+@htf.measures(htf.Measurement('bad').with_dimensions('a').with_validator(
+    bad_validator))
+def bad_validator_phase(test):
+  test.measurements.bad[1] = 1
+  test.measurements.bad[2] = 2
+
+
+@htf.measures(htf.Measurement('bad').with_dimensions('a').with_validator(
+    bad_validator))
+def bad_validator_with_error(test):
+  test.measurements.bad[2] = 2
+  raise BadPhaseError('Bad phase.')
+
+
 class TestMeasurements(htf_test.TestCase):
 
   def setUp(self):
@@ -91,6 +118,26 @@ def test_measurement_order(self):
                      ['replaced_min_only', 'replaced_max_only',
                       'replaced_min_max'])
 
+  @htf_test.yields_phases
+  def test_bad_validation(self):
+    record = yield bad_validator_phase
+    self.assertPhaseError(record, exc_type=BadValidatorError)
+    self.assertMeasurementFail(record, 'bad')
+
+  @htf_test.yields_phases
+  def test_bad_validation_with_other_phases(self):
+    test_record = yield htf.Test(bad_validator_phase, all_the_things.dimensions)
+    self.assertTestError(test_record, exc_type=BadValidatorError)
+    # Start phase and the bad validator phase only.
+    self.assertEqual(len(test_record.phases), 2)
+    self.assertPhaseError(test_record.phases[1], exc_type=BadValidatorError)
+
+  @htf_test.yields_phases
+  def test_bad_validation_with_error(self):
+    record = yield bad_validator_with_error
+    self.assertPhaseError(record, exc_type=BadPhaseError)
+    self.assertMeasurementFail(record, 'bad')
+
 
 class TestMeasurement(htf_test.TestCase):
 
@@ -130,3 +177,13 @@ def test_to_dataframe(self, units=True):
 
   def test_to_dataframe__no_units(self):
     self.test_to_dataframe(units=False)
+
+  def test_bad_validator(self):
+    measurement = htf.Measurement('bad_measure')
+    measurement.with_dimensions('a')
+    measurement.with_validator(bad_validator)
+    measurement.measured_value['A'] = 1
+    measurement.measured_value['B'] = 2
+    with self.assertRaises(BadValidatorError):
+      measurement.validate()
+