def verify(self, context):
"""Attempt to make an observation and verify it.
This call will repeatedly attempt to observe new data and verify it
until either the verification passes, or it times out base on
the retryable_for_secs specified in the constructor.
Args:
context: Runtime citest execution context may contain operation status
and other testing parameters used by downstream verifiers.
Returns:
ContractClauseVerifyResult with details.
"""
JournalLogger.begin_context(
'Verifying ContractClause: {0}'.format(self.__title))
context_relation = 'ERROR'
try:
JournalLogger.delegate("store", self, _title='Clause Specification')
result = self.__do_verify(context)
context_relation = 'VALID' if result else 'INVALID'
finally:
JournalLogger.end_context(relation=context_relation)
return result
def __do_verify(self, context):
"""Helper function that implements the clause verification policy.
We will periodically attempt to verify the clause until we succeed
or give up trying. Each individual iteration attempt is performed
by the verify_once method.
Args:
context: Runtime citest execution context.
Returns:
VerifyClauseResult specifying the final outcome.
"""
# self.logger.debug('Verifying Contract: %s', self.__title)
start_time = time.time()
end_time = start_time + self.__retryable_for_secs
while True:
clause_result = self.verify_once(context)
if clause_result:
break
now = time.time()
if end_time <= now:
if end_time > start_time:
self.logger.debug(
'Giving up verifying %s after %r of %r secs.',
self.__title, end_time - start_time, self.__retryable_for_secs)
break
secs_remaining = end_time - now
# This could be a bounded exponential backoff, but we probably
# want to have an idea of when it actually becomes available so keep low.
# But if we are going to wait a long time, then dont poll very frequently.
# The numbers here are arbitrary otherwise.
#
# 1/10 total time or 5 seconds if that is pretty long,
# but no less than 1 second unless there is less than 1 second left.
sleep = min(secs_remaining, min(5, max(1, self.__retryable_for_secs / 10)))
self.logger.debug(
'%s not yet satisfied with secs_remaining=%r. Retry in %r\n%s',
self.__title, secs_remaining, sleep, clause_result)
time.sleep(sleep)
summary = clause_result.enumerated_summary_message
ok_str = 'OK' if clause_result else 'FAILED'
JournalLogger.delegate(
"store", clause_result,
_title='Validation Analysis of "{0}"'.format(self.__title))
self.logger.debug('ContractClause %s: %s\n%s',
ok_str, self.__title, summary)
return clause_result
def _do_run_test_case_execute(self, test_case, context, **kwargs):
"""Run the specified test operation
See run_test_case for **kwargs.
"""
timeout_ok = kwargs.pop('timeout_ok', False)
max_retries = kwargs.pop('max_retries', 0)
retry_interval_secs = kwargs.pop('retry_interval_secs', 5)
poll_every_secs = kwargs.pop('poll_every_secs', 1)
max_wait_secs = kwargs.pop('max_wait_secs', None)
if kwargs:
raise TypeError('Unrecognized arguments {0}'.format(kwargs.keys()))
self.log_start_test(test_case.title)
if max_retries < 0:
raise ValueError(
'max_retries={max} cannot be negative'.format(max=max_retries))
if retry_interval_secs < 0:
raise ValueError(
'retry_interval_secs={secs} cannot be negative'.format(
secs=retry_interval_secs))
execution_trace = OperationContractExecutionTrace(test_case)
verify_results = None
final_status_ok = None
attempt_info = None
status = None
try:
JournalLogger.delegate(
"store",
test_case.operation,
_title='Operation "{0}" Specification'.format(
test_case.operation.title))
# We attempt the operation on the agent multiple times until the agent
# thinks that it succeeded. But we will only verify once the agent thinks
# it succeeded. We do not give multiple chances to satisfy the
# verification.
attempt_info = self.__do_operation(
context,
execution_trace,
1 + max_retries,
retry_interval_secs=retry_interval_secs,
poll_every_secs=poll_every_secs,
max_wait_secs=max_wait_secs)
context.set_internal(self.CONTEXT_KEY_ATTEMPT_INFO, attempt_info)
status = attempt_info.status
title = '%s summary' % status.__class__.__name__
JournalLogger.delegate(
"store_summary",
status,
_title=title,
relation=('VALID'
if status.finished_ok else 'ERROR' if status.error
else 'INVALID' if status.finished else None))
# We're always going to verify the contract, even if the request itself
# failed. We set the verification on the attempt here, but do not assert
# anything. We'll assert below outside this try/catch handler.
verify_results = test_case.contract.verify(context)
context.set_internal(self.CONTEXT_KEY_CONTRACT_VERIFY_RESULTS,
verify_results)
execution_trace.set_verify_results(verify_results)
final_status_ok = self.verify_final_status_ok(
status,
timeout_ok=timeout_ok,
final_attempt=attempt_info,
execution_trace=execution_trace)
context.set_internal(self.CONTEXT_KEY_FINAL_STATUS_OK,
final_status_ok)
except BaseException as ex:
execution_trace.set_exception(ex)
if attempt_info is None:
execution_trace.set_exception(ex,
traceback_module.format_exc())
elif not attempt_info.completed:
# Exception happened during the attempt as opposed to during our
# verification afterwards.
attempt_info.set_exception(ex, traceback_module.format_exc())
try:
self.logger.error('Test failed with exception: %s', ex)
self.logger.error('Last status was:\n%s', str(status))
self.logger.debug('Exception was at:\n%s',
traceback_module.format_exc())
except BaseException as unexpected:
self.logger.error(
'Unexpected error %s\nHandling original exception %s',
unexpected, ex)
self.logger.debug('Unexpected exception was at:\n%s',
traceback_module.format_exc())
raise
finally:
self.log_end_test(test_case.title)
self.report(execution_trace)
if not final_status_ok:
self.raise_final_status_not_ok(status, attempt_info)
if verify_results is not None:
self.assertVerifyResults(verify_results)
def run_test_case(self, test_case, context=None, **kwargs):
"""Run the specified test operation from start to finish.
Args:
test_case: [OperationContract] To test.
context: [ExecutionContext] The citest execution context to run in.
timeout_ok: [bool] Whether an AgentOperationStatus timeout implies
a test failure. If it is ok to timeout, then we'll still verify the
contracts, but skip the final status check if there is no final
status yet.
max_retries: [int] Number of independent retries permitted on
individual operations if the operation status fails. A value of 0
indicates that a test should only be given a single attempt.
retry_interval_secs: [int] The number of seconds to wait between retries.
full_trace: [bool] If true, then apply as much tracing as possible, else
use the default tracing. The intent here is to be able to crank up
the tracing when needed but not be overwhelmed by data when the
default tracing is typically sufficient.
poll_every_secs: [int] Number of seconds between wait polls. Default=1.
"""
if context is None:
context = ExecutionContext()
timeout_ok = kwargs.pop('timeout_ok', False)
max_retries = kwargs.pop('max_retries', 0)
retry_interval_secs = kwargs.pop('retry_interval_secs', 5)
poll_every_secs = kwargs.pop('poll_every_secs', 1)
full_trace = kwargs.pop('full_trace', False)
if kwargs:
raise TypeError('Unrecognized arguments {0}'.format(kwargs.keys()))
self.log_start_test(test_case.title)
if max_retries < 0:
raise ValueError(
'max_retries={max} cannot be negative'.format(max=max_retries))
if retry_interval_secs < 0:
raise ValueError(
'retry_interval_secs={secs} cannot be negative'.format(
secs=retry_interval_secs))
execution_trace = OperationContractExecutionTrace(test_case)
verify_results = None
final_status_ok = None
context_relation = None
attempt_info = None
status = None
try:
JournalLogger.begin_context('Test "{0}"'.format(test_case.title))
JournalLogger.delegate(
"store",
test_case.operation,
_title='Operation "{0}" Specification'.format(
test_case.operation.title))
max_tries = 1 + max_retries
# We attempt the operation on the agent multiple times until the agent
# thinks that it succeeded. But we will only verify once the agent thinks
# it succeeded. We do not give multiple chances to satisfy the
# verification.
for i in range(max_tries):
context.clear_key('OperationStatus')
context.clear_key('AttemptInfo')
attempt_info = execution_trace.new_attempt()
status = None
status = test_case.operation.execute(agent=self.testing_agent)
status.wait(poll_every_secs=poll_every_secs,
trace_every=full_trace)
summary = status.error or ('Operation status OK'
if status.finished_ok else
'Operation status Unknown')
# Write the status (and attempt_info) into the execution_context
# to make it available to contract verifiers. For example, to
# make specific details in the status (e.g. new resource names)
# available to downstream validators for their consideration.
context.set_internal('AttemptInfo', attempt_info)
context.set_internal('OperationStatus', status)
attempt_info.set_status(status, summary)
if test_case.status_extractor:
test_case.status_extractor(status, context)
if not status.exception_details:
execution_trace.set_operation_summary('Completed test.')
break
if max_tries - i > 1:
self.logger.warning(
'Got an exception: %s.\nTrying again in %r secs...',
status.exception_details, retry_interval_secs)
time.sleep(retry_interval_secs)
elif max_tries > 1:
execution_trace.set_operation_summary(
'Gave up retrying operation.')
self.logger.error('Giving up retrying test.')
# We're always going to verify the contract, even if the request itself
# failed. We set the verification on the attempt here, but do not assert
# anything. We'll assert below outside this try/catch handler.
verify_results = test_case.contract.verify(context)
execution_trace.set_verify_results(verify_results)
final_status_ok = self.verify_final_status_ok(
status,
timeout_ok=timeout_ok,
final_attempt=attempt_info,
execution_trace=execution_trace)
context_relation = ('VALID' if (final_status_ok and verify_results)
else 'INVALID')
except BaseException as ex:
context_relation = 'ERROR'
execution_trace.set_exception(ex)
if attempt_info is None:
execution_trace.set_exception(ex,
traceback_module.format_exc())
elif not attempt_info.completed:
# Exception happened during the attempt as opposed to during our
# verification afterwards.
attempt_info.set_exception(ex, traceback_module.format_exc())
try:
self.logger.error('Test failed with exception: %s', ex)
self.logger.error('Last status was:\n%s', str(status))
self.logger.debug('Exception was at:\n%s',
traceback_module.format_exc())
except BaseException as unexpected:
self.logger.error(
'Unexpected error %s\nHandling original exception %s',
unexpected, ex)
self.logger.debug('Unexpected exception was at:\n%s',
traceback_module.format_exc())
raise
finally:
try:
context.set_internal('ContractVerifyResults', verify_results)
self.log_end_test(test_case.title)
self.report(execution_trace)
if test_case.cleanup:
if status is None:
self.logger.info(
'Skipping operation cleanup because'
' operation could not be performed at all.')
else:
self.logger.info(
'Invoking injected operation cleanup.')
test_case.cleanup(context)
finally:
JournalLogger.end_context(relation=context_relation)
if not final_status_ok:
self.raise_final_status_not_ok(status, attempt_info)
if verify_results is not None:
self.assertVerifyResults(verify_results)
def run_test_case(self, test_case, context=None, **kwargs):
"""Run the specified test operation from start to finish.
Args:
test_case: [OperationContract] To test.
context: [ExecutionContext] The citest execution context to run in.
timeout_ok: [bool] Whether an AgentOperationStatus timeout implies
a test failure. If it is ok to timeout, then we'll still verify the
contracts, but skip the final status check if there is no final
status yet.
max_retries: [int] Number of independent retries permitted on
individual operations if the operation status fails. A value of 0
indicates that a test should only be given a single attempt.
retry_interval_secs: [int] The number of seconds to wait between retries.
poll_every_secs: [int] Number of seconds between wait polls. Default=1.
"""
if context is None:
context = ExecutionContext()
timeout_ok = kwargs.pop('timeout_ok', False)
max_retries = kwargs.pop('max_retries', 0)
retry_interval_secs = kwargs.pop('retry_interval_secs', 5)
poll_every_secs = kwargs.pop('poll_every_secs', 1)
full_trace = kwargs.pop('full_trace', False) # Deprecated
if kwargs:
raise TypeError('Unrecognized arguments {0}'.format(kwargs.keys()))
self.log_start_test(test_case.title)
if max_retries < 0:
raise ValueError(
'max_retries={max} cannot be negative'.format(max=max_retries))
if retry_interval_secs < 0:
raise ValueError(
'retry_interval_secs={secs} cannot be negative'.format(
secs=retry_interval_secs))
execution_trace = OperationContractExecutionTrace(test_case)
verify_results = None
final_status_ok = None
context_relation = None
attempt_info = None
status = None
try:
JournalLogger.begin_context('Test "{0}"'.format(test_case.title))
JournalLogger.delegate(
"store", test_case.operation,
_title='Operation "{0}" Specification'.format(
test_case.operation.title))
max_tries = 1 + max_retries
# We attempt the operation on the agent multiple times until the agent
# thinks that it succeeded. But we will only verify once the agent thinks
# it succeeded. We do not give multiple chances to satisfy the
# verification.
for i in range(max_tries):
context.clear_key('OperationStatus')
context.clear_key('AttemptInfo')
attempt_info = execution_trace.new_attempt()
status = None
status = test_case.operation.execute(agent=self.testing_agent)
status.wait(poll_every_secs=poll_every_secs)
summary = status.error or ('Operation status OK' if status.finished_ok
else 'Operation status Unknown')
# Write the status (and attempt_info) into the execution_context
# to make it available to contract verifiers. For example, to
# make specific details in the status (e.g. new resource names)
# available to downstream validators for their consideration.
context.set_internal('AttemptInfo', attempt_info)
context.set_internal('OperationStatus', status)
attempt_info.set_status(status, summary)
if test_case.status_extractor:
test_case.status_extractor(status, context)
if not status.exception_details:
execution_trace.set_operation_summary('Completed test.')
break
if max_tries - i > 1:
self.logger.warning(
'Got an exception: %s.\nTrying again in %r secs...',
status.exception_details, retry_interval_secs)
time.sleep(retry_interval_secs)
elif max_tries > 1:
execution_trace.set_operation_summary('Gave up retrying operation.')
self.logger.error('Giving up retrying test.')
# We're always going to verify the contract, even if the request itself
# failed. We set the verification on the attempt here, but do not assert
# anything. We'll assert below outside this try/catch handler.
verify_results = test_case.contract.verify(context)
execution_trace.set_verify_results(verify_results)
final_status_ok = self.verify_final_status_ok(
status, timeout_ok=timeout_ok,
final_attempt=attempt_info,
execution_trace=execution_trace)
context_relation = ('VALID' if (final_status_ok and verify_results)
else 'INVALID')
except BaseException as ex:
context_relation = 'ERROR'
execution_trace.set_exception(ex)
if attempt_info is None:
execution_trace.set_exception(ex, traceback_module.format_exc())
elif not attempt_info.completed:
# Exception happened during the attempt as opposed to during our
# verification afterwards.
attempt_info.set_exception(ex, traceback_module.format_exc())
try:
self.logger.error('Test failed with exception: %s', ex)
self.logger.error('Last status was:\n%s', str(status))
self.logger.debug('Exception was at:\n%s',
traceback_module.format_exc())
except BaseException as unexpected:
self.logger.error(
'Unexpected error %s\nHandling original exception %s',
unexpected, ex)
self.logger.debug('Unexpected exception was at:\n%s',
traceback_module.format_exc())
raise
finally:
try:
context.set_internal('ContractVerifyResults', verify_results)
self.log_end_test(test_case.title)
self.report(execution_trace)
if test_case.cleanup:
if status is None:
self.logger.info('Skipping operation cleanup because'
' operation could not be performed at all.')
else:
self.logger.info('Invoking injected operation cleanup.')
test_case.cleanup(context)
finally:
JournalLogger.end_context(relation=context_relation)
if not final_status_ok:
self.raise_final_status_not_ok(status, attempt_info)
if verify_results is not None:
self.assertVerifyResults(verify_results)
def _do_run_test_case_execute(self, test_case, context, **kwargs):
"""Run the specified test operation
See run_test_case for **kwargs.
"""
timeout_ok = kwargs.pop('timeout_ok', False)
max_retries = kwargs.pop('max_retries', 0)
retry_interval_secs = kwargs.pop('retry_interval_secs', 5)
poll_every_secs = kwargs.pop('poll_every_secs', 1)
max_wait_secs = kwargs.pop('max_wait_secs', None)
if kwargs:
raise TypeError('Unrecognized arguments {0}'.format(kwargs.keys()))
self.log_start_test(test_case.title)
if max_retries < 0:
raise ValueError(
'max_retries={max} cannot be negative'.format(max=max_retries))
if retry_interval_secs < 0:
raise ValueError(
'retry_interval_secs={secs} cannot be negative'.format(
secs=retry_interval_secs))
execution_trace = OperationContractExecutionTrace(test_case)
verify_results = None
final_status_ok = None
attempt_info = None
status = None
try:
JournalLogger.delegate(
"store", test_case.operation,
_title='Operation "{0}" Specification'.format(
test_case.operation.title))
# We attempt the operation on the agent multiple times until the agent
# thinks that it succeeded. But we will only verify once the agent thinks
# it succeeded. We do not give multiple chances to satisfy the
# verification.
attempt_info = self.__do_operation(
context, execution_trace, 1 + max_retries,
retry_interval_secs=retry_interval_secs,
poll_every_secs=poll_every_secs, max_wait_secs=max_wait_secs)
context.set_internal(self.CONTEXT_KEY_ATTEMPT_INFO, attempt_info)
status = attempt_info.status
title = '%s summary' % status.__class__.__name__
JournalLogger.delegate("store_summary", status, _title=title,
relation=('VALID' if status.finished_ok
else 'ERROR' if status.error
else 'INVALID' if status.finished
else None))
# We're always going to verify the contract, even if the request itself
# failed. We set the verification on the attempt here, but do not assert
# anything. We'll assert below outside this try/catch handler.
verify_results = test_case.contract.verify(context)
context.set_internal(
self.CONTEXT_KEY_CONTRACT_VERIFY_RESULTS, verify_results)
execution_trace.set_verify_results(verify_results)
final_status_ok = self.verify_final_status_ok(
status, timeout_ok=timeout_ok,
final_attempt=attempt_info,
execution_trace=execution_trace)
context.set_internal(self.CONTEXT_KEY_FINAL_STATUS_OK, final_status_ok)
except BaseException as ex:
execution_trace.set_exception(ex)
if attempt_info is None:
execution_trace.set_exception(ex, traceback_module.format_exc())
elif not attempt_info.completed:
# Exception happened during the attempt as opposed to during our
# verification afterwards.
attempt_info.set_exception(ex, traceback_module.format_exc())
try:
self.logger.error('Test failed with exception: %s', ex)
self.logger.error('Last status was:\n%s', str(status))
self.logger.debug('Exception was at:\n%s',
traceback_module.format_exc())
except BaseException as unexpected:
self.logger.error(
'Unexpected error %s\nHandling original exception %s',
unexpected, ex)
self.logger.debug('Unexpected exception was at:\n%s',
traceback_module.format_exc())
raise
finally:
self.log_end_test(test_case.title)
self.report(execution_trace)
if not final_status_ok:
self.raise_final_status_not_ok(status, attempt_info)
if verify_results is not None:
self.assertVerifyResults(verify_results)
