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)