def _update_to_scheduled(liveaction_db, execution_queue_item_db):
liveaction_id = str(liveaction_db.id)
queue_item_id = str(execution_queue_item_db.id)
extra = {
'liveaction_id': liveaction_id,
'liveaction_status': liveaction_db.status,
'queue_item_id': queue_item_id
}
# Update liveaction status to "scheduled".
LOG.info('Liveaction (%s) Status Update to Scheduled 1: %s (%s)',
liveaction_id, liveaction_db.status, queue_item_id, extra=extra)
if liveaction_db.status in [action_constants.LIVEACTION_STATUS_REQUESTED,
action_constants.LIVEACTION_STATUS_DELAYED]:
liveaction_db = action_service.update_status(
liveaction_db, action_constants.LIVEACTION_STATUS_SCHEDULED, publish=False)
# 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['liveaction_status'] = liveaction_db.status
# Delete execution queue entry only after status is published.
ActionExecutionSchedulingQueue.delete(execution_queue_item_db)
LOG.info('Liveaction (%s) Status Update to Scheduled 2: %s (%s)',
liveaction_id, liveaction_db.status, queue_item_id)
def _handle_garbage_collection(self):
"""
Periodically look for executions which have "handling" set to "True" and haven't been
updated for a while (this likely indicates that an execution as picked up by a scheduler
process which died before finishing the processing or similar) and reset handling to
False so other scheduler can pick it up.
"""
query = {
'scheduled_start_timestamp__lte': date.append_milliseconds_to_time(
date.get_datetime_utc_now(),
-EXECUTION_SCHEDUELING_TIMEOUT_THRESHOLD_MS
),
'handling': True
}
execution_queue_item_dbs = ActionExecutionSchedulingQueue.query(**query) or []
for execution_queue_item_db in execution_queue_item_dbs:
execution_queue_item_db.handling = False
try:
ActionExecutionSchedulingQueue.add_or_update(execution_queue_item_db, publish=False)
LOG.info('Removing lock for orphaned execution queue item: %s',
execution_queue_item_db.id)
except db_exc.StackStormDBObjectWriteConflictError:
LOG.info(
'Execution queue item updated before rescheduling: %s',
execution_queue_item_db.id
)
def test_failed_next_item(self, mocked_logger):
self.reset()
liveaction_db = self._create_liveaction_db()
schedule_q_db = self.scheduler._create_execution_queue_item_db_from_liveaction(
liveaction_db,
)
schedule_q_db = ActionExecutionSchedulingQueue.add_or_update(schedule_q_db)
with mock.patch(
'st2actions.scheduler.handler.ActionExecutionSchedulingQueue.add_or_update',
side_effect=db_exc.StackStormDBObjectWriteConflictError(schedule_q_db)
):
schedule_q_db = self.scheduling_queue._get_next_execution()
self.assertIsNone(schedule_q_db)
self.assertEqual(mocked_logger.info.call_count, 2)
call_args = mocked_logger.info.call_args_list[1][0]
self.assertEqual(r'[%s] Item "%s" is already handled by another scheduler.', call_args[0])
schedule_q_db = self.scheduling_queue._get_next_execution()
self.assertIsNotNone(schedule_q_db)
ActionExecutionSchedulingQueue.delete(schedule_q_db)
def _is_execution_queue_item_runnable(liveaction_db, execution_queue_item_db):
"""
Return True if a particular execution request is runnable.
The status of the liveaction could have been changed by one of the policies and that could
make execution not runnable anymore.
"""
valid_status = [
action_constants.LIVEACTION_STATUS_REQUESTED,
action_constants.LIVEACTION_STATUS_SCHEDULED,
action_constants.LIVEACTION_STATUS_DELAYED
]
if liveaction_db.status in valid_status:
return True
LOG.info(
'Scheduler is ignoring %s (id=%s) with "%s" status after policies are applied.',
type(execution_queue_item_db),
execution_queue_item_db.id,
liveaction_db.status
)
ActionExecutionSchedulingQueue.delete(execution_queue_item_db)
return False
def _get_next_execution(self):
"""
Sort execution requests by FIFO and priority and get the latest, highest priority item from
the queue and pop it off.
"""
query = {
'scheduled_start_timestamp__lte': date.get_datetime_utc_now(),
'handling': False,
'limit': 1,
'order_by': [
'+scheduled_start_timestamp',
]
}
execution_queue_item_db = ActionExecutionSchedulingQueue.query(**query).first()
if not execution_queue_item_db:
return None
# Mark that this scheduler process is currently handling (processing) that request
# NOTE: This operation is atomic (CAS)
execution_queue_item_db.handling = True
try:
ActionExecutionSchedulingQueue.add_or_update(execution_queue_item_db, publish=False)
return execution_queue_item_db
except db_exc.StackStormDBObjectWriteConflictError:
LOG.info('Execution queue item handled by another scheduler: %s',
execution_queue_item_db.id)
return None
def test_next_execution(self):
self.reset()
schedule_q_dbs = []
delays = [2000, 5000, 4000]
expected_order = [0, 2, 1]
test_cases = []
for delay in delays:
liveaction_db = self._create_liveaction_db()
delayed_start = date.append_milliseconds_to_time(liveaction_db.start_timestamp, delay)
test_case = {
'liveaction': liveaction_db,
'delay': delay,
'delayed_start': delayed_start
}
test_cases.append(test_case)
for test_case in test_cases:
schedule_q_dbs.append(
ActionExecutionSchedulingQueue.add_or_update(
self.scheduler._create_execution_queue_item_db_from_liveaction(
test_case['liveaction'],
test_case['delay'],
)
)
)
# Wait maximum delay seconds so the query works as expected
eventlet.sleep(3.2)
for index in expected_order:
test_case = test_cases[index]
date_mock = mock.MagicMock()
date_mock.get_datetime_utc_now.return_value = test_case['delayed_start']
date_mock.append_milliseconds_to_time = date.append_milliseconds_to_time
with mock.patch('st2actions.scheduler.handler.date', date_mock):
schedule_q_db = self.scheduling_queue._get_next_execution()
ActionExecutionSchedulingQueue.delete(schedule_q_db)
self.assertIsInstance(schedule_q_db, ActionExecutionSchedulingQueueItemDB)
self.assertEqual(schedule_q_db.delay, test_case['delay'])
self.assertEqual(schedule_q_db.liveaction_id, str(test_case['liveaction'].id))
# NOTE: We can't directly assert on the timestamp due to the delays on the code and
# timing variance
scheduled_start_timestamp = schedule_q_db.scheduled_start_timestamp
test_case_start_timestamp = test_case['delayed_start']
start_timestamp_diff = (scheduled_start_timestamp - test_case_start_timestamp)
self.assertTrue(start_timestamp_diff <= datetime.timedelta(seconds=1))
def _handle_execution(self, execution_queue_item_db):
liveaction_id = str(execution_queue_item_db.liveaction_id)
queue_item_id = str(execution_queue_item_db.id)
extra = {
'liveaction_id': liveaction_id,
'queue_item_id': queue_item_id
}
LOG.info('Scheduling liveaction: %s (queue_item_id=%s)', liveaction_id,
queue_item_id, extra=extra)
try:
liveaction_db = action_utils.get_liveaction_by_id(liveaction_id)
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database (queue_item_id=%s).',
liveaction_id, queue_item_id, extra=extra)
ActionExecutionSchedulingQueue.delete(execution_queue_item_db)
raise
# Identify if the action has policies that require locking.
action_has_policies_require_lock = policy_service.has_policies(
liveaction_db,
policy_types=policy_constants.POLICY_TYPES_REQUIRING_LOCK
)
# Acquire a distributed lock if the referenced action has specific policies attached.
if action_has_policies_require_lock:
# Warn users that the coordination service is not configured.
if not coordination_service.configured():
LOG.warn(
'Coordination backend is not configured. '
'Policy enforcement is best effort.'
)
# Acquire a distributed lock before querying the database to make sure that only one
# scheduler is scheduling execution for this action. Even if the coordination service
# is not configured, the fake driver using zake or the file driver can still acquire
# a lock for the local process or server respectively.
lock_uid = liveaction_db.action
LOG.debug('%s is attempting to acquire lock "%s".', self.__class__.__name__, lock_uid)
lock = self._coordinator.get_lock(lock_uid)
try:
if lock.acquire(blocking=False):
self._regulate_and_schedule(liveaction_db, execution_queue_item_db)
else:
self._delay(liveaction_db, execution_queue_item_db)
finally:
lock.release()
else:
# Otherwise if there is no policy, then schedule away.
self._schedule(liveaction_db, execution_queue_item_db)
def test_processing_when_task_completed(self, mock_execution_queue_delete, mock_action_service):
self.reset()
liveaction_db = self._create_liveaction_db()
LiveAction.publish_status(liveaction_db)
liveaction_db.status = action_constants.LIVEACTION_STATUS_CANCELED
LiveAction.add_or_update(liveaction_db)
schedule_q_db = self.scheduling_queue._get_next_execution()
scheduling_queue.get_handler()._handle_execution(schedule_q_db)
mock_action_service.update_status.assert_not_called()
mock_execution_queue_delete.assert_called_once()
ActionExecutionSchedulingQueue.delete(schedule_q_db)
def _delay(self, liveaction_db, execution_queue_item_db):
liveaction_db = action_service.update_status(
liveaction_db, action_constants.LIVEACTION_STATUS_DELAYED, publish=False
)
execution_queue_item_db.scheduled_start_timestamp = date.append_milliseconds_to_time(
date.get_datetime_utc_now(),
POLICY_DELAYED_EXECUTION_RESCHEDULE_TIME_MS
)
try:
execution_queue_item_db.handling = False
ActionExecutionSchedulingQueue.add_or_update(execution_queue_item_db, publish=False)
except db_exc.StackStormDBObjectWriteConflictError:
LOG.warning(
'Execution queue item update conflict during scheduling: %s',
execution_queue_item_db.id
)
def _regulate_and_schedule(self, liveaction_db, execution_queue_item_db):
# Apply policies defined for the action.
liveaction_db = policy_service.apply_pre_run_policies(liveaction_db)
liveaction_id = str(liveaction_db.id)
queue_item_id = str(execution_queue_item_db.id)
extra = {
'liveaction_id': liveaction_id,
'liveaction_status': liveaction_db.status,
'queue_item_id': queue_item_id
}
LOG.info('Liveaction (%s) Status Pre-Run: %s (%s)', liveaction_id, liveaction_db.status,
queue_item_id, extra=extra)
if liveaction_db.status is action_constants.LIVEACTION_STATUS_POLICY_DELAYED:
liveaction_db = action_service.update_status(
liveaction_db, action_constants.LIVEACTION_STATUS_DELAYED, publish=False
)
execution_queue_item_db.handling = False
execution_queue_item_db.scheduled_start_timestamp = date.append_milliseconds_to_time(
date.get_datetime_utc_now(),
POLICY_DELAYED_EXECUTION_RESCHEDULE_TIME_MS
)
try:
ActionExecutionSchedulingQueue.add_or_update(execution_queue_item_db, publish=False)
except db_exc.StackStormDBObjectWriteConflictError:
LOG.warning(
'Execution queue item update conflict during scheduling: %s',
execution_queue_item_db.id
)
return
if (liveaction_db.status in action_constants.LIVEACTION_COMPLETED_STATES or
liveaction_db.status in action_constants.LIVEACTION_CANCEL_STATES):
ActionExecutionSchedulingQueue.delete(execution_queue_item_db)
return
self._schedule(liveaction_db, execution_queue_item_db)
def process(self, request):
"""
Adds execution into execution_scheduling database for scheduling
: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(str(request.id))
except StackStormDBObjectNotFoundError:
LOG.exception('Failed to find liveaction %s in the database.', str(request.id))
raise
query = {
'liveaction_id': str(liveaction_db.id),
}
queued_requests = ActionExecutionSchedulingQueue.query(**query)
if len(queued_requests) > 0:
# Particular execution is already being scheduled
return queued_requests[0]
if liveaction_db.delay and liveaction_db.delay > 0:
liveaction_db = action_service.update_status(
liveaction_db,
action_constants.LIVEACTION_STATUS_DELAYED,
publish=False
)
execution_queue_item_db = self._create_execution_queue_item_db_from_liveaction(
liveaction_db,
delay=liveaction_db.delay
)
ActionExecutionSchedulingQueue.add_or_update(execution_queue_item_db, publish=False)
return execution_queue_item_db
def test_populate_action_execution_id(self):
self.reset()
liveaction_db = self._create_liveaction_db()
schedule_q_db = self.scheduler._create_execution_queue_item_db_from_liveaction(
liveaction_db
)
# Manually unset the action_execution_id ot mock DB model of previous version.
schedule_q_db.action_execution_id = None
schedule_q_db = ActionExecutionSchedulingQueue.add_or_update(schedule_q_db)
schedule_q_db = ActionExecutionSchedulingQueue.get_by_id(str(schedule_q_db.id))
self.assertIsNone(schedule_q_db.action_execution_id)
# Run the clean up logic.
self.scheduling_queue._fix_missing_action_execution_id()
# Check that the action_execution_id is populated.
schedule_q_db = ActionExecutionSchedulingQueue.get_by_id(str(schedule_q_db.id))
execution_db = execution_service.update_execution(liveaction_db)
self.assertEqual(schedule_q_db.action_execution_id, str(execution_db.id))
def test_cleanup_policy_delayed(self):
self.reset()
liveaction_db = self._create_liveaction_db()
schedule_q_db = self.scheduler._create_execution_queue_item_db_from_liveaction(
liveaction_db
)
schedule_q_db = ActionExecutionSchedulingQueue.add_or_update(schedule_q_db)
# Manually update the liveaction to policy-delayed status.
# Using action_service.update_status will throw an exception on the
# deprecated action_constants.LIVEACTION_STATUS_POLICY_DELAYED.
liveaction_db.status = 'policy-delayed'
liveaction_db = LiveAction.add_or_update(liveaction_db)
execution_db = execution_service.update_execution(liveaction_db)
# Check that the execution status is set to policy-delayed.
liveaction_db = LiveAction.get_by_id(str(liveaction_db.id))
self.assertEqual(liveaction_db.status, 'policy-delayed')
execution_db = ActionExecution.get_by_id(str(execution_db.id))
self.assertEqual(execution_db.status, 'policy-delayed')
# Run the clean up logic.
self.scheduling_queue._cleanup_policy_delayed()
# Check that the execution status is reset to requested.
liveaction_db = LiveAction.get_by_id(str(liveaction_db.id))
self.assertEqual(liveaction_db.status, action_constants.LIVEACTION_STATUS_REQUESTED)
execution_db = ActionExecution.get_by_id(str(execution_db.id))
self.assertEqual(execution_db.status, action_constants.LIVEACTION_STATUS_REQUESTED)
# The old entry should have been deleted. Since the execution is
# reset to requested, there should be a new scheduling entry.
new_schedule_q_db = self.scheduling_queue._get_next_execution()
self.assertIsNotNone(new_schedule_q_db)
self.assertNotEqual(str(schedule_q_db.id), str(new_schedule_q_db.id))
self.assertEqual(schedule_q_db.action_execution_id, new_schedule_q_db.action_execution_id)
self.assertEqual(schedule_q_db.liveaction_id, new_schedule_q_db.liveaction_id)
def test_garbage_collection(self):
self.reset()
liveaction_db = self._create_liveaction_db()
schedule_q_db = self.scheduler._create_execution_queue_item_db_from_liveaction(
liveaction_db,
-70000,
)
schedule_q_db.handling = True
schedule_q_db = ActionExecutionSchedulingQueue.add_or_update(schedule_q_db)
schedule_q_db = self.scheduling_queue._get_next_execution()
self.assertIsNone(schedule_q_db)
self.scheduling_queue._handle_garbage_collection()
schedule_q_db = self.scheduling_queue._get_next_execution()
self.assertIsNotNone(schedule_q_db)
def _process_scheduling_queue():
for queued_req in ActionExecutionSchedulingQueue.get_all():
scheduling_queue.get_handler()._handle_execution(queued_req)
def _process_scheduling_queue():
for queued_req in ActionExecutionSchedulingQueue.get_all():
scheduling_queue.get_handler()._handle_execution(queued_req)