def test_cancel_phase(self):
@openhtf.PhaseOptions()
def cancel_phase(test):
del test # Unused.
# See above cancel_phase for explanations.
inner_ev = threading.Event()
def stop_executor():
executor.stop()
inner_ev.set()
threading.Thread(target=stop_executor).start()
inner_ev.wait(1)
ev = threading.Event()
test = openhtf.Test(cancel_phase)
# Cancel during test start phase.
executor = core.TestExecutor(test.descriptor, 'uid', start_phase, 'dut',
teardown_function=lambda: ev.set()) # pylint: disable=unnecessary-lambda
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should be executed.
self.assertTrue(ev.wait(1))
def record_timing_context(self):
"""Context manager for the execution of a single phase.
This method performs some pre-phase setup on self (for measurements), and
records the start and end time based on when the context is entered/exited.
"""
self.phase_record.start_time_millis = util.time_millis()
try:
yield
finally:
# Initialize with already-validated and UNSET measurements.
validated_measurements = {
name: measurement
for name, measurement in self.measurements.iteritems()
if measurement.outcome is not measurements.Outcome.PARTIALLY_SET
}
# Validate multi-dimensional measurements now that we have all values.
validated_measurements.update({
name: measurement.validate()
for name, measurement in self.measurements.iteritems()
if measurement.outcome is measurements.Outcome.PARTIALLY_SET
})
# Fill out final values for the PhaseRecord.
self.phase_record.measurements = validated_measurements
self.phase_record.end_time_millis = util.time_millis()
def record_timing_context(self):
"""Context manager for the execution of a single phase.
This method performs some pre-phase setup on self (for measurements), and
records the start and end time based on when the context is entered/exited.
Yields:
None
"""
self.phase_record.start_time_millis = util.time_millis()
try:
yield
finally:
# Initialize with already-validated and UNSET measurements.
validated_measurements = {
name: measurement
for name, measurement in self.measurements.iteritems() if
measurement.outcome is not measurements.Outcome.PARTIALLY_SET
}
# Validate multi-dimensional measurements now that we have all values.
validated_measurements.update({
name: measurement.validate()
for name, measurement in self.measurements.iteritems()
if measurement.outcome is measurements.Outcome.PARTIALLY_SET
})
# Fill out final values for the PhaseRecord.
self.phase_record.measurements = validated_measurements
self.phase_record.end_time_millis = util.time_millis()
self.phase_record.options = self.options
def test_cancel_phase(self):
@openhtf.PhaseOptions()
def start_phase(test):
test.dut_id = 'DUT ID'
@openhtf.PhaseOptions()
def cancel_phase(test):
del test # Unused.
# See above cancel_phase for explanations.
inner_ev = threading.Event()
def stop_executor():
executor.stop()
inner_ev.set()
threading.Thread(target=stop_executor).start()
inner_ev.wait(1)
ev = threading.Event()
test = openhtf.Test(cancel_phase)
# Cancel during test start phase.
executor = core.TestExecutor(test.descriptor, 'uid', start_phase,
teardown_function=lambda: ev.set()) # pylint: disable=unnecessary-lambda
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should be executed.
self.assertTrue(ev.wait(1))
def test_cancel_phase(self):
@openhtf.PhaseOptions()
def cancel_phase():
# See above cancel_phase for explanations.
_abort_executor_in_thread(executor.abort)
ev = threading.Event()
group = phase_group.PhaseGroup(main=[cancel_phase],
teardown=[lambda: ev.set()]) # pylint: disable=unnecessary-lambda
test = openhtf.Test(group)
test.configure(
default_dut_id='dut',
)
executor = test_executor.TestExecutor(
test.descriptor, 'uid', start_phase, test._test_options)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should be executed.
self.assertTrue(ev.wait(1))
def test_cancel_phase(self):
@openhtf.PhaseOptions()
def cancel_phase():
# See above cancel_phase for explanations.
_abort_executor_in_thread(executor.abort)
ev = threading.Event()
group = phase_group.PhaseGroup(main=[cancel_phase],
teardown=[lambda: ev.set()]) # pylint: disable=unnecessary-lambda
test = openhtf.Test(group)
test.configure(default_dut_id='dut', )
executor = test_executor.TestExecutor(test.descriptor,
'uid',
start_phase,
test._test_options,
run_with_profiling=False)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should be executed.
self.assertTrue(ev.wait(1))
executor.close()
def test_cancel_twice_phase(self):
def abort_twice():
executor.abort()
teardown_running.wait()
executor.abort()
@openhtf.PhaseOptions()
def cancel_twice_phase():
# See above cancel_phase for explanations.
_abort_executor_in_thread(abort_twice)
@openhtf.PhaseOptions()
def teardown_phase():
teardown_running.set()
# Sleeping for the entire duration has a race condition with cancellation.
timeout = timeouts.PolledTimeout(1)
while not timeout.has_expired():
time.sleep(0.01)
ev.set()
@openhtf.PhaseOptions()
def teardown2_phase():
ev2.set()
teardown_running = threading.Event()
ev = threading.Event()
ev2 = threading.Event()
group = phase_group.PhaseGroup(
main=[cancel_twice_phase],
teardown=[teardown_phase, teardown2_phase])
test = openhtf.Test(group)
test.configure(default_dut_id='dut', )
executor = test_executor.TestExecutor(test.descriptor,
'uid',
start_phase,
test._test_options,
run_with_profiling=False)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should *NOT* be executed.
self.assertFalse(ev.is_set())
self.assertFalse(ev2.is_set())
executor.close()
def _finalize(self, test_outcome: test_record.Outcome) -> None:
aborting = test_outcome == test_record.Outcome.ABORTED
assert not self.is_finalized or aborting, (
'Test already completed with status %s!' % self._status.name)
self.test_record.outcome = test_outcome
# If we've reached here without 'starting' the test, then we 'start' it just
# so we can properly 'end' it.
if self.test_record.start_time_millis == 0:
self.test_record.start_time_millis = util.time_millis()
# The test is done at this point, no further updates to test_record.
self.test_record.end_time_millis = util.time_millis()
self._status = self.Status.COMPLETED
self.notify_update()
def test_cancel_start(self):
@openhtf.PhaseOptions()
def cancel_phase(test):
test.dut_id = 'DUT ID'
# We have 'executor' because we're inside the test method's scope.
# We have to run it in a thread to avoid getting a nasty series of
# confusing errors:
_abort_executor_in_thread(executor.abort)
ev = threading.Event()
group = phase_group.PhaseGroup(
teardown=[lambda: ev.set()], # pylint: disable=unnecessary-lambda
)
test = openhtf.Test(group)
test.configure(default_dut_id='dut', )
# Cancel during test start phase.
executor = test_executor.TestExecutor(test.descriptor, 'uid',
cancel_phase, test._test_options)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, cancel_phase.name)
# The test will end at the same time it starts because the test never
# actually started, we canceled it inside of test_start, resulting in a
# short vacuous start. Start and end times should be no more than a
# few milliseconds apart in that case.
self.assertLess(record.end_time_millis - record.start_time_millis, 4)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should not be executed.
self.assertFalse(ev.wait(3))
def __init__(self, *phases, **metadata):
# Some sanity checks on special metadata keys we automatically fill in.
if 'config' in metadata:
raise KeyError(
'Invalid metadata key "config", it will be automatically populated.')
self.created_time_millis = util.time_millis()
self.last_run_time_millis = None
code_info = test_record.CodeInfo.for_module_from_stack(levels_up=2)
self._test_desc = TestDescriptor(self.uid, phases, code_info, metadata)
self._test_options = TestOptions()
self._lock = threading.Lock()
self._executor = None
# Make sure configure() gets called at least once before Execute(). The
# user might call configure() again to override options, but we don't want
# to force them to if they want to use defaults. For default values, see
# the class definition of TestOptions.
if 'test_name' in metadata:
# Allow legacy metadata key for specifying test name.
self.configure(name=metadata['test_name'])
else:
self.configure()
self.TEST_INSTANCES[self.uid] = self
# This is a noop if the server is already running, otherwise start it now
# that we have at least one Test instance.
station_api.start_server()
def mark_test_started(self, dut_id): """Set the TestRecord's dut_id and start_time_millis fields.""" assert self._status == self.Status.WAITING_FOR_TEST_START # This might still be None; it's the value returned by test_start. self.test_record.dut_id = dut_id self.test_record.start_time_millis = util.time_millis() self.notify_update()
def evaluate_checkpoint(
self, checkpoint: phase_branches.Checkpoint,
subtest_rec: Optional[test_record.SubtestRecord]
) -> PhaseExecutionOutcome:
"""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)
else:
_LOG.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)
if outcome.is_fail_subtest and not subtest_rec:
raise InvalidPhaseResultError(
'Checkpoint returned FAIL_SUBTEST, but subtest not running.'
)
except Exception: # pylint: disable=broad-except
outcome = PhaseExecutionOutcome(ExceptionInfo(*sys.exc_info()))
checkpoint_rec = test_record.CheckpointRecord.from_checkpoint(
checkpoint, subtest_name, outcome, evaluated_millis)
self.test_state.test_record.add_checkpoint_record(checkpoint_rec)
return outcome
def setup_logger():
"""Configure logging for OpenHTF."""
record_logger = logging.getLogger(RECORD_LOGGER)
record_logger.propagate = False
record_logger.setLevel(logging.DEBUG)
record_logger.addHandler(logging.StreamHandler(stream=sys.stdout))
logger = logging.getLogger(LOGGER_PREFIX)
logger.propagate = False
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
if LOGFILE:
try:
cur_time = str(util.time_millis())
file_handler = logging.FileHandler('%s.%s' % (LOGFILE, cur_time))
file_handler.setFormatter(formatter)
file_handler.setLevel(DEFAULT_LOGFILE_LEVEL.upper())
file_handler.addFilter(MAC_FILTER)
logger.addHandler(file_handler)
except IOError as exception:
print ('Failed to set up log file due to error: %s. '
'Continuing anyway.' % exception)
if not QUIET:
console_handler = logging.StreamHandler(stream=sys.stderr)
console_handler.setFormatter(formatter)
console_handler.setLevel(DEFAULT_LEVEL.upper())
console_handler.addFilter(MAC_FILTER)
logger.addHandler(console_handler)
def __init__(self, *nodes: phase_descriptor.PhaseCallableOrNodeT,
**metadata: Any):
# Some sanity checks on special metadata keys we automatically fill in.
if 'config' in metadata:
raise KeyError(
'Invalid metadata key "config", it will be automatically populated.'
)
self.created_time_millis = util.time_millis()
self.last_run_time_millis = None
self._test_options = TestOptions()
self._lock = threading.Lock()
self._executor = None
# TODO(arsharma): Drop _flatten at some point.
sequence = phase_collections.PhaseSequence(nodes)
self._test_desc = TestDescriptor(sequence,
htf_test_record.CodeInfo.uncaptured(),
metadata)
if CONF.capture_source:
# Copy the phases with the real CodeInfo for them.
self._test_desc.phase_sequence = (
self._test_desc.phase_sequence.load_code_info())
self._test_desc.code_info = (
htf_test_record.CodeInfo.for_module_from_stack(levels_up=2))
# Make sure configure() gets called at least once before Execute(). The
# user might call configure() again to override options, but we don't want
# to force them to if they want to use defaults. For default values, see
# the class definition of TestOptions.
if 'test_name' in metadata:
# Allow legacy metadata key for specifying test name.
self.configure(name=metadata['test_name'])
else:
self.configure()
def _execute_phase_branch(self, branch: phase_branches.BranchSequence,
subtest_rec: Optional[test_record.SubtestRecord],
in_teardown: bool) -> _ExecutorReturn:
branch_message = branch.diag_condition.message
if branch.name:
branch_message = '{}:{}'.format(branch.name, branch_message)
if not in_teardown and subtest_rec and subtest_rec.is_fail:
self.logger.debug('%s: Branch not being run due to failed subtest.',
branch_message)
return _ExecutorReturn.CONTINUE
evaluated_millis = util.time_millis()
if branch.should_run(self.test_state.diagnoses_manager.store):
self.logger.debug('%s: Branch condition met; running phases.',
branch_message)
branch_taken = True
ret = self._execute_sequence(branch, subtest_rec, in_teardown)
else:
self.logger.debug('%s: Branch condition NOT met; not running sequence.',
branch_message)
branch_taken = False
ret = _ExecutorReturn.CONTINUE
branch_rec = test_record.BranchRecord.from_branch(branch, branch_taken,
evaluated_millis)
self.test_state.test_record.add_branch_record(branch_rec)
return ret
def _finalize(self, test_outcome):
aborting = test_outcome == test_record.Outcome.ABORTED
assert not self.is_finalized or aborting, (
'Test already completed with status %s!' % self._status.name)
self.test_record.outcome = test_outcome
# If we've reached here without 'starting' the test, then we 'start' it just
# so we can properly 'end' it.
if self.test_record.start_time_millis == 0:
self.test_record.start_time_millis = util.time_millis()
# The test is done at this point, no further updates to test_record.
self.logger.handlers = []
self.test_record.end_time_millis = util.time_millis()
self._status = self.Status.COMPLETED
self.notify_update()
def setup_logger():
"""Configure logging for OpenHTF."""
record_logger = logging.getLogger(RECORD_LOGGER)
record_logger.propagate = False
record_logger.setLevel(logging.DEBUG)
record_logger.addHandler(logging.StreamHandler(stream=sys.stdout))
logger = logging.getLogger(LOGGER_PREFIX)
logger.propagate = False
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
if LOGFILE:
try:
cur_time = str(util.time_millis())
file_handler = logging.FileHandler('%s.%s' % (LOGFILE, cur_time))
file_handler.setFormatter(formatter)
file_handler.setLevel(DEFAULT_LOGFILE_LEVEL.upper())
file_handler.addFilter(MAC_FILTER)
logger.addHandler(file_handler)
except IOError as exception:
print('Failed to set up log file due to error: %s. '
'Continuing anyway.' % exception)
if not QUIET:
console_handler = logging.StreamHandler(stream=sys.stderr)
console_handler.setFormatter(formatter)
console_handler.setLevel(DEFAULT_LEVEL.upper())
console_handler.addFilter(MAC_FILTER)
logger.addHandler(console_handler)
def __init__(self, *phases, **metadata):
# Some sanity checks on special metadata keys we automatically fill in.
if 'config' in metadata:
raise KeyError(
'Invalid metadata key "config", it will be automatically populated.'
)
self.created_time_millis = util.time_millis()
self.last_run_time_millis = None
self._test_options = TestOptions()
self._lock = threading.Lock()
self._executor = None
self._test_desc = TestDescriptor(phases,
test_record.CodeInfo.uncaptured(),
metadata)
if conf.capture_source:
# First, we copy the phases with the real CodeInfo for them.
group = self._test_desc.phase_group.load_code_info()
# Then we replace the TestDescriptor with one that stores the test
# module's CodeInfo as well as our newly copied phases.
code_info = test_record.CodeInfo.for_module_from_stack(levels_up=2)
self._test_desc = self._test_desc._replace(code_info=code_info,
phase_group=group)
# Make sure configure() gets called at least once before Execute(). The
# user might call configure() again to override options, but we don't want
# to force them to if they want to use defaults. For default values, see
# the class definition of TestOptions.
if 'test_name' in metadata:
# Allow legacy metadata key for specifying test name.
self.configure(name=metadata['test_name'])
else:
self.configure()
def __init__(self, *phases, **metadata):
# Some sanity checks on special metadata keys we automatically fill in.
if 'config' in metadata:
raise KeyError(
'Invalid metadata key "config", it will be automatically populated.')
self.created_time_millis = util.time_millis()
self.last_run_time_millis = None
self._test_options = TestOptions()
self._lock = threading.Lock()
self._executor = None
self._test_desc = TestDescriptor(
phases, test_record.CodeInfo.uncaptured(), metadata)
if conf.capture_source:
# First, we copy the phases with the real CodeInfo for them.
group = self._test_desc.phase_group.load_code_info()
# Then we replace the TestDescriptor with one that stores the test
# module's CodeInfo as well as our newly copied phases.
code_info = test_record.CodeInfo.for_module_from_stack(levels_up=2)
self._test_desc = self._test_desc._replace(
code_info=code_info, phase_group=group)
# Make sure configure() gets called at least once before Execute(). The
# user might call configure() again to override options, but we don't want
# to force them to if they want to use defaults. For default values, see
# the class definition of TestOptions.
if 'test_name' in metadata:
# Allow legacy metadata key for specifying test name.
self.configure(name=metadata['test_name'])
else:
self.configure()
def test_cancel_twice_phase(self):
def abort_twice():
executor.abort()
teardown_running.wait()
executor.abort()
@openhtf.PhaseOptions()
def cancel_twice_phase():
# See above cancel_phase for explanations.
_abort_executor_in_thread(abort_twice)
@openhtf.PhaseOptions()
def teardown_phase():
teardown_running.set()
# Sleeping for the entire duration has a race condition with cancellation.
timeout = timeouts.PolledTimeout(1)
while not timeout.has_expired():
time.sleep(0.01)
ev.set()
@openhtf.PhaseOptions()
def teardown2_phase():
ev2.set()
teardown_running = threading.Event()
ev = threading.Event()
ev2 = threading.Event()
group = phase_group.PhaseGroup(main=[cancel_twice_phase],
teardown=[teardown_phase, teardown2_phase])
test = openhtf.Test(group)
test.configure(
default_dut_id='dut',
)
executor = test_executor.TestExecutor(
test.descriptor, 'uid', start_phase, test._test_options)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should *NOT* be executed.
self.assertFalse(ev.is_set())
self.assertFalse(ev2.is_set())
def execute(self, test_start=None):
"""Starts the framework and executes the given test.
Args:
test_start: Either a trigger phase for starting the test, or a function
that returns a DUT ID. If neither is provided, defaults to not
setting the DUT ID.
"""
# Lock this section so we don't .stop() the executor between instantiating
# it and .Start()'ing it, doing so does weird things to the executor state.
with self._lock:
# Sanity check to make sure someone isn't doing something weird like
# trying to Execute() the same test twice in two separate threads. We
# hold the lock between here and Start()'ing the executor to guarantee
# that only one thread is successfully executing the test.
if self._executor:
raise InvalidTestStateError('Test already running', self._executor)
# Snapshot some things we care about and store them.
self._test_desc.metadata['test_name'] = self._test_options.name
self._test_desc.metadata['config'] = conf._asdict()
self.last_run_time_millis = util.time_millis()
if isinstance(test_start, LambdaType):
@TestPhase()
def trigger_phase(test):
test.test_record.dut_id = test_start()
trigger = trigger_phase
else:
trigger = test_start
if conf.capture_source:
trigger.code_info = test_record.CodeInfo.for_function(trigger.func)
self._executor = core.TestExecutor(
self._test_desc, trigger, self._test_options.teardown_function)
_LOG.info('Executing test: %s', self.descriptor.code_info.name)
self._executor.start()
try:
self._executor.wait()
finally:
try:
final_state = self._executor.finalize()
_LOG.debug('Test completed for %s, saving to history and outputting.',
final_state.test_record.metadata['test_name'])
for output_cb in (self._test_options.output_callbacks +
[functools.partial(history.append_record, self.uid)]):
try:
output_cb(final_state.test_record)
except Exception: # pylint: disable=broad-except
_LOG.exception(
'Output callback %s raised; continuing anyway', output_cb)
finally:
self._executor = None
return final_state.test_record.outcome == test_record.Outcome.PASS
def record_timing_context(self):
"""Context manager for the execution of a single phase.
This method performs some pre-phase setup on self (for measurements), and
records the start and end time based on when the context is entered/exited.
Yields:
None
"""
self.phase_record.start_time_millis = util.time_millis()
try:
yield
finally:
self._finalize_measurements()
self._set_phase_outcome()
self.phase_record.end_time_millis = util.time_millis()
self.phase_record.options = self.options
def record_timing_context(self):
"""Context manager for the execution of a single phase.
This method performs some pre-phase setup on self (for measurements), and
records the start and end time based on when the context is entered/exited.
Yields:
None
"""
self.phase_record.start_time_millis = util.time_millis()
try:
yield
finally:
self._finalize_measurements()
self._set_phase_outcome()
self.phase_record.end_time_millis = util.time_millis()
self.phase_record.options = self.options
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)
subtest_name = subtest_rec.name if subtest_rec else None
checkpoint_rec = test_record.CheckpointRecord.from_checkpoint(
checkpoint, subtest_name,
PhaseExecutionOutcome(phase_descriptor.PhaseResult.SKIP),
util.time_millis())
self.test_state.test_record.add_checkpoint_record(checkpoint_rec)
def make_uid(self):
"""Returns the next test execution's UID.
This identifier must be unique but trackable across invocations of
execute(). Therefore, it's made of four parts separated by ':'
* Process-specific (decided on process start up)
* Test descriptor-specific (decided on descriptor creation)
* Execution-specific (decided on test start)
"""
return '%s:%s:%s:%s' % (os.getpid(), self.descriptor.uid,
uuid.uuid4().hex[:16], util.time_millis())
def make_uid(self):
"""Returns the next test execution's UID.
This identifier must be unique but trackable across invocations of
execute(). Therefore, it's made of four parts separated by ':'
* Process-specific (decided on process start up)
* Test descriptor-specific (decided on descriptor creation)
* Execution-specific (decided on test start)
"""
return '%s:%s:%s:%s' % (os.getpid(), self.descriptor.uid,
uuid.uuid4().hex[:16], util.time_millis())
def _finalize(self, test_outcome):
aborting = test_outcome == test_record.Outcome.ABORTED
assert not self.is_finalized or aborting, (
'Test already completed with status %s!' % self._status.name)
# Sanity check to make sure we have a DUT ID by the end of the test.
if not self.test_record.dut_id:
raise BlankDutIdError(
'Blank or missing DUT ID, HTF requires a non-blank ID.')
self.test_record.outcome = test_outcome
# If we've reached here without 'starting' the test, then we 'start' it just
# so we can properly 'end' it.
if self.test_record.start_time_millis == 0:
self.test_record.start_time_millis = util.time_millis()
# The test is done at this point, no further updates to test_record.
self.logger.handlers = []
self.test_record.end_time_millis = util.time_millis()
self._status = self.Status.COMPLETED
self.notify_update()
def mark_operator_attendance_start(self):
if not self._track_operator_time:
return
if self._start_time_millis is not None:
raise OperatorAttendanceViolation(
"Attempt to mark operator attendance start without marking an end to the previous one."
)
self._elapsed_seconds = 0
self._response_time_millis = None
self._start_time_millis = util.time_millis()
def test_cancel_phase_with_diagnoser(self):
class DiagResult(openhtf.DiagResultEnum):
RESULT = 'result'
@openhtf.PhaseDiagnoser(DiagResult)
def diag(phase_record):
del phase_record # Unused.
return openhtf.Diagnosis(DiagResult.RESULT, 'result')
@openhtf.diagnose(diag)
@openhtf.PhaseOptions()
def cancel_phase():
# See above cancel_phase for explanations.
_abort_executor_in_thread(executor.abort)
ev = threading.Event()
def set_ev():
ev.set()
group = phase_group.PhaseGroup(main=[cancel_phase], teardown=[set_ev])
test = openhtf.Test(group)
test.configure(default_dut_id='dut', )
executor = test_executor.TestExecutor(test.descriptor,
'uid',
start_phase,
test._test_options,
run_with_profiling=False)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, start_phase.name)
self.assertLessEqual(record.start_time_millis, util.time_millis())
self.assertLessEqual(record.start_time_millis, record.end_time_millis)
self.assertLessEqual(record.end_time_millis, util.time_millis())
self.assertEqual([], record.diagnoses)
# Teardown function should be executed.
self.assertTrue(ev.wait(1))
executor.close()
def _subtest_context(
self, subtest: phase_collections.Subtest
) -> Iterator[test_record.SubtestRecord]:
"""Enter a subtest context.
This context tracks the subname and sets up the subtest record to track the
timing.
Args:
subtest: The subtest running during the context.
Yields:
The subtest record for updating the outcome.
"""
self.logger.debug('%s: Starting subtest.', subtest.name)
subtest_rec = test_record.SubtestRecord(
name=subtest.name,
start_time_millis=util.time_millis(),
outcome=test_record.SubtestOutcome.PASS)
yield subtest_rec
subtest_rec.end_time_millis = util.time_millis()
self.test_state.test_record.add_subtest_record(subtest_rec)
def _finalize(self, test_outcome):
aborting = test_outcome == test_record.Outcome.ABORTED
assert not self.is_finalized or aborting, (
'Test already completed with status %s!' % self._status.name)
# Sanity check to make sure we have a DUT ID by the end of the test.
if not self.test_record.dut_id:
print('')
self.logger.warning(
"WARNING: no DUT ID assigned at test finalization. "
"This record will be assigned DUT_ID = \"UNKNOWN\"")
print('')
self.test_record.dut_id = "UNKNOWN"
self.test_record.outcome = test_outcome
# If we've reached here without 'starting' the test, then we 'start' it just
# so we can properly 'end' it.
if self.test_record.start_time_millis == 0:
self.test_record.start_time_millis = util.time_millis()
# The test is done at this point, no further updates to test_record.
self.logger.handlers = []
self.test_record.end_time_millis = util.time_millis()
self._status = self.Status.COMPLETED
self.notify_update()
def test_cancel_start(self):
@openhtf.PhaseOptions()
def cancel_phase(test):
test.dut_id = 'DUT ID'
# We have 'executor' because we're inside the test method's scope.
# We have to run it in a thread to avoid getting a nasty series of
# confusing errors:
# If we were to stop it in this phase, it eventually causes the phase
# to be killed using KillableThread, which raises ThreadTerminationError
# inside here, which really raises it inside wherever executor.stop() is.
# That leads to the stopping of the executor to get stopped itself at a
# random point in time. To make this deterministic, we keep the phase
# alive as long as the executor is running, which really just means that
# the wait() call gets the error raised in it.
inner_ev = threading.Event()
def stop_executor():
executor.stop()
inner_ev.set()
threading.Thread(target=stop_executor).start()
inner_ev.wait(1)
ev = threading.Event()
test = openhtf.Test()
test.configure(
teardown_function=lambda: ev.set(), # pylint: disable=unnecessary-lambda
default_dut_id='dut',
)
# Cancel during test start phase.
executor = test_executor.TestExecutor(test.descriptor, 'uid',
cancel_phase, test._test_options)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, cancel_phase.name)
# The test will end at the same time it starts because the test never
# actually started, we canceled it inside of test_start, resulting in a
# short vacuous start. Start and end times should be no more than a
# millisecond or two apart in that case.
self.assertLess(record.end_time_millis - record.start_time_millis, 2)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should not be executed.
self.assertFalse(ev.wait(3))
def finalize(self, test_outcome=None):
"""Mark the state as finished.
This method is called with no arguments on normal test completion, or
with an argument if the test stopped under some other condition, where
the test_outcome argument specifies what the Test's outcome was.
When a Test completes normally, the outcome will be either PASS or FAIL,
depending on measurements' PASS/FAIL status. Any UNSET measurements will
cause the Test to FAIL unless conf.allow_unset_measurements is set True.
Args:
test_outcome: If specified, use this as the Test outcome.
"""
assert not self.is_finalized, 'Test already completed!'
# Sanity check to make sure we have a DUT ID by the end of the test.
if not self.test_record.dut_id:
raise BlankDutIdError(
'Blank or missing DUT ID, HTF requires a non-blank ID.')
if test_outcome:
# Override measurement-based PASS/FAIL with a specific test outcome.
self.test_record.outcome = test_outcome
else:
allowed_outcomes = {measurements.Outcome.PASS}
if conf.allow_unset_measurements:
allowed_outcomes.add(measurements.Outcome.UNSET)
if any(meas.outcome not in allowed_outcomes
for phase in self.test_record.phases
for meas in phase.measurements.itervalues()):
self.test_record.outcome = test_record.Outcome.FAIL
else:
self.test_record.outcome = test_record.Outcome.PASS
# A message has already been logged if we were called with test_outcome
# set, but if we're finishing normally, log it here.
self.logger.debug(
'Finishing test execution normally with outcome %s.',
self.test_record.outcome.name)
# The test is done at this point, no further updates to test_record.
self.logger.handlers = []
self.test_record.end_time_millis = util.time_millis()
self._status = self.Status.COMPLETED
self.notify_update()
def finalize(self, test_outcome=None):
"""Mark the state as finished.
This method is called with no arguments on normal test completion, or
with an argument if the test stopped under some other condition, where
the test_outcome argument specifies what the Test's outcome was.
When a Test completes normally, the outcome will be either PASS or FAIL,
depending on measurements' PASS/FAIL status. Any UNSET measurements will
cause the Test to FAIL unless conf.allow_unset_measurements is set True.
Args:
test_outcome: If specified, use this as the Test outcome.
"""
assert not self.is_finalized, 'Test already completed!'
# Sanity check to make sure we have a DUT ID by the end of the test.
if not self.test_record.dut_id:
raise BlankDutIdError(
'Blank or missing DUT ID, HTF requires a non-blank ID.')
if test_outcome:
# Override measurement-based PASS/FAIL with a specific test outcome.
self.test_record.outcome = test_outcome
else:
allowed_outcomes = {measurements.Outcome.PASS}
if conf.allow_unset_measurements:
allowed_outcomes.add(measurements.Outcome.UNSET)
if any(meas.outcome not in allowed_outcomes
for phase in self.test_record.phases
for meas in phase.measurements.itervalues()):
self.test_record.outcome = test_record.Outcome.FAIL
else:
self.test_record.outcome = test_record.Outcome.PASS
# A message has already been logged if we were called with test_outcome
# set, but if we're finishing normally, log it here.
self.logger.debug('Finishing test execution normally with outcome %s.',
self.test_record.outcome.name)
# The test is done at this point, no further updates to test_record.
self.logger.handlers = []
self.test_record.end_time_millis = util.time_millis()
self._status = self.Status.COMPLETED
self.notify_update()
def __init__(self, *phases, **metadata):
# Some sanity checks on special metadata keys we automatically fill in.
if 'config' in metadata:
raise KeyError(
'Invalid metadata key "config", it will be automatically populated.')
self.created_time_millis = util.time_millis()
self.last_run_time_millis = None
self._test_options = TestOptions()
self._lock = threading.Lock()
self._executor = None
self._test_desc = TestDescriptor(
self.uid, phases, test_record.CodeInfo.uncaptured(), metadata)
if conf.capture_source:
# First, we copy the phases with the real CodeInfo for them.
phases = [
mutablerecords.CopyRecord(
phase, code_info=test_record.CodeInfo.for_function(phase.func))
for phase in self._test_desc.phases]
# Then we replace the TestDescriptor with one that stores the test
# module's CodeInfo as well as our newly copied phases.
code_info = test_record.CodeInfo.for_module_from_stack(levels_up=2)
self._test_desc = self._test_desc._replace(
code_info=code_info, phases=phases)
# Make sure configure() gets called at least once before Execute(). The
# user might call configure() again to override options, but we don't want
# to force them to if they want to use defaults. For default values, see
# the class definition of TestOptions.
if 'test_name' in metadata:
# Allow legacy metadata key for specifying test name.
self.configure(name=metadata['test_name'])
else:
self.configure()
self.TEST_INSTANCES[self.uid] = self
# This is a noop if the server is already running, otherwise start it now
# that we have at least one Test instance.
station_api.start_server()
def test_cancel_start(self):
@openhtf.PhaseOptions()
def cancel_phase(test):
test.dut_id = 'DUT ID'
# We have 'executor' because we're inside the test method's scope.
# We have to run it in a thread to avoid getting a nasty series of
# confusing errors:
_abort_executor_in_thread(executor.abort)
ev = threading.Event()
group = phase_group.PhaseGroup(
teardown=[lambda: ev.set()], # pylint: disable=unnecessary-lambda
)
test = openhtf.Test(group)
test.configure(
default_dut_id='dut',
)
# Cancel during test start phase.
executor = test_executor.TestExecutor(
test.descriptor,
'uid',
cancel_phase,
test._test_options
)
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, cancel_phase.name)
# The test will end at the same time it starts because the test never
# actually started, we canceled it inside of test_start, resulting in a
# short vacuous start. Start and end times should be no more than a
# millisecond or two apart in that case.
self.assertLess(record.end_time_millis - record.start_time_millis, 2)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should not be executed.
self.assertFalse(ev.wait(3))
def mark_operator_attendance_end(self):
if not self._track_operator_time:
return
if self._start_time_millis is None:
raise OperatorAttendanceViolation(
"Attempt ot mark operator attendance end without marking the start."
)
self._response_time_millis = util.time_millis()
self._elapsed_seconds = (self._response_time_millis -
self._start_time_millis) / float(1000)
self._total_elapsed_seconds += self._elapsed_seconds
self._attendance_log.append({
'start_time_millis': self._start_time_millis,
'elapsed_seconds': self._elapsed_seconds
})
_LOG.debug(
"Operator was required for %.1f seconds; %.1f minutes this test so far."
% (self._elapsed_seconds, self._total_elapsed_seconds / 60.0))
self._start_time_millis = None # we use this to tag that we've completed an operator attendance cycle.
def test_cancel_start(self):
@openhtf.PhaseOptions()
def cancel_phase(test):
test.dut_id = 'DUT ID'
# We have 'executor' because we're inside the test method's scope.
# We have to run it in a thread to avoid getting a nasty series of
# confusing errors:
# If we were to stop it in this phase, it eventually causes the phase
# to be killed using KillableThread, which raises ThreadTerminationError
# inside here, which really raises it inside wherever executor.stop() is.
# That leads to the stopping of the executor to get stopped itself at a
# random point in time. To make this deterministic, we keep the phase
# alive as long as the executor is running, which really just means that
# the wait() call gets the error raised in it.
inner_ev = threading.Event()
def stop_executor():
executor.stop()
inner_ev.set()
threading.Thread(target=stop_executor).start()
inner_ev.wait(1)
ev = threading.Event()
test = openhtf.Test()
# Cancel during test start phase.
executor = core.TestExecutor(test.descriptor, 'uid', cancel_phase, 'dut',
teardown_function=lambda: ev.set()) # pylint: disable=unnecessary-lambda
executor.start()
executor.wait()
record = executor.test_state.test_record
self.assertEqual(record.phases[0].name, cancel_phase.name)
# The test will end at the same time it starts because the test never
# actually started, we canceled it inside of test_start, resulting in a
# short vacuous start. Start and end times should be no more than a
# millisecond or two apart in that case.
self.assertLess(record.end_time_millis - record.start_time_millis, 2)
self.assertLessEqual(record.end_time_millis, util.time_millis())
# Teardown function should not be executed.
self.assertFalse(ev.wait(3))
def partial_upload_callback(test_record_obj: test_record.TestRecord):
if not test_record_obj.end_time_millis:
# We cannot mutate the test_record_obj, so we copy it to add a
# fake end_time_millis which is needed for MfgEvent construction.
try:
tmp_test_record = copy.deepcopy(test_record_obj)
except TypeError:
# This happens when test has errored but the partial_uploader got a
# hold of the test record before it is finalized. We force an errored
# test to be processed with zero deepcopy thus only after
# end_time_mills is set in the test record.
print('Skipping this upload cycle, waiting for test to be finalized')
return {}
tmp_test_record.end_time_millis = util.time_millis()
# Also fake a PASS outcome for now.
tmp_test_record.outcome = test_record.Outcome.PASS
proto = self._convert(tmp_test_record)
proto.test_run_type = mfg_event_pb2.TEST_RUN_PARTIAL
else:
proto = self._convert(test_record_obj)
proto.test_run_type = mfg_event_pb2.TEST_RUN_COMPLETE
# Replaces the attachment payloads already uploaded with their blob_refs.
if (self._cached_partial_proto and
self._cached_partial_proto.start_time_ms == proto.start_time_ms):
# Reads the attachments in the _cached_partial_proto and merge them into
# the proto.
self._update_attachments_from_cache(proto)
# Avoids timing issue whereby last complete upload performed twice.
# This is only for projects that use a partial uploader to mfg-inspector.
if not self._partial_proto_upload_complete:
self.upload_result = send_mfg_inspector_data(
proto, self.credentials, self.destination_url, payload_type)
# Reads the upload_result (a lite_test_run proto) and update the
# attachments blob_refs.
self._update_attachments_from_reply(proto)
if proto.test_run_type == mfg_event_pb2.TEST_RUN_COMPLETE:
self._partial_proto_upload_complete = True
return self.upload_result
def execute(self, test_start=None):
"""Starts the framework and executes the given test.
Args:
test_start: Either a trigger phase for starting the test, or a function
that returns a DUT ID. If neither is provided, defaults to not
setting the DUT ID.
Returns:
Boolean indicating whether the test failed (False) or passed (True).
Raises:
InvalidTestStateError: if this test is already being executed.
"""
# Lock this section so we don't .stop() the executor between instantiating
# it and .Start()'ing it, doing so does weird things to the executor state.
with self._lock:
# Sanity check to make sure someone isn't doing something weird like
# trying to Execute() the same test twice in two separate threads. We
# hold the lock between here and Start()'ing the executor to guarantee
# that only one thread is successfully executing the test.
if self._executor:
raise InvalidTestStateError('Test already running',
self._executor)
# Snapshot some things we care about and store them.
self._test_desc.metadata['test_name'] = self._test_options.name
self._test_desc.metadata['config'] = conf._asdict()
self.last_run_time_millis = util.time_millis()
if isinstance(test_start, LambdaType):
@phase_descriptor.PhaseOptions()
def trigger_phase(test):
test.test_record.dut_id = test_start()
trigger = trigger_phase
else:
trigger = test_start
if conf.capture_source:
trigger.code_info = test_record.CodeInfo.for_function(
trigger.func)
self._executor = test_executor.TestExecutor(
self._test_desc, self.make_uid(), trigger,
self._test_options.default_dut_id,
self._test_options.teardown_function,
self._test_options.failure_exceptions)
_LOG.info('Executing test: %s', self.descriptor.code_info.name)
self.TEST_INSTANCES[self.uid] = self
self._executor.start()
try:
self._executor.wait()
finally:
try:
final_state = self._executor.finalize()
_LOG.debug('Test completed for %s, outputting now.',
final_state.test_record.metadata['test_name'])
for output_cb in self._test_options.output_callbacks:
try:
output_cb(final_state.test_record)
except Exception: # pylint: disable=broad-except
_LOG.error(
'Output callback %s raised; continuing anyway',
output_cb)
# Make sure the final outcome of the test is printed last and in a
# noticeable color so it doesn't get scrolled off the screen or missed.
if final_state.test_record.outcome == test_record.Outcome.ERROR:
for detail in final_state.test_record.outcome_details:
console_output.error_print(detail.description)
else:
colors = collections.defaultdict(
lambda: 'colorama.Style.BRIGHT')
colors[test_record.Outcome.PASS] = ''.join(
(colorama.Style.BRIGHT, colorama.Fore.GREEN))
colors[test_record.Outcome.FAIL] = ''.join(
(colorama.Style.BRIGHT, colorama.Fore.RED))
msg_template = "test: {name} outcome: {color}{outcome}{rst}"
console_output.banner_print(
msg_template.format(
name=final_state.test_record.metadata['test_name'],
color=colors[final_state.test_record.outcome],
outcome=final_state.test_record.outcome.name,
rst=colorama.Style.RESET_ALL))
finally:
del self.TEST_INSTANCES[self.uid]
self._executor = None
return final_state.test_record.outcome == test_record.Outcome.PASS
class StationApi(object):
UID = '%s:%s' % (os.getpid(), util.time_millis())
def get_station_info(self):
"""Obtain dict required to make a StationInfo for this station.
See StationInfo namedtuple above for explanation of the returned fields."""
_LOG.debug('RPC:get_station_info() -> %s:%s', conf.station_id,
self.UID)
return {
'station_id': conf.station_id,
'station_uid': self.UID,
'station_api_bind_address': conf.station_api_bind_address,
'last_activity_time_millis': API_SERVER.last_activity_time_millis,
}
def list_tests(self):
"""List currently known test types.
A new 'test type' is created each time openhtf.Test is instantiated, and
lasts as long as there are any external references to it (ie, outside the
internal tracking structures within OpenHTF).
This means creating large numbers of openhtf.Test instances and keeping
references to them around can cause memory usage to grow rapidly and
station_api performance to degrade; don't do that.
Returns:
List of RemoteTest tuple values (as a dict). Only currently-executing
tests are returned.
"""
retval = [{
'test_uid':
test.uid,
'test_name':
test.get_option('name'),
'created_time_millis':
long(test.created_time_millis),
'last_run_time_millis':
test.last_run_time_millis and long(test.last_run_time_millis),
} for test in openhtf.Test.TEST_INSTANCES.values()
if test.uid is not None]
_LOG.debug('RPC:list_tests() -> %s results', len(retval))
return retval
def get_phase_descriptors(self, test_uid):
"""Get phase descriptor fields for the given test UID.
Returns:
List of dicts of RemotePhaseDescriptor fields.
Raises:
UnrecognizedTestUidError: The test_uid is not recognized.
"""
phases = openhtf.Test.from_uid(test_uid).descriptor.phases
return [
dict(id=id(phase), **data.convert_to_base_types(phase))
for phase in phases
]
@staticmethod
def _serialize_state_dict(state_dict, remote_record=None):
if (remote_record and remote_record['start_time_millis']
== state_dict['test_record'].start_time_millis):
# Make a copy and delete phases/logs that are already known remotely.
state_dict['test_record'] = mutablerecords.CopyRecord(
state_dict['test_record'])
del state_dict['test_record'].phases[:remote_record['phases']]
del state_dict[
'test_record'].log_records[:remote_record['log_records']]
return {
'status':
state_dict['status'].name,
'test_record':
data.convert_to_base_types(state_dict['test_record']),
'plugs':
state_dict['plugs'],
'running_phase_state':
data.convert_to_base_types(state_dict['running_phase_state'])
}
def get_test_state(self, test_uid, remote_record):
"""Get test state for the given Test UID.
If a remote TestRecord is cached, information from it will be used to
limit the phases/log records returned to only new ones.
Args:
test_uid: Test for which to obtain TestState info.
remote_record: TestRecord we have cached on the remote side (if any),
with phases and log_records swapped out for their respective lengths.
Returns:
Serialized RemoteState, as a dict, or None if the remote test is not
currently .Execute()'ing.
"""
_LOG.debug('RPC:get_test_state(%s)', test_uid)
state = openhtf.Test.from_uid(test_uid).state
if state:
return self._serialize_state_dict(state._asdict(), remote_record)
def wait_for_plug_update(self, test_uid, plug_name, current_state,
timeout_s):
"""Long-poll RPC that blocks until the requested plug has an update.
Args:
test_uid: Test UID from which to obtain the plug on which to wait.
plug_name: The plug type (string name, like 'my.module.MyPlug') on which
to wait for an update.
current_state: Current remotely known plug state. This is what the
plug's state is compared against to detect an update.
timeout_s: Number of seconds to wait for an update before giving up.
Returns:
New _asdict() state of plug, or None in the case of a timeout.
Raises:
UnrecognizedTestUidError: The test_uid is not recognized.
TestNotRunningError: The requested test is not running.
openhtf.plugs.InvalidPlugError: The plug can't be waited on either because
it's not in use or it's not frontend-aware.
"""
_LOG.debug('RPC:wait_for_plug_update(timeout_s=%s)', timeout_s)
test_state = openhtf.Test.from_uid(test_uid).state
if test_state is None:
raise TestNotRunningError('Test %s is not running.' % test_uid)
return test_state.plug_manager.wait_for_plug_update(
plug_name, current_state, timeout_s)
@staticmethod
def _summary_for_state_dict(state_dict):
"""Return a dict for state with counts swapped in for phase/log records."""
state_dict_summary = {
k: v
for k, v in state_dict.items() if k != 'plugs'
}
state_dict_summary['test_record'] = data.convert_to_base_types(
state_dict_summary['test_record'])
state_dict_summary['test_record']['phases'] = len(
state_dict_summary['test_record']['phases'])
state_dict_summary['test_record']['log_records'] = len(
state_dict_summary['test_record']['log_records'])
state_dict_summary['running_phase_state'] = data.convert_to_base_types(
state_dict_summary['running_phase_state'], tuple_type=list)
return state_dict_summary
def wait_for_update(self, test_uid, remote_state_dict, timeout_s):
"""Long-poll RPC that blocks until the test state has an update.
Events that trigger an update:
Test Status Changes (ie, transition from WAITING_FOR_START to RUNNING).
Phase Start/Finish.
Measurement is set/updated.
Attachment is attached.
Log line is produced (via TestApi.logger).
Note that plug state changes do NOT trigger an update here, use
wait_for_plug_update() to get plug state change events.
Args:
test_uid: Test UID for which to wait on an update.
remote_state_dict: Current RemoteState that we have for the test, as a
dict, with phases and log_records swapped out for counts instead of
the actual records themselves.
timeout_s: Number of seconds to wait for an update before giving up.
Returns:
Updated RemoteState, as per get_test_state, except args are taken from
remote_state_dict rather than passed in individually (because we care about
more stuff here). In the event of a timeout, returns None.
Raises:
UnrecognizedTestUidError: If the test_uid is not recognized.
UpdateTimeout: If there was no new information before the timeout expired,
as differentiated from a None return value, which indicates the
requested test is not being Execute()'ed on the remote side (but we
previously thought it was).
"""
_LOG.debug('RPC:wait_for_update(timeout_s=%s)', timeout_s)
state = openhtf.Test.from_uid(test_uid).state
# Handle the case in which the test is not running.
if state is None:
if remote_state_dict:
# Remote end expected the test to be running but it's not. This is all
# the information we need to return immediately.
return
# Remote end expected that the test was not running, so wait for it to
# start.
state = timeouts.loop_until_timeout_or_not_none(
timeout_s,
lambda: openhtf.Test.from_uid(test_uid).state,
sleep_s=.1)
if state is None:
raise UpdateTimeout(
"No test started Execute()'ing before timeout", timeout_s)
_LOG.debug(
'RPC:wait_for_update() -> short-circuited wait (local was blank)'
)
return self._serialize_state_dict(state._asdict())
state_dict, update_event = state.asdict_with_event()
state_dict_summary = self._summary_for_state_dict(state_dict)
# Deserialize the RemoteState fields for comparison.
remote_state_dict = remote_state_dict and {
'status': test_state.TestState.Status[remote_state_dict['status']],
'test_record': remote_state_dict['test_record'],
'running_phase_state': remote_state_dict['running_phase_state'],
}
if state_dict_summary != remote_state_dict:
if not remote_state_dict:
_LOG.debug(
'RPC:wait_for_update() -> short-circuited wait (remote was blank)'
)
elif _LOG.isEnabledFor(logging.DEBUG):
log_msg = [
'RPC:wait_for_update() -> short-circuited wait, diff:'
]
log_msg.extend(
data.pprint_diff(remote_state_dict, state_dict_summary,
'remote_state', 'local_state'))
_LOG.debug('\n'.join(log_msg))
# We already have new info, serialize the new state and send it,
# skipping any phases/logs that we already know about remotely.
return self._serialize_state_dict(
state_dict, remote_state_dict
and remote_state_dict['test_record'])
# If we get here, then the remote side is already up-to-date, so we wait
# for there to be new information available. We rely on the TestState
# object itself to notify us when this is the case.
if not update_event.wait(timeout_s):
_LOG.debug('RPC:wait_for_update() -> timeout after %s seconds',
timeout_s)
raise UpdateTimeout('No new information before timeout.',
timeout_s)
_LOG.debug('RPC:wait_for_update() -> change after wait')
# Grab a fresh copy of the state and return the new info.
state = openhtf.Test.from_uid(test_uid).state
return state and self._serialize_state_dict(
state._asdict(), remote_state_dict['test_record'])
def get_history_after(self, test_uid, start_time_millis):
"""Get a list of TestRecords for test_uid from the History."""
_LOG.debug('RPC:get_history_after(%s)', start_time_millis)
# TODO(madsci): We really should pull attachments out of band here.
return [
data.convert_to_base_types(test_record)
for test_record in history.for_test_uid(
test_uid, start_after_millis=start_time_millis)
]
def get_frontend_aware_plug_names(self, test_uid):
"""Returns the names of frontend-aware plugs."""
_LOG.debug('RPC:get_frontend_aware_plug_names()')
state = openhtf.Test.from_uid(test_uid).state
if state is None:
return
return state.plug_manager.get_frontend_aware_plug_names()
def finalize_phase(self, options): self.end_time_millis = util.time_millis() self.options = options
def record_start_time(self): """Record the phase start time and return it.""" self.start_time_millis = util.time_millis() return self.start_time_millis
def execute(self, test_start=None):
"""Starts the framework and executes the given test.
Args:
test_start: Either a trigger phase for starting the test, or a function
that returns a DUT ID. If neither is provided, defaults to not
setting the DUT ID.
Returns:
Boolean indicating whether the test failed (False) or passed (True).
Raises:
InvalidTestStateError: if this test is already being executed.
"""
# Lock this section so we don't .stop() the executor between instantiating
# it and .Start()'ing it, doing so does weird things to the executor state.
with self._lock:
# Sanity check to make sure someone isn't doing something weird like
# trying to Execute() the same test twice in two separate threads. We
# hold the lock between here and Start()'ing the executor to guarantee
# that only one thread is successfully executing the test.
if self._executor:
raise InvalidTestStateError('Test already running', self._executor)
# Snapshot some things we care about and store them.
self._test_desc.metadata['test_name'] = self._test_options.name
self._test_desc.metadata['config'] = conf._asdict()
self.last_run_time_millis = util.time_millis()
if isinstance(test_start, LambdaType):
@phase_descriptor.PhaseOptions()
def trigger_phase(test):
test.test_record.dut_id = test_start()
trigger = trigger_phase
else:
trigger = test_start
if conf.capture_source:
trigger.code_info = test_record.CodeInfo.for_function(trigger.func)
test_desc = self._get_running_test_descriptor()
self._executor = test_executor.TestExecutor(
test_desc, self.make_uid(), trigger, self._test_options)
_LOG.info('Executing test: %s', self.descriptor.code_info.name)
self.TEST_INSTANCES[self.uid] = self
self._executor.start()
try:
self._executor.wait()
except KeyboardInterrupt:
# The SIGINT handler only raises the KeyboardInterrupt once, so only retry
# that once.
self._executor.wait()
raise
finally:
try:
final_state = self._executor.finalize()
_LOG.debug('Test completed for %s, outputting now.',
final_state.test_record.metadata['test_name'])
for output_cb in self._test_options.output_callbacks:
try:
output_cb(final_state.test_record)
except Exception: # pylint: disable=broad-except
_LOG.exception(
'Output callback %s raised; continuing anyway', output_cb)
# Make sure the final outcome of the test is printed last and in a
# noticeable color so it doesn't get scrolled off the screen or missed.
if final_state.test_record.outcome == test_record.Outcome.ERROR:
for detail in final_state.test_record.outcome_details:
console_output.error_print(detail.description)
else:
colors = collections.defaultdict(lambda: colorama.Style.BRIGHT)
colors[test_record.Outcome.PASS] = ''.join((colorama.Style.BRIGHT,
colorama.Fore.GREEN))
colors[test_record.Outcome.FAIL] = ''.join((colorama.Style.BRIGHT,
colorama.Fore.RED))
msg_template = 'test: {name} outcome: {color}{outcome}{rst}'
console_output.banner_print(msg_template.format(
name=final_state.test_record.metadata['test_name'],
color=colors[final_state.test_record.outcome],
outcome=final_state.test_record.outcome.name,
rst=colorama.Style.RESET_ALL))
finally:
del self.TEST_INSTANCES[self.uid]
self._executor = None
return final_state.test_record.outcome == test_record.Outcome.PASS
def mark_test_started(self):
"""Set the TestRecord's start_time_millis field."""
# Blow up instead of blowing away a previously set start_time_millis.
assert self.test_record.start_time_millis is 0
self.test_record.start_time_millis = util.time_millis()
self.notify_update()
def execute(self,
test_start: Optional[phase_descriptor.PhaseT] = None,
profile_filename: Optional[Text] = None) -> bool:
"""Starts the framework and executes the given test.
Args:
test_start: Either a trigger phase for starting the test, or a function
that returns a DUT ID. If neither is provided, defaults to not setting
the DUT ID.
profile_filename: Name of file to put profiling stats into. This also
enables profiling data collection.
Returns:
Boolean indicating whether the test failed (False) or passed (True).
Raises:
InvalidTestStateError: if this test is already being executed.
"""
phase_descriptor.check_for_duplicate_results(
self._test_desc.phase_sequence.all_phases(),
self._test_options.diagnosers)
phase_collections.check_for_duplicate_subtest_names(
self._test_desc.phase_sequence)
# Lock this section so we don't .stop() the executor between instantiating
# it and .Start()'ing it, doing so does weird things to the executor state.
with self._lock:
# Sanity check to make sure someone isn't doing something weird like
# trying to Execute() the same test twice in two separate threads. We
# hold the lock between here and Start()'ing the executor to guarantee
# that only one thread is successfully executing the test.
if self._executor:
raise InvalidTestStateError('Test already running',
self._executor)
# Snapshot some things we care about and store them.
self._test_desc.metadata['test_name'] = self._test_options.name
self._test_desc.metadata['config'] = CONF._asdict()
self.last_run_time_millis = util.time_millis()
if isinstance(test_start, types.LambdaType):
@phase_descriptor.PhaseOptions()
def trigger_phase(test):
test.test_record.dut_id = typing.cast(
types.LambdaType, test_start)()
trigger = trigger_phase
else:
trigger = test_start
if CONF.capture_source:
trigger.code_info = htf_test_record.CodeInfo.for_function(
trigger.func)
self._executor = test_executor.TestExecutor(
self._test_desc,
self.make_uid(),
trigger,
self._test_options,
run_with_profiling=profile_filename is not None)
_LOG.info('Executing test: %s', self.descriptor.code_info.name)
self.TEST_INSTANCES[self.uid] = self
self._executor.start()
try:
self._executor.wait()
except KeyboardInterrupt:
# The SIGINT handler only raises the KeyboardInterrupt once, so only retry
# that once.
self._executor.wait()
raise
finally:
try:
final_state = self._executor.finalize()
_LOG.debug('Test completed for %s, outputting now.',
final_state.test_record.metadata['test_name'])
test_executor.combine_profile_stats(
self._executor.phase_profile_stats, profile_filename)
for output_cb in self._test_options.output_callbacks:
try:
output_cb(final_state.test_record)
except Exception: # pylint: disable=broad-except
stacktrace = traceback.format_exc()
_LOG.error(
'Output callback %s raised:\n%s\nContinuing anyway...',
output_cb, stacktrace)
# Make sure the final outcome of the test is printed last and in a
# noticeable color so it doesn't get scrolled off the screen or missed.
if final_state.test_record.outcome == htf_test_record.Outcome.ERROR:
for detail in final_state.test_record.outcome_details:
console_output.error_print(detail.description)
else:
colors = collections.defaultdict(
lambda: colorama.Style.BRIGHT)
colors[htf_test_record.Outcome.PASS] = ''.join(
(colorama.Style.BRIGHT, colorama.Fore.GREEN)) # pytype: disable=wrong-arg-types
colors[htf_test_record.Outcome.FAIL] = ''.join(
(colorama.Style.BRIGHT, colorama.Fore.RED)) # pytype: disable=wrong-arg-types
msg_template = (
'test: {name} outcome: {color}{outcome}{marginal}{rst}'
)
console_output.banner_print(
msg_template.format(
name=final_state.test_record.metadata['test_name'],
color=(colorama.Fore.YELLOW
if final_state.test_record.marginal else
colors[final_state.test_record.outcome]),
outcome=final_state.test_record.outcome.name,
marginal=(' (MARGINAL)'
if final_state.test_record.marginal else
''),
rst=colorama.Style.RESET_ALL))
finally:
del self.TEST_INSTANCES[self.uid]
self._executor.close()
self._executor = None
return final_state.test_record.outcome == htf_test_record.Outcome.PASS
def execute(self, test_start=None):
"""Starts the framework and executes the given test.
Args:
test_start: Either a trigger phase for starting the test, or a function
that returns a DUT ID. If neither is provided, defaults to not
setting the DUT ID.
"""
# Lock this section so we don't .stop() the executor between instantiating
# it and .Start()'ing it, doing so does weird things to the executor state.
with self._lock:
# Sanity check to make sure someone isn't doing something weird like
# trying to Execute() the same test twice in two separate threads. We
# hold the lock between here and Start()'ing the executor to guarantee
# that only one thread is successfully executing the test.
if self._executor:
raise InvalidTestStateError('Test already running',
self._executor)
# Snapshot some things we care about and store them.
self._test_desc.metadata['test_name'] = self._test_options.name
self._test_desc.metadata['config'] = conf._asdict()
self.last_run_time_millis = util.time_millis()
if isinstance(test_start, LambdaType):
@TestPhase()
def trigger_phase(test):
test.test_record.dut_id = test_start()
trigger = trigger_phase
else:
trigger = test_start
if conf.capture_source:
trigger.code_info = test_record.CodeInfo.for_function(
trigger.func)
self._executor = core.TestExecutor(
self._test_desc, self.make_uid(), trigger,
self._test_options.teardown_function)
_LOG.info('Executing test: %s', self.descriptor.code_info.name)
self.TEST_INSTANCES[self.uid] = self
self._executor.start()
try:
self._executor.wait()
finally:
try:
final_state = self._executor.finalize()
_LOG.debug(
'Test completed for %s, saving to history and outputting.',
final_state.test_record.metadata['test_name'])
for output_cb in (
self._test_options.output_callbacks +
[functools.partial(history.append_record, self.uid)]):
try:
output_cb(final_state.test_record)
except Exception: # pylint: disable=broad-except
_LOG.exception(
'Output callback %s raised; continuing anyway',
output_cb)
finally:
del self.TEST_INSTANCES[self.uid]
self._executor = None
return final_state.test_record.outcome == test_record.Outcome.PASS
def mark_test_started(self): """Set the TestRecord's start_time_millis field.""" # Blow up instead of blowing away a previously set start_time_millis. assert self.test_record.start_time_millis is None self.test_record.start_time_millis = util.time_millis() self.notify_update()
def record_start_time(self) -> int:
"""Record the phase start time and return it."""
self.start_time_millis = util.time_millis()
return self.start_time_millis
def finalize_phase(self, options: 'phase_descriptor.PhaseOptions') -> None:
self.end_time_millis = util.time_millis()
self.options = options
