def handle_action_execution_resume(ac_ex_db):
if 'orchestra' not in ac_ex_db.context:
raise Exception(
'Unable to handle resume of action execution. The action execution '
'%s is not an orchestra workflow task.' % str(ac_ex_db.id))
wf_ex_id = ac_ex_db.context['orchestra']['workflow_execution_id']
task_ex_id = ac_ex_db.context['orchestra']['task_execution_id']
# Updat task execution to running.
resume_task_execution(task_ex_id)
# Update workflow execution to running.
resume_workflow_execution(wf_ex_id, task_ex_id)
# If action execution has a parent, cascade status change upstream and do not publish
# the status change because we do not want to trigger resume of other peer subworkflows.
if 'parent' in ac_ex_db.context:
parent_ac_ex_id = ac_ex_db.context['parent']['execution_id']
parent_ac_ex_db = ex_db_access.ActionExecution.get_by_id(
parent_ac_ex_id)
if parent_ac_ex_db.status == ac_const.LIVEACTION_STATUS_PAUSED:
ac_db_util.update_liveaction_status(
liveaction_id=parent_ac_ex_db.liveaction['id'],
status=ac_const.LIVEACTION_STATUS_RUNNING,
publish=False)
# If there are grand parents, handle the resume of the parent action execution.
if 'orchestra' in parent_ac_ex_db.context and 'parent' in parent_ac_ex_db.context:
handle_action_execution_resume(parent_ac_ex_db)
def test_execute_cancelation(self):
liveaction_db = self._create_liveaction_db()
self._process_request(liveaction_db)
scheduled_liveaction_db = action_db.get_liveaction_by_id(liveaction_db.id)
scheduled_liveaction_db = self._wait_on_status(
scheduled_liveaction_db,
action_constants.LIVEACTION_STATUS_SCHEDULED
)
action_db.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
liveaction_id=liveaction_db.id
)
canceled_liveaction_db = action_db.get_liveaction_by_id(liveaction_db.id)
self.dispatcher._queue_consumer._process_message(canceled_liveaction_db)
dispatched_liveaction_db = action_db.get_liveaction_by_id(liveaction_db.id)
self.assertEqual(
dispatched_liveaction_db.status,
action_constants.LIVEACTION_STATUS_CANCELED
)
self.assertDictEqual(
dispatched_liveaction_db.result,
{'message': 'Action execution canceled by user.'}
)
def test_execute_cancelation(self):
liveaction_db = self._create_liveaction_db()
self._process_request(liveaction_db)
scheduled_liveaction_db = action_utils.get_liveaction_by_id(
liveaction_db.id)
scheduled_liveaction_db = self._wait_on_status(
scheduled_liveaction_db,
action_constants.LIVEACTION_STATUS_SCHEDULED)
action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
liveaction_id=liveaction_db.id)
canceled_liveaction_db = action_utils.get_liveaction_by_id(
liveaction_db.id)
self.dispatcher._queue_consumer._process_message(
canceled_liveaction_db)
dispatched_liveaction_db = action_utils.get_liveaction_by_id(
liveaction_db.id)
self.assertEqual(dispatched_liveaction_db.status,
action_constants.LIVEACTION_STATUS_CANCELED)
self.assertDictEqual(dispatched_liveaction_db.result,
{'message': 'Action execution canceled by user.'})
def execute_action(self, liveaction):
try:
liveaction_db = get_liveaction_by_id(liveaction.id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.',
liveaction.id)
raise
# Update liveaction status to "running"
liveaction_db = update_liveaction_status(status=LIVEACTION_STATUS_RUNNING,
liveaction_id=liveaction_db.id)
# Launch action
LOG.audit('Launching action execution.',
extra={'liveaction': liveaction_db.to_serializable_dict()})
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
except Exception:
liveaction_db = update_liveaction_status(status=LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id)
raise
if not result:
raise ActionRunnerException('Failed to execute action.')
return result
def test_chain_pause_resume_status_change(self):
"""Tests context_result is updated when last task's status changes between pause and resume
"""
# A temp file is created during test setup. Ensure the temp file exists.
# The test action chain will stall until this file is deleted. This gives
# the unit test a moment to run any test related logic.
path = self.temp_file_path
self.assertTrue(os.path.exists(path))
action = TEST_PACK + '.' + 'test_pause_resume_context_result'
params = {'tempfile': path}
liveaction = LiveActionDB(action=action, parameters=params)
liveaction, execution = action_service.request(liveaction)
liveaction = LiveAction.get_by_id(str(liveaction.id))
# This workflow runs 'core.ask' so will pause on its own. We just need to
# wait until the liveaction is pausing.
liveaction = self._wait_for_status(
liveaction, action_constants.LIVEACTION_STATUS_PAUSING)
self.assertEqual(liveaction.status,
action_constants.LIVEACTION_STATUS_PAUSING)
# Delete the temporary file that the action chain is waiting on.
os.remove(path)
self.assertFalse(os.path.exists(path))
# Wait until the liveaction is paused.
liveaction = self._wait_for_status(
liveaction, action_constants.LIVEACTION_STATUS_PAUSED)
self.assertEqual(liveaction.status,
action_constants.LIVEACTION_STATUS_PAUSED)
# Wait for non-blocking threads to complete. Ensure runner is not running.
MockLiveActionPublisherNonBlocking.wait_all()
last_task_liveaction_id = liveaction.result['tasks'][-1][
'liveaction_id']
action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
result={'foo': 'bar'},
liveaction_id=last_task_liveaction_id)
# Request action chain to resume.
liveaction, execution = action_service.request_resume(
liveaction, USERNAME)
# Wait until the liveaction is completed.
liveaction = self._wait_for_status(
liveaction, action_constants.LIVEACTION_STATUS_SUCCEEDED)
self.assertEqual(liveaction.status,
action_constants.LIVEACTION_STATUS_SUCCEEDED)
# Wait for non-blocking threads to complete.
MockLiveActionPublisherNonBlocking.wait_all()
# Check liveaction result.
self.assertIn('tasks', liveaction.result)
self.assertEqual(len(liveaction.result['tasks']), 2)
self.assertEqual(liveaction.result['tasks'][0]['result']['foo'], 'bar')
def handle_action_execution_resume(ac_ex_db):
if 'orchestra' not in ac_ex_db.context:
raise Exception(
'Unable to handle resume of action execution. The action execution '
'%s is not an orchestra workflow task.' % str(ac_ex_db.id)
)
wf_ex_id = ac_ex_db.context['orchestra']['workflow_execution_id']
task_ex_id = ac_ex_db.context['orchestra']['task_execution_id']
# Updat task execution to running.
resume_task_execution(task_ex_id)
# Update workflow execution to running.
resume_workflow_execution(wf_ex_id, task_ex_id)
# If action execution has a parent, cascade status change upstream and do not publish
# the status change because we do not want to trigger resume of other peer subworkflows.
if 'parent' in ac_ex_db.context:
parent_ac_ex_id = ac_ex_db.context['parent']['execution_id']
parent_ac_ex_db = ex_db_access.ActionExecution.get_by_id(parent_ac_ex_id)
if parent_ac_ex_db.status == ac_const.LIVEACTION_STATUS_PAUSED:
ac_db_util.update_liveaction_status(
liveaction_id=parent_ac_ex_db.liveaction['id'],
status=ac_const.LIVEACTION_STATUS_RUNNING,
publish=False)
# If there are grand parents, handle the resume of the parent action execution.
if 'orchestra' in parent_ac_ex_db.context and 'parent' in parent_ac_ex_db.context:
handle_action_execution_resume(parent_ac_ex_db)
def test_update_canceled_liveaction(self):
liveaction_db = LiveActionDB()
liveaction_db.status = "initializing"
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack,
).ref
params = {
"actionstr": "foo",
"some_key_that_aint_exist_in_action_or_runner": "bar",
"runnerint": 555,
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status="running", liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, "running")
# Verify that state is published.
self.assertTrue(LiveActionPublisher.publish_state.called)
LiveActionPublisher.publish_state.assert_called_once_with(
newliveaction_db, "running")
# Cancel liveaction.
now = get_datetime_utc_now()
status = "canceled"
newliveaction_db = action_db_utils.update_liveaction_status(
status=status, end_timestamp=now, liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertEqual(newliveaction_db.end_timestamp, now)
# Since liveaction has already been canceled, check that anymore update of
# status, result, context, and end timestamp are not processed.
now = get_datetime_utc_now()
status = "succeeded"
result = "Work is done."
context = {"third_party_id": uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status,
result=result,
context=context,
end_timestamp=now,
liveaction_id=liveaction_db.id,
)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, "canceled")
self.assertNotEqual(newliveaction_db.result, result)
self.assertNotEqual(newliveaction_db.context, context)
self.assertNotEqual(newliveaction_db.end_timestamp, now)
def _run_action(self, liveaction_db):
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_RUNNING,
runner_info=runner_info,
liveaction_id=liveaction_db.id)
self._running_liveactions.add(liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {
'action_execution_db': action_execution_db,
'liveaction_db': liveaction_db
}
LOG.audit('Launching action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info(
'Dispatched {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id, liveaction_db.id, liveaction_db.status)
extra = {'liveaction_db': liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result:
raise ActionRunnerException('Failed to execute action.')
except:
_, ex, tb = sys.exc_info()
extra['error'] = str(ex)
LOG.info('Action "%s" failed: %s' %
(liveaction_db.action, str(ex)),
extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={
'error': str(ex),
'traceback': ''.join(traceback.format_tb(tb, 20))
})
executions.update_execution(liveaction_db)
raise
finally:
# In the case of worker shutdown, the items are removed from _running_liveactions.
# As the subprocesses for action executions are terminated, this finally block
# will be executed. Set remove will result in KeyError if item no longer exists.
# Use set discard to not raise the KeyError.
self._running_liveactions.discard(liveaction_db.id)
return result
def process(self, liveaction):
"""Dispatches the LiveAction to appropriate action runner.
LiveAction in statuses other than "scheduled" are ignored. If
LiveAction is already canceled and result is empty, the LiveAction
is updated with a generic exception message.
:param liveaction: Scheduled action execution request.
:type liveaction: ``st2common.models.db.liveaction.LiveActionDB``
:rtype: ``dict``
"""
if liveaction.status == action_constants.LIVEACTION_STATUS_CANCELED:
LOG.info('%s is not executing %s (id=%s) with "%s" status.',
self.__class__.__name__, type(liveaction), liveaction.id, liveaction.status)
if not liveaction.result:
updated_liveaction = action_utils.update_liveaction_status(
status=liveaction.status,
result={'message': 'Action execution canceled by user.'},
liveaction_id=liveaction.id)
executions.update_execution(updated_liveaction)
return
if liveaction.status != action_constants.LIVEACTION_STATUS_SCHEDULED:
LOG.info('%s is not executing %s (id=%s) with "%s" status.',
self.__class__.__name__, type(liveaction), liveaction.id, liveaction.status)
return
try:
liveaction_db = action_utils.get_liveaction_by_id(liveaction.id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.', liveaction.id)
raise
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_RUNNING,
runner_info=runner_info,
liveaction_id=liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {'action_execution_db': action_execution_db, 'liveaction_db': liveaction_db}
LOG.audit('Launching action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info('Dispatched {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id, liveaction_db.id, liveaction.status)
return self._run_action(liveaction_db)
def test_update_canceled_liveaction(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'initializing'
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status='running', liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'running')
# Verify that state is published.
self.assertTrue(LiveActionPublisher.publish_state.called)
LiveActionPublisher.publish_state.assert_called_once_with(newliveaction_db, 'running')
# Cancel liveaction.
now = get_datetime_utc_now()
status = 'canceled'
newliveaction_db = action_db_utils.update_liveaction_status(
status=status, end_timestamp=now, liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertEqual(newliveaction_db.end_timestamp, now)
# Since liveaction has already been canceled, check that anymore update of
# status, result, context, and end timestamp are not processed.
now = get_datetime_utc_now()
status = 'succeeded'
result = 'Work is done.'
context = {'third_party_id': uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status, result=result, context=context, end_timestamp=now,
liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'canceled')
self.assertNotEqual(newliveaction_db.result, result)
self.assertNotEqual(newliveaction_db.context, context)
self.assertNotEqual(newliveaction_db.end_timestamp, now)
def test_chain_pause_resume_status_change(self):
# Tests context_result is updated when last task's status changes between pause and resume
action = TEST_PACK + "." + "test_pause_resume_context_result"
liveaction = LiveActionDB(action=action)
liveaction, execution = action_service.request(liveaction)
liveaction = LiveAction.get_by_id(str(liveaction.id))
# Wait until the liveaction is paused.
liveaction = self._wait_for_status(
liveaction, action_constants.LIVEACTION_STATUS_PAUSED)
extra_info = str(liveaction)
self.assertEqual(liveaction.status,
action_constants.LIVEACTION_STATUS_PAUSED, extra_info)
# Wait for non-blocking threads to complete. Ensure runner is not running.
MockLiveActionPublisherNonBlocking.wait_all()
last_task_liveaction_id = liveaction.result["tasks"][-1][
"liveaction_id"]
action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
end_timestamp=date_utils.get_datetime_utc_now(),
result={"foo": "bar"},
liveaction_id=last_task_liveaction_id,
)
# Request action chain to resume.
liveaction, execution = action_service.request_resume(
liveaction, USERNAME)
# Wait until the liveaction is completed.
liveaction = self._wait_for_status(
liveaction, action_constants.LIVEACTION_STATUS_SUCCEEDED)
self.assertEqual(
liveaction.status,
action_constants.LIVEACTION_STATUS_SUCCEEDED,
str(liveaction),
)
# Wait for non-blocking threads to complete.
MockLiveActionPublisherNonBlocking.wait_all()
# Check liveaction result.
self.assertIn("tasks", liveaction.result)
self.assertEqual(len(liveaction.result["tasks"]), 2)
self.assertEqual(liveaction.result["tasks"][0]["result"]["foo"], "bar")
def _run_action(self, liveaction_db):
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_RUNNING,
runner_info=runner_info,
liveaction_id=liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {
'action_execution_db': action_execution_db,
'liveaction_db': liveaction_db
}
LOG.audit('Launching action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info(
'Dispatched {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id, liveaction_db.id, liveaction_db.status)
extra = {'liveaction_db': liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result:
raise ActionRunnerException('Failed to execute action.')
except:
_, ex, tb = sys.exc_info()
extra['error'] = str(ex)
LOG.info('Action "%s" failed: %s' %
(liveaction_db.action, str(ex)),
extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={
'error': str(ex),
'traceback': ''.join(traceback.format_tb(tb, 20))
})
executions.update_execution(liveaction_db)
raise
return result
def test_update_liveaction_result_with_dotted_key(self):
liveaction_db = LiveActionDB()
liveaction_db.status = "initializing"
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack,
).ref
params = {
"actionstr": "foo",
"some_key_that_aint_exist_in_action_or_runner": "bar",
"runnerint": 555,
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status="running", liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, "running")
# Verify that state is published.
self.assertTrue(LiveActionPublisher.publish_state.called)
LiveActionPublisher.publish_state.assert_called_once_with(
newliveaction_db, "running")
now = get_datetime_utc_now()
status = "succeeded"
result = {"a": 1, "b": True, "a.b.c": "abc"}
context = {"third_party_id": uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status,
result=result,
context=context,
end_timestamp=now,
liveaction_id=liveaction_db.id,
)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertIn("a.b.c", list(result.keys()))
self.assertDictEqual(newliveaction_db.result, result)
self.assertDictEqual(newliveaction_db.context, context)
self.assertEqual(newliveaction_db.end_timestamp, now)
def execute_action(self, liveaction):
# Note: We only want to execute actions which haven't completed yet
if liveaction.status == LIVEACTION_STATUS_CANCELED:
LOG.info('Not executing liveaction %s. User canceled execution.', liveaction.id)
if not liveaction.result:
update_liveaction_status(status=LIVEACTION_STATUS_CANCELED,
result={'message': 'Action execution canceled by user.'},
liveaction_id=liveaction.id)
return
if liveaction.status in [LIVEACTION_STATUS_SUCCEEDED, LIVEACTION_STATUS_FAILED]:
LOG.info('Ignoring liveaction %s which has already finished', liveaction.id)
return
try:
liveaction_db = get_liveaction_by_id(liveaction.id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.',
liveaction.id)
raise
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = update_liveaction_status(status=LIVEACTION_STATUS_RUNNING,
runner_info=runner_info,
liveaction_id=liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {'action_execution_db': action_execution_db, 'liveaction_db': liveaction_db}
LOG.audit('Launching action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info('{~}action_execution: %s / {~}live_action: %s',
action_execution_db.id, liveaction_db.id)
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result:
raise ActionRunnerException('Failed to execute action.')
except Exception:
liveaction_db = update_liveaction_status(status=LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id)
raise
return result
def abandon_execution_if_incomplete(liveaction_id, publish=True):
"""
Marks execution as abandoned if it is still incomplete. Abandoning an
execution implies that its end state is unknown and cannot anylonger
be determined. This method should only be called if the owning process
is certain it can no longer determine status of an execution.
"""
liveaction_db = action_utils.get_liveaction_by_id(liveaction_id)
# No need to abandon and already complete action
if liveaction_db.status in action_constants.LIVEACTION_COMPLETED_STATES:
raise ValueError('LiveAction %s already in a completed state %s.' %
(liveaction_id, liveaction_db.status))
# Update status to reflect execution being abandoned.
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_ABANDONED,
liveaction_db=liveaction_db,
result={})
execution_db = update_execution(liveaction_db, publish=publish)
LOG.info('Marked execution %s as %s.', execution_db.id,
action_constants.LIVEACTION_STATUS_ABANDONED)
# Invoke post run on the action to execute post run operations such as callback.
runners_utils.invoke_post_run(liveaction_db)
return execution_db
def test_update_same_liveaction_status(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'requested'
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status='requested', liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'requested')
# Verify that state is not published.
self.assertFalse(LiveActionPublisher.publish_state.called)
def update_status(liveaction, new_status, result=None, publish=True):
if liveaction.status == new_status:
return liveaction
old_status = liveaction.status
liveaction = action_utils.update_liveaction_status(
status=new_status, result=result, liveaction_id=liveaction.id, publish=False
)
action_execution = executions.update_execution(liveaction)
msg = "The status of action execution is changed from %s to %s. " "<LiveAction.id=%s, ActionExecution.id=%s>" % (
old_status,
new_status,
liveaction.id,
action_execution.id,
)
extra = {"action_execution_db": action_execution, "liveaction_db": liveaction}
LOG.audit(msg, extra=extra)
LOG.info(msg)
if publish:
LiveAction.publish_status(liveaction)
return liveaction
def respond(inquiry, response, requester=None):
# Set requester to system user is not provided.
if not requester:
requester = cfg.CONF.system_user.user
# Retrieve the liveaction from the database.
liveaction_db = lv_db_access.LiveAction.get_by_id(
inquiry.liveaction.get("id"))
# Resume the parent workflow first. If the action execution for the inquiry is updated first,
# it triggers handling of the action execution completion which will interact with the paused
# parent workflow. The resuming logic that is executed here will then race with the completion
# of the inquiry action execution, which will randomly result in the parent workflow stuck in
# paused state.
if liveaction_db.context.get("parent"):
LOG.debug('Resuming workflow parent(s) for inquiry "%s".' %
str(inquiry.id))
# For action execution under Action Chain workflows, request the entire
# workflow to resume. Orquesta handles resume differently and so does not require root
# to resume. Orquesta allows for specifc branches to resume while other is paused. When
# there is no other paused branches, the conductor will resume the rest of the workflow.
resume_target = (
action_service.get_parent_liveaction(liveaction_db)
if workflow_service.is_action_execution_under_workflow_context(
liveaction_db) else
action_service.get_root_liveaction(liveaction_db))
if resume_target.status in action_constants.LIVEACTION_PAUSE_STATES:
action_service.request_resume(resume_target, requester)
# Succeed the liveaction and update result with the inquiry response.
LOG.debug('Updating response for inquiry "%s".' % str(inquiry.id))
result = fast_deepcopy_dict(inquiry.result)
result["response"] = response
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
end_timestamp=date_utils.get_datetime_utc_now(),
runner_info=sys_info_utils.get_process_info(),
result=result,
liveaction_id=str(liveaction_db.id),
)
# Sync the liveaction with the corresponding action execution.
execution_service.update_execution(liveaction_db)
# Invoke inquiry post run to trigger a callback to parent workflow.
LOG.debug('Invoking post run for inquiry "%s".' % str(inquiry.id))
runner_container = container.get_runner_container()
action_db = action_utils.get_action_by_ref(liveaction_db.action)
runnertype_db = action_utils.get_runnertype_by_name(
action_db.runner_type["name"])
runner = runner_container._get_runner(runnertype_db, action_db,
liveaction_db)
runner.post_run(status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
result=result)
return liveaction_db
def _do_cancel(self, runner, runnertype_db, action_db, liveaction_db):
try:
extra = {'runner': runner}
LOG.debug('Performing cancel for runner: %s', (runner.runner_id),
extra=extra)
runner.cancel()
liveaction_db = update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
end_timestamp=date_utils.get_datetime_utc_now(),
liveaction_db=liveaction_db)
executions.update_execution(liveaction_db)
except:
_, ex, tb = sys.exc_info()
# include the error message and traceback to try and provide some hints.
result = {
'error': str(ex),
'traceback': ''.join(traceback.format_tb(tb, 20))
}
LOG.exception('Failed to cancel action %s.' % (liveaction_db.id),
extra=result)
return liveaction_db
def update_status(liveaction, new_status, result=None, publish=True):
if liveaction.status == new_status:
return liveaction
old_status = liveaction.status
liveaction = action_utils.update_liveaction_status(
status=new_status,
result=result,
liveaction_id=liveaction.id,
publish=False)
action_execution = executions.update_execution(liveaction)
msg = ('The status of action execution is changed from %s to %s. '
'<LiveAction.id=%s, ActionExecution.id=%s>' %
(old_status, new_status, liveaction.id, action_execution.id))
extra = {
'action_execution_db': action_execution,
'liveaction_db': liveaction
}
LOG.audit(msg, extra=extra)
LOG.info(msg)
if publish:
LiveAction.publish_status(liveaction)
return liveaction
def _update_live_action_db(self, liveaction_id, status, result, context):
"""
Update LiveActionDB object for the provided liveaction id.
"""
liveaction_db = get_liveaction_by_id(liveaction_id)
state_changed = (
liveaction_db.status != status and
liveaction_db.status not in action_constants.LIVEACTION_COMPLETED_STATES
)
if status in action_constants.LIVEACTION_COMPLETED_STATES:
end_timestamp = date_utils.get_datetime_utc_now()
else:
end_timestamp = None
liveaction_db = update_liveaction_status(
status=status if state_changed else liveaction_db.status,
result=result,
context=context,
end_timestamp=end_timestamp,
liveaction_db=liveaction_db
)
return (liveaction_db, state_changed)
def _do_cancel(self, runner, runnertype_db, action_db, liveaction_db):
try:
extra = {"runner": runner}
LOG.debug("Performing cancel for runner: %s", (runner.runner_id), extra=extra)
runner.cancel()
liveaction_db = update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
end_timestamp=date_utils.get_datetime_utc_now(),
liveaction_db=liveaction_db,
)
executions.update_execution(liveaction_db)
LOG.debug("Performing post_run for runner: %s", runner.runner_id)
result = {"error": "Execution canceled by user."}
runner.post_run(status=liveaction_db.status, result=result)
runner.container_service = None
except:
_, ex, tb = sys.exc_info()
# include the error message and traceback to try and provide some hints.
result = {"error": str(ex), "traceback": "".join(traceback.format_tb(tb, 20))}
LOG.exception("Failed to cancel action %s." % (liveaction_db.id), extra=result)
finally:
# Always clean-up the auth_token
status = liveaction_db.status
self._clean_up_auth_token(runner=runner, status=status)
return liveaction_db
def update_status(liveaction, new_status, publish=True):
if liveaction.status == new_status:
return liveaction
old_status = liveaction.status
liveaction = action_utils.update_liveaction_status(
status=new_status, liveaction_id=liveaction.id, publish=False)
action_execution = executions.update_execution(liveaction)
msg = ('The status of action execution is changed from %s to %s. '
'<LiveAction.id=%s, ActionExecution.id=%s>' % (old_status,
new_status, liveaction.id, action_execution.id))
extra = {
'action_execution_db': action_execution,
'liveaction_db': liveaction
}
LOG.audit(msg, extra=extra)
LOG.info(msg)
if publish:
LiveAction.publish_status(liveaction)
return liveaction
def _mark_inquiry_complete(self, inquiry_id, result):
"""Mark Inquiry as completed
This function updates the local LiveAction and Execution with a successful
status as well as call the "post_run" function for the Inquirer runner so that
the appropriate callback function is executed
:param inquiry: The Inquiry for which the response is given
:param requester_user: The user providing the response
:rtype: bool - True if requester_user is able to respond. False if not.
"""
# Update inquiry's execution result with a successful status and the validated response
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
runner_info=system_info.get_process_info(),
result=result,
liveaction_id=inquiry_id)
executions.update_execution(liveaction_db)
# Call Inquiry runner's post_run to trigger callback to workflow
runner_container = get_runner_container()
action_db = get_action_by_ref(liveaction_db.action)
runnertype_db = get_runnertype_by_name(action_db.runner_type['name'])
runner = runner_container._get_runner(runnertype_db, action_db, liveaction_db)
runner.post_run(status=action_constants.LIVEACTION_STATUS_SUCCEEDED, result=result)
return liveaction_db
def _mark_inquiry_complete(self, inquiry_id, result):
"""Mark Inquiry as completed
This function updates the local LiveAction and Execution with a successful
status as well as call the "post_run" function for the Inquirer runner so that
the appropriate callback function is executed
:param inquiry: The Inquiry for which the response is given
:param requester_user: The user providing the response
:rtype: bool - True if requester_user is able to respond. False if not.
"""
# Update inquiry's execution result with a successful status and the validated response
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
runner_info=system_info.get_process_info(),
result=result,
liveaction_id=inquiry_id)
executions.update_execution(liveaction_db)
# Call Inquiry runner's post_run to trigger callback to workflow
runner_container = get_runner_container()
action_db = get_action_by_ref(liveaction_db.action)
runnertype_db = get_runnertype_by_name(action_db.runner_type['name'])
runner = runner_container._get_runner(runnertype_db, action_db,
liveaction_db)
runner.post_run(status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
result=result)
return liveaction_db
def _update_live_action_db(self, liveaction_id, status, result, context):
"""
Update LiveActionDB object for the provided liveaction id.
"""
liveaction_db = get_liveaction_by_id(liveaction_id)
state_changed = (
liveaction_db.status != status and
liveaction_db.status not in action_constants.LIVEACTION_COMPLETED_STATES
)
if status in action_constants.LIVEACTION_COMPLETED_STATES:
end_timestamp = date_utils.get_datetime_utc_now()
else:
end_timestamp = None
liveaction_db = update_liveaction_status(
status=status if state_changed else liveaction_db.status,
result=result,
context=context,
end_timestamp=end_timestamp,
liveaction_db=liveaction_db
)
return (liveaction_db, state_changed)
def test_update_liveaction_with_incorrect_output_schema(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'initializing'
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
runner = mock.MagicMock()
runner.output_schema = {"notaparam": {"type": "boolean"}}
liveaction_db.runner = runner
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
now = get_datetime_utc_now()
status = 'succeeded'
result = 'Work is done.'
context = {'third_party_id': uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status,
result=result,
context=context,
end_timestamp=now,
liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertEqual(newliveaction_db.result, result)
self.assertDictEqual(newliveaction_db.context, context)
self.assertEqual(newliveaction_db.end_timestamp, now)
def set_execution_status(self, lv_ac_db_id, status):
lv_ac_db = action_utils.update_liveaction_status(
status=status, liveaction_id=lv_ac_db_id, publish=False)
ac_ex_db = execution_service.update_execution(lv_ac_db, publish=False)
return lv_ac_db, ac_ex_db
def _do_cancel(self, runner, runnertype_db, action_db, liveaction_db):
try:
extra = {'runner': runner}
LOG.debug('Performing cancel for runner: %s', (runner.runner_id),
extra=extra)
runner.cancel()
liveaction_db = update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
end_timestamp=date_utils.get_datetime_utc_now(),
liveaction_db=liveaction_db)
executions.update_execution(liveaction_db)
LOG.debug('Performing post_run for runner: %s', runner.runner_id)
result = {'error': 'Execution canceled by user.'}
runner.post_run(status=liveaction_db.status, result=result)
runner.container_service = None
except:
_, ex, tb = sys.exc_info()
# include the error message and traceback to try and provide some hints.
result = {
'error': str(ex),
'traceback': ''.join(traceback.format_tb(tb, 20))
}
LOG.exception('Failed to cancel action %s.' % (liveaction_db.id),
extra=result)
finally:
# Always clean-up the auth_token
status = liveaction_db.status
self._clean_up_auth_token(runner=runner, status=status)
return liveaction_db
def _run_action(self, liveaction_db):
extra = {'liveaction_db': liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result:
raise ActionRunnerException('Failed to execute action.')
except:
_, ex, tb = sys.exc_info()
extra['error'] = str(ex)
LOG.info('Action "%s" failed: %s' %
(liveaction_db.action, str(ex)),
extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={
'error': str(ex),
'traceback': ''.join(traceback.format_tb(tb, 20))
})
executions.update_execution(liveaction_db)
raise
return result
def abandon_execution_if_incomplete(liveaction_id, publish=True):
"""
Marks execution as abandoned if it is still incomplete. Abandoning an
execution implies that its end state is unknown and cannot anylonger
be determined. This method should only be called if the owning process
is certain it can no longer determine status of an execution.
"""
liveaction_db = action_utils.get_liveaction_by_id(liveaction_id)
# No need to abandon and already complete action
if liveaction_db.status in action_constants.LIVEACTION_COMPLETED_STATES:
raise ValueError('LiveAction %s already in a completed state %s.' %
(liveaction_id, liveaction_db.status))
# Update status to reflect execution being abandoned.
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_ABANDONED,
liveaction_db=liveaction_db,
result={})
execution_db = update_execution(liveaction_db, publish=publish)
LOG.info('Marked execution %s as %s.', execution_db.id,
action_constants.LIVEACTION_STATUS_ABANDONED)
# Invoke post run on the action to execute post run operations such as callback.
runners_utils.invoke_post_run(liveaction_db)
return execution_db
def _run_action(self, liveaction_db):
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_RUNNING,
runner_info=runner_info,
liveaction_id=liveaction_db.id)
self._running_liveactions.add(liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {'action_execution_db': action_execution_db, 'liveaction_db': liveaction_db}
LOG.audit('Launching action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info('Dispatched {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id, liveaction_db.id, liveaction_db.status)
extra = {'liveaction_db': liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result and not liveaction_db.action_is_workflow:
raise ActionRunnerException('Failed to execute action.')
except:
_, ex, tb = sys.exc_info()
extra['error'] = str(ex)
LOG.info('Action "%s" failed: %s' % (liveaction_db.action, str(ex)), extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={'error': str(ex), 'traceback': ''.join(traceback.format_tb(tb, 20))})
executions.update_execution(liveaction_db)
raise
finally:
# In the case of worker shutdown, the items are removed from _running_liveactions.
# As the subprocesses for action executions are terminated, this finally block
# will be executed. Set remove will result in KeyError if item no longer exists.
# Use set discard to not raise the KeyError.
self._running_liveactions.discard(liveaction_db.id)
return result
def _run_action(self, liveaction_db):
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_RUNNING, runner_info=runner_info, liveaction_id=liveaction_db.id
)
self._running_liveactions.add(liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {"action_execution_db": action_execution_db, "liveaction_db": liveaction_db}
LOG.audit("Launching action execution.", extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info(
'Dispatched {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id,
liveaction_db.id,
liveaction_db.status,
)
extra = {"liveaction_db": liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug("Runner dispatch produced result: %s", result)
if not result:
raise ActionRunnerException("Failed to execute action.")
except:
_, ex, tb = sys.exc_info()
extra["error"] = str(ex)
LOG.info('Action "%s" failed: %s' % (liveaction_db.action, str(ex)), extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={"error": str(ex), "traceback": "".join(traceback.format_tb(tb, 20))},
)
executions.update_execution(liveaction_db)
raise
finally:
self._running_liveactions.remove(liveaction_db.id)
return result
def test_update_liveaction_result_with_dotted_key(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'initializing'
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status='running', liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'running')
# Verify that state is published.
self.assertTrue(LiveActionPublisher.publish_state.called)
LiveActionPublisher.publish_state.assert_called_once_with(
newliveaction_db, 'running')
now = get_datetime_utc_now()
status = 'succeeded'
result = {'a': 1, 'b': True, 'a.b.c': 'abc'}
context = {'third_party_id': uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status,
result=result,
context=context,
end_timestamp=now,
liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertIn('a.b.c', result.keys())
self.assertDictEqual(newliveaction_db.result, result)
self.assertDictEqual(newliveaction_db.context, context)
self.assertEqual(newliveaction_db.end_timestamp, now)
def update_execution_records(wf_ex_db,
conductor,
update_lv_ac_on_states=None,
pub_wf_ex=False,
pub_lv_ac=True,
pub_ac_ex=True):
wf_ac_ex_id = wf_ex_db.action_execution
wf_old_status = wf_ex_db.status
# Update timestamp and output if workflow is completed.
if conductor.get_workflow_state() in states.COMPLETED_STATES:
wf_ex_db.end_timestamp = date_utils.get_datetime_utc_now()
wf_ex_db.output = conductor.get_workflow_output()
# Update workflow status and task flow and write changes to database.
wf_ex_db.status = conductor.get_workflow_state()
wf_ex_db.errors = copy.deepcopy(conductor.errors)
wf_ex_db.flow = conductor.flow.serialize()
wf_ex_db = wf_db_access.WorkflowExecution.update(wf_ex_db,
publish=pub_wf_ex)
# Add log entry if status changed.
if wf_old_status != wf_ex_db.status:
LOG.info('[%s] Updated workflow execution from state "%s" to "%s".',
wf_ac_ex_id, wf_old_status, wf_ex_db.status)
# Return if workflow execution status is not specified in update_lv_ac_on_states.
if isinstance(update_lv_ac_on_states,
list) and wf_ex_db.status not in update_lv_ac_on_states:
return
# Update the corresponding liveaction and action execution for the workflow.
wf_ac_ex_db = ex_db_access.ActionExecution.get_by_id(
wf_ex_db.action_execution)
wf_lv_ac_db = ac_db_util.get_liveaction_by_id(wf_ac_ex_db.liveaction['id'])
# Gather result for liveaction and action execution.
result = {'output': wf_ex_db.output or None}
if wf_ex_db.status in states.ABENDED_STATES:
result['errors'] = wf_ex_db.errors
for wf_ex_error in wf_ex_db.errors:
LOG.error('[%s] Workflow execution completed with errors.',
wf_ac_ex_id,
extra=wf_ex_error)
# Sync update with corresponding liveaction and action execution.
wf_lv_ac_db = ac_db_util.update_liveaction_status(
status=wf_ex_db.status,
result=result,
end_timestamp=wf_ex_db.end_timestamp,
liveaction_db=wf_lv_ac_db,
publish=pub_lv_ac)
ex_svc.update_execution(wf_lv_ac_db, publish=pub_ac_ex)
def apply_before(self, target):
if self.get_threshold() <= 0:
# Cancel the action execution.
target = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
liveaction_id=target.id,
publish=False)
return target
def test_chain_pause_resume_status_change(self):
# Tests context_result is updated when last task's status changes between pause and resume
action = TEST_PACK + '.' + 'test_pause_resume_context_result'
liveaction = LiveActionDB(action=action)
liveaction, execution = action_service.request(liveaction)
liveaction = LiveAction.get_by_id(str(liveaction.id))
# Wait until the liveaction is paused.
liveaction = self._wait_for_status(liveaction, action_constants.LIVEACTION_STATUS_PAUSED)
extra_info = str(liveaction)
self.assertEqual(liveaction.status, action_constants.LIVEACTION_STATUS_PAUSED, extra_info)
# Wait for non-blocking threads to complete. Ensure runner is not running.
MockLiveActionPublisherNonBlocking.wait_all()
last_task_liveaction_id = liveaction.result['tasks'][-1]['liveaction_id']
action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
end_timestamp=date_utils.get_datetime_utc_now(),
result={'foo': 'bar'},
liveaction_id=last_task_liveaction_id
)
# Request action chain to resume.
liveaction, execution = action_service.request_resume(liveaction, USERNAME)
# Wait until the liveaction is completed.
liveaction = self._wait_for_status(liveaction, action_constants.LIVEACTION_STATUS_SUCCEEDED)
self.assertEqual(
liveaction.status,
action_constants.LIVEACTION_STATUS_SUCCEEDED,
str(liveaction)
)
# Wait for non-blocking threads to complete.
MockLiveActionPublisherNonBlocking.wait_all()
# Check liveaction result.
self.assertIn('tasks', liveaction.result)
self.assertEqual(len(liveaction.result['tasks']), 2)
self.assertEqual(liveaction.result['tasks'][0]['result']['foo'], 'bar')
def purge_inquiries(logger):
"""Purge Inquiries that have exceeded their configured TTL
At the moment, Inquiries do not have their own database model, so this function effectively
is another, more specialized GC for executions. It will look for executions with a 'pending'
status that use the 'inquirer' runner, which is the current definition for an Inquiry.
Then it will mark those that have a nonzero TTL have existed longer than their TTL as
"timed out". It will then request that the parent workflow(s) resume, where the failure
can be handled as the user desires.
"""
# Get all existing Inquiries
filters = {'runner__name': 'inquirer', 'status': action_constants.LIVEACTION_STATUS_PENDING}
inquiries = list(ActionExecution.query(**filters))
gc_count = 0
# Inspect each Inquiry, and determine if TTL is expired
for inquiry in inquiries:
ttl = int(inquiry.result.get('ttl'))
if ttl <= 0:
logger.debug("Inquiry %s has a TTL of %s. Skipping." % (inquiry.id, ttl))
continue
min_since_creation = int(
(get_datetime_utc_now() - inquiry.start_timestamp).total_seconds() / 60
)
logger.debug("Inquiry %s has a TTL of %s and was started %s minute(s) ago" % (
inquiry.id, ttl, min_since_creation))
if min_since_creation > ttl:
gc_count += 1
logger.info("TTL expired for Inquiry %s. Marking as timed out." % inquiry.id)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_TIMED_OUT,
result=inquiry.result,
liveaction_id=inquiry.liveaction.get('id'))
executions.update_execution(liveaction_db)
# Call Inquiry runner's post_run to trigger callback to workflow
action_db = get_action_by_ref(liveaction_db.action)
invoke_post_run(liveaction_db=liveaction_db, action_db=action_db)
if liveaction_db.context.get("parent"):
# Request that root workflow resumes
root_liveaction = action_service.get_root_liveaction(liveaction_db)
action_service.request_resume(
root_liveaction,
UserDB(cfg.CONF.system_user.user)
)
logger.info('Marked %s ttl-expired Inquiries as "timed out".' % (gc_count))
def respond(inquiry, response, requester=None):
# Set requester to system user is not provided.
if not requester:
requester = cfg.CONF.system_user.user
# Retrieve the liveaction from the database.
liveaction_db = lv_db_access.LiveAction.get_by_id(inquiry.liveaction.get('id'))
# Resume the parent workflow first. If the action execution for the inquiry is updated first,
# it triggers handling of the action execution completion which will interact with the paused
# parent workflow. The resuming logic that is executed here will then race with the completion
# of the inquiry action execution, which will randomly result in the parent workflow stuck in
# paused state.
if liveaction_db.context.get('parent'):
LOG.debug('Resuming workflow parent(s) for inquiry "%s".' % str(inquiry.id))
# For action execution under Action Chain and Mistral workflows, request the entire
# workflow to resume. Orquesta handles resume differently and so does not require root
# to resume. Orquesta allows for specifc branches to resume while other is paused. When
# there is no other paused branches, the conductor will resume the rest of the workflow.
resume_target = (
action_service.get_parent_liveaction(liveaction_db)
if workflow_service.is_action_execution_under_workflow_context(liveaction_db)
else action_service.get_root_liveaction(liveaction_db)
)
if resume_target.status in action_constants.LIVEACTION_PAUSE_STATES:
action_service.request_resume(resume_target, requester)
# Succeed the liveaction and update result with the inquiry response.
LOG.debug('Updating response for inquiry "%s".' % str(inquiry.id))
result = copy.deepcopy(inquiry.result)
result['response'] = response
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SUCCEEDED,
end_timestamp=date_utils.get_datetime_utc_now(),
runner_info=sys_info_utils.get_process_info(),
result=result,
liveaction_id=str(liveaction_db.id)
)
# Sync the liveaction with the corresponding action execution.
execution_service.update_execution(liveaction_db)
# Invoke inquiry post run to trigger a callback to parent workflow.
LOG.debug('Invoking post run for inquiry "%s".' % str(inquiry.id))
runner_container = container.get_runner_container()
action_db = action_utils.get_action_by_ref(liveaction_db.action)
runnertype_db = action_utils.get_runnertype_by_name(action_db.runner_type['name'])
runner = runner_container._get_runner(runnertype_db, action_db, liveaction_db)
runner.post_run(status=action_constants.LIVEACTION_STATUS_SUCCEEDED, result=result)
return liveaction_db
def test_update_liveaction_result_with_dotted_key(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'initializing'
liveaction_db.start_timestamp = get_datetime_utc_now()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status='running', liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'running')
# Verify that state is published.
self.assertTrue(LiveActionPublisher.publish_state.called)
LiveActionPublisher.publish_state.assert_called_once_with(newliveaction_db, 'running')
now = get_datetime_utc_now()
status = 'succeeded'
result = {'a': 1, 'b': True, 'a.b.c': 'abc'}
context = {'third_party_id': uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status, result=result, context=context, end_timestamp=now,
liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertIn('a.b.c', list(result.keys()))
self.assertDictEqual(newliveaction_db.result, result)
self.assertDictEqual(newliveaction_db.context, context)
self.assertEqual(newliveaction_db.end_timestamp, now)
def process(self, liveaction):
"""Dispatches the LiveAction to appropriate action runner.
LiveAction in statuses other than "scheduled" and "canceling" are ignored. If
LiveAction is already canceled and result is empty, the LiveAction
is updated with a generic exception message.
:param liveaction: Action execution request.
:type liveaction: ``st2common.models.db.liveaction.LiveActionDB``
:rtype: ``dict``
"""
if liveaction.status == action_constants.LIVEACTION_STATUS_CANCELED:
LOG.info(
'%s is not executing %s (id=%s) with "%s" status.',
self.__class__.__name__,
type(liveaction),
liveaction.id,
liveaction.status,
)
if not liveaction.result:
updated_liveaction = action_utils.update_liveaction_status(
status=liveaction.status,
result={"message": "Action execution canceled by user."},
liveaction_id=liveaction.id,
)
executions.update_execution(updated_liveaction)
return
if liveaction.status not in [
action_constants.LIVEACTION_STATUS_SCHEDULED,
action_constants.LIVEACTION_STATUS_CANCELING,
]:
LOG.info(
'%s is not dispatching %s (id=%s) with "%s" status.',
self.__class__.__name__,
type(liveaction),
liveaction.id,
liveaction.status,
)
return
try:
liveaction_db = action_utils.get_liveaction_by_id(liveaction.id)
except StackStormDBObjectNotFoundError:
LOG.exception("Failed to find liveaction %s in the database.", liveaction.id)
raise
return (
self._run_action(liveaction_db)
if liveaction.status == action_constants.LIVEACTION_STATUS_SCHEDULED
else self._cancel_action(liveaction_db)
)
def handle_action_execution_resume(ac_ex_db):
if 'orquesta' not in ac_ex_db.context:
raise Exception(
'Unable to handle resume of action execution. The action execution '
'%s is not an orquesta workflow task.' % str(ac_ex_db.id)
)
# Get related record identifiers.
wf_ex_id = ac_ex_db.context['orquesta']['workflow_execution_id']
task_ex_id = ac_ex_db.context['orquesta']['task_execution_id']
# Get execution records for logging purposes.
wf_ex_db = wf_db_access.WorkflowExecution.get_by_id(wf_ex_id)
task_ex_db = wf_db_access.TaskExecution.get_by_id(task_ex_id)
msg = '[%s] Handling resume of action execution "%s" for task "%s", route "%s".'
LOG.info(msg, wf_ex_db.action_execution, str(ac_ex_db.id),
task_ex_db.task_id, str(task_ex_db.task_route))
# Updat task execution to running.
resume_task_execution(task_ex_id)
# Update workflow execution to running.
resume_workflow_execution(wf_ex_id, task_ex_id)
# If action execution has a parent, cascade status change upstream and do not publish
# the status change because we do not want to trigger resume of other peer subworkflows.
if 'parent' in ac_ex_db.context:
parent_ac_ex_id = ac_ex_db.context['parent']['execution_id']
parent_ac_ex_db = ex_db_access.ActionExecution.get_by_id(parent_ac_ex_id)
if parent_ac_ex_db.status == ac_const.LIVEACTION_STATUS_PAUSED:
action_utils.update_liveaction_status(
liveaction_id=parent_ac_ex_db.liveaction['id'],
status=ac_const.LIVEACTION_STATUS_RUNNING,
publish=False)
# If there are grand parents, handle the resume of the parent action execution.
if 'orquesta' in parent_ac_ex_db.context and 'parent' in parent_ac_ex_db.context:
handle_action_execution_resume(parent_ac_ex_db)
def test_update_liveaction_status(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'initializing'
liveaction_db.start_timestamp = datetime.datetime.utcnow()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status='running', liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'running')
# Update status, result, context, and end timestamp.
now = datetime.datetime.utcnow()
status = 'succeeded'
result = 'Work is done.'
context = {'third_party_id': uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status,
result=result,
context=context,
end_timestamp=now,
liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertEqual(newliveaction_db.result, result)
self.assertDictEqual(newliveaction_db.context, context)
self.assertEqual(newliveaction_db.end_timestamp, now)
def handle_action_execution_resume(ac_ex_db):
if 'orquesta' not in ac_ex_db.context:
raise Exception(
'Unable to handle resume of action execution. The action execution '
'%s is not an orquesta workflow task.' % str(ac_ex_db.id))
# Get related record identifiers.
wf_ex_id = ac_ex_db.context['orquesta']['workflow_execution_id']
task_ex_id = ac_ex_db.context['orquesta']['task_execution_id']
# Get execution records for logging purposes.
wf_ex_db = wf_db_access.WorkflowExecution.get_by_id(wf_ex_id)
task_ex_db = wf_db_access.TaskExecution.get_by_id(task_ex_id)
msg = '[%s] Handling resume of action execution "%s" for task "%s".'
LOG.info(msg, wf_ex_db.action_execution, str(ac_ex_db.id),
task_ex_db.task_id)
# Updat task execution to running.
resume_task_execution(task_ex_id)
# Update workflow execution to running.
resume_workflow_execution(wf_ex_id, task_ex_id)
# If action execution has a parent, cascade status change upstream and do not publish
# the status change because we do not want to trigger resume of other peer subworkflows.
if 'parent' in ac_ex_db.context:
parent_ac_ex_id = ac_ex_db.context['parent']['execution_id']
parent_ac_ex_db = ex_db_access.ActionExecution.get_by_id(
parent_ac_ex_id)
if parent_ac_ex_db.status == ac_const.LIVEACTION_STATUS_PAUSED:
action_utils.update_liveaction_status(
liveaction_id=parent_ac_ex_db.liveaction['id'],
status=ac_const.LIVEACTION_STATUS_RUNNING,
publish=False)
# If there are grand parents, handle the resume of the parent action execution.
if 'orquesta' in parent_ac_ex_db.context and 'parent' in parent_ac_ex_db.context:
handle_action_execution_resume(parent_ac_ex_db)
def process(self, liveaction):
"""Dispatches the LiveAction to appropriate action runner.
LiveAction in statuses other than "scheduled" and "canceling" are ignored. If
LiveAction is already canceled and result is empty, the LiveAction
is updated with a generic exception message.
:param liveaction: Action execution request.
:type liveaction: ``st2common.models.db.liveaction.LiveActionDB``
:rtype: ``dict``
"""
if liveaction.status == action_constants.LIVEACTION_STATUS_CANCELED:
LOG.info('%s is not executing %s (id=%s) with "%s" status.',
self.__class__.__name__, type(liveaction), liveaction.id, liveaction.status)
if not liveaction.result:
updated_liveaction = action_utils.update_liveaction_status(
status=liveaction.status,
result={'message': 'Action execution canceled by user.'},
liveaction_id=liveaction.id)
executions.update_execution(updated_liveaction)
return
if liveaction.status not in ACTIONRUNNER_DISPATCHABLE_STATES:
LOG.info('%s is not dispatching %s (id=%s) with "%s" status.',
self.__class__.__name__, type(liveaction), liveaction.id, liveaction.status)
return
try:
liveaction_db = action_utils.get_liveaction_by_id(liveaction.id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.', liveaction.id)
raise
if liveaction.status != liveaction_db.status:
LOG.warning(
'The status of liveaction %s has changed from %s to %s '
'while in the queue waiting for processing.',
liveaction.id,
liveaction.status,
liveaction_db.status
)
dispatchers = {
action_constants.LIVEACTION_STATUS_SCHEDULED: self._run_action,
action_constants.LIVEACTION_STATUS_CANCELING: self._cancel_action,
action_constants.LIVEACTION_STATUS_PAUSING: self._pause_action,
action_constants.LIVEACTION_STATUS_RESUMING: self._resume_action
}
return dispatchers[liveaction.status](liveaction)
def process(self, liveaction):
"""Dispatches the LiveAction to appropriate action runner.
LiveAction in statuses other than "scheduled" and "canceling" are ignored. If
LiveAction is already canceled and result is empty, the LiveAction
is updated with a generic exception message.
:param liveaction: Action execution request.
:type liveaction: ``st2common.models.db.liveaction.LiveActionDB``
:rtype: ``dict``
"""
if liveaction.status == action_constants.LIVEACTION_STATUS_CANCELED:
LOG.info('%s is not executing %s (id=%s) with "%s" status.',
self.__class__.__name__, type(liveaction), liveaction.id, liveaction.status)
if not liveaction.result:
updated_liveaction = action_utils.update_liveaction_status(
status=liveaction.status,
result={'message': 'Action execution canceled by user.'},
liveaction_id=liveaction.id)
executions.update_execution(updated_liveaction)
return
if liveaction.status not in ACTIONRUNNER_DISPATCHABLE_STATES:
LOG.info('%s is not dispatching %s (id=%s) with "%s" status.',
self.__class__.__name__, type(liveaction), liveaction.id, liveaction.status)
return
try:
liveaction_db = action_utils.get_liveaction_by_id(liveaction.id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.', liveaction.id)
raise
if liveaction.status != liveaction_db.status:
LOG.warning(
'The status of liveaction %s has changed from %s to %s '
'while in the queue waiting for processing.',
liveaction.id,
liveaction.status,
liveaction_db.status
)
dispatchers = {
action_constants.LIVEACTION_STATUS_SCHEDULED: self._run_action,
action_constants.LIVEACTION_STATUS_CANCELING: self._cancel_action,
action_constants.LIVEACTION_STATUS_PAUSING: self._pause_action,
action_constants.LIVEACTION_STATUS_RESUMING: self._resume_action
}
return dispatchers[liveaction.status](liveaction)
def _update_live_action_db(self, liveaction_id, status, result, context):
liveaction_db = get_liveaction_by_id(liveaction_id)
if status in action_constants.COMPLETED_STATES:
end_timestamp = date_utils.get_datetime_utc_now()
else:
end_timestamp = None
liveaction_db = update_liveaction_status(status=status,
result=result,
context=context,
end_timestamp=end_timestamp,
liveaction_db=liveaction_db)
return liveaction_db
def _update_live_action_db(self, liveaction_id, status, result, context):
liveaction_db = get_liveaction_by_id(liveaction_id)
if status in DONE_STATES:
end_timestamp = isotime.add_utc_tz(datetime.datetime.utcnow())
else:
end_timestamp = None
liveaction_db = update_liveaction_status(status=status,
result=result,
context=context,
end_timestamp=end_timestamp,
liveaction_db=liveaction_db)
return liveaction_db
def _update_live_action_db(self, liveaction_id, status, result, context):
liveaction_db = get_liveaction_by_id(liveaction_id)
if status in action_constants.COMPLETED_STATES:
end_timestamp = isotime.add_utc_tz(datetime.datetime.utcnow())
else:
end_timestamp = None
liveaction_db = update_liveaction_status(status=status,
result=result,
context=context,
end_timestamp=end_timestamp,
liveaction_db=liveaction_db)
return liveaction_db
def set_execution_status(self, lv_ac_db_id, status):
lv_ac_db = action_utils.update_liveaction_status(
status=status,
liveaction_id=lv_ac_db_id,
publish=False
)
ac_ex_db = execution_service.update_execution(
lv_ac_db,
publish=False
)
return lv_ac_db, ac_ex_db
def _run_action(self, liveaction_db):
# stamp liveaction with process_info
runner_info = system_info.get_process_info()
# Update liveaction status to "running"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_RUNNING,
runner_info=runner_info,
liveaction_id=liveaction_db.id)
action_execution_db = executions.update_execution(liveaction_db)
# Launch action
extra = {'action_execution_db': action_execution_db, 'liveaction_db': liveaction_db}
LOG.audit('Launching action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info('Dispatched {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id, liveaction_db.id, liveaction_db.status)
extra = {'liveaction_db': liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result:
raise ActionRunnerException('Failed to execute action.')
except:
_, ex, tb = sys.exc_info()
extra['error'] = str(ex)
LOG.info('Action "%s" failed: %s' % (liveaction_db.action, str(ex)), extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={'error': str(ex), 'traceback': ''.join(traceback.format_tb(tb, 20))})
executions.update_execution(liveaction_db)
raise
return result
def test_update_liveaction_status(self):
liveaction_db = LiveActionDB()
liveaction_db.status = 'initializing'
liveaction_db.start_timestamp = datetime.datetime.utcnow()
liveaction_db.action = ResourceReference(
name=ActionDBUtilsTestCase.action_db.name,
pack=ActionDBUtilsTestCase.action_db.pack).ref
params = {
'actionstr': 'foo',
'some_key_that_aint_exist_in_action_or_runner': 'bar',
'runnerint': 555
}
liveaction_db.parameters = params
liveaction_db = LiveAction.add_or_update(liveaction_db)
origliveaction_db = copy.copy(liveaction_db)
# Update by id.
newliveaction_db = action_db_utils.update_liveaction_status(
status='running', liveaction_id=liveaction_db.id)
# Verify id didn't change.
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, 'running')
# Update status, result, context, and end timestamp.
now = datetime.datetime.utcnow()
status = 'succeeded'
result = 'Work is done.'
context = {'third_party_id': uuid.uuid4().hex}
newliveaction_db = action_db_utils.update_liveaction_status(
status=status, result=result, context=context, end_timestamp=now,
liveaction_id=liveaction_db.id)
self.assertEqual(origliveaction_db.id, newliveaction_db.id)
self.assertEqual(newliveaction_db.status, status)
self.assertEqual(newliveaction_db.result, result)
self.assertDictEqual(newliveaction_db.context, context)
self.assertEqual(newliveaction_db.end_timestamp, now)
def update_status(
liveaction,
new_status,
result=None,
publish=True,
set_result_size=False,
context=None,
):
if liveaction.status == new_status:
return liveaction
old_status = liveaction.status
updates = {
"liveaction_id": liveaction.id,
"status": new_status,
"result": result,
"publish": False,
"context": context,
}
if new_status in action_constants.LIVEACTION_COMPLETED_STATES:
updates["end_timestamp"] = date_utils.get_datetime_utc_now()
liveaction = action_utils.update_liveaction_status(**updates)
action_execution = executions.update_execution(
liveaction, set_result_size=set_result_size)
msg = ("The status of action execution is changed from %s to %s. "
"<LiveAction.id=%s, ActionExecution.id=%s>" %
(old_status, new_status, liveaction.id, action_execution.id))
extra = {
"action_execution_db": action_execution,
"liveaction_db": liveaction
}
LOG.audit(msg, extra=extra)
LOG.info(msg)
# Invoke post run if liveaction status is completed or paused.
if (new_status in action_constants.LIVEACTION_COMPLETED_STATES
or new_status == action_constants.LIVEACTION_STATUS_PAUSED):
runners_utils.invoke_post_run(liveaction)
if publish:
LiveAction.publish_status(liveaction)
return liveaction
def _run_action(self, liveaction_db):
extra = {'liveaction_db': liveaction_db}
try:
result = self.container.dispatch(liveaction_db)
LOG.debug('Runner dispatch produced result: %s', result)
if not result:
raise ActionRunnerException('Failed to execute action.')
except:
_, ex, tb = sys.exc_info()
extra['error'] = str(ex)
LOG.info('Action "%s" failed: %s' % (liveaction_db.action, str(ex)), extra=extra)
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_FAILED,
liveaction_id=liveaction_db.id,
result={'error': str(ex), 'traceback': ''.join(traceback.format_tb(tb, 20))})
executions.update_execution(liveaction_db)
raise
return result
def _do_cancel(self, runner, runnertype_db, action_db, liveaction_db):
try:
extra = {'runner': runner}
LOG.debug('Performing cancel for runner: %s', (runner.runner_id), extra=extra)
runner.cancel()
liveaction_db = update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_CANCELED,
end_timestamp=date_utils.get_datetime_utc_now(),
liveaction_db=liveaction_db)
executions.update_execution(liveaction_db)
except:
_, ex, tb = sys.exc_info()
# include the error message and traceback to try and provide some hints.
result = {'error': str(ex), 'traceback': ''.join(traceback.format_tb(tb, 20))}
LOG.exception('Failed to cancel action %s.' % (liveaction_db.id), extra=result)
return liveaction_db
def process(self, request):
"""Schedules the LiveAction and publishes the request
to the appropriate action runner(s).
LiveAction in statuses other than "requested" are ignored.
:param request: Action execution request.
:type request: ``st2common.models.db.liveaction.LiveActionDB``
"""
if request.status != action_constants.LIVEACTION_STATUS_REQUESTED:
LOG.info('%s is ignoring %s (id=%s) with "%s" status.',
self.__class__.__name__, type(request), request.id, request.status)
return
try:
liveaction_db = action_utils.get_liveaction_by_id(request.id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.', request.id)
raise
# Update liveaction status to "scheduled"
liveaction_db = action_utils.update_liveaction_status(
status=action_constants.LIVEACTION_STATUS_SCHEDULED,
liveaction_id=liveaction_db.id,
publish=False)
action_execution_db = executions.update_execution(liveaction_db)
# Publish the "scheduled" status here manually. Otherwise, there could be a
# race condition with the update of the action_execution_db if the execution
# of the liveaction completes first.
LiveAction.publish_status(liveaction_db)
extra = {'action_execution_db': action_execution_db, 'liveaction_db': liveaction_db}
LOG.audit('Scheduled action execution.', extra=extra)
# the extra field will not be shown in non-audit logs so temporarily log at info.
LOG.info('Scheduled {~}action_execution: %s / {~}live_action: %s with "%s" status.',
action_execution_db.id, liveaction_db.id, request.status)