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 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) mocked_logger.info.assert_called_once() call_args = mocked_logger.info.call_args_list[0][0] self.assertEqual( r'Execution queue item handled by another scheduler: %s', 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 action_execution_id = str(execution_queue_item_db.action_execution_id) liveaction_id = str(execution_queue_item_db.liveaction_id) queue_item_id = str(execution_queue_item_db.id) extra = {'queue_item_id': queue_item_id} LOG.info( '[%s] Ignoring Liveaction "%s" with status "%s" after policies are applied.', action_execution_id, liveaction_id, liveaction_db.status, extra=extra ) ActionExecutionSchedulingQueue.delete(execution_queue_item_db) return False
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 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 _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 liveaction_db = self._apply_pre_run(liveaction_db, execution_queue_item_db) if not liveaction_db: return if self._is_execution_queue_item_runnable(liveaction_db, execution_queue_item_db): self._update_to_scheduled(liveaction_db, execution_queue_item_db)
def _update_to_scheduled(liveaction_db, execution_queue_item_db): action_execution_id = str(execution_queue_item_db.action_execution_id) liveaction_id = str(execution_queue_item_db.liveaction_id) queue_item_id = str(execution_queue_item_db.id) extra = {'queue_item_id': queue_item_id} # Update liveaction status to "scheduled". LOG.info( '[%s] Liveaction "%s" with status "%s" is updated to status "scheduled."', action_execution_id, liveaction_id, liveaction_db.status, 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) # Delete execution queue entry only after status is published. ActionExecutionSchedulingQueue.delete(execution_queue_item_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 _regulate_and_schedule(self, liveaction_db, execution_queue_item_db): action_execution_id = str(execution_queue_item_db.action_execution_id) liveaction_id = str(execution_queue_item_db.liveaction_id) queue_item_id = str(execution_queue_item_db.id) extra = {'queue_item_id': queue_item_id} LOG.info( '[%s] Liveaction "%s" has status "%s" before applying policies.', action_execution_id, liveaction_id, liveaction_db.status, extra=extra) # Apply policies defined for the action. liveaction_db = policy_service.apply_pre_run_policies(liveaction_db) LOG.info( '[%s] Liveaction "%s" has status "%s" after applying policies.', action_execution_id, liveaction_id, liveaction_db.status, extra=extra) if liveaction_db.status == action_constants.LIVEACTION_STATUS_DELAYED: LOG.info( '[%s] Liveaction "%s" is delayed and scheduling queue is updated.', action_execution_id, liveaction_id, extra=extra) 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( '[%s] Database write conflict on updating scheduling queue.', action_execution_id, extra=extra) 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 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 _cleanup_policy_delayed(self): """ Clean up any action execution in the deprecated policy-delayed status. Associated entries in the scheduling queue will be removed and the action execution will be moved back into requested status. """ policy_delayed_liveaction_dbs = LiveAction.query(status="policy-delayed") or [] for liveaction_db in policy_delayed_liveaction_dbs: ex_que_qry = {"liveaction_id": str(liveaction_db.id), "handling": False} execution_queue_item_dbs = ( ActionExecutionSchedulingQueue.query(**ex_que_qry) or [] ) for execution_queue_item_db in execution_queue_item_dbs: # Mark the entry in the scheduling queue for handling. try: execution_queue_item_db.handling = True execution_queue_item_db = ( ActionExecutionSchedulingQueue.add_or_update( execution_queue_item_db, publish=False ) ) except db_exc.StackStormDBObjectWriteConflictError: msg = ( '[%s] Item "%s" is currently being processed by another scheduler.' % ( execution_queue_item_db.action_execution_id, str(execution_queue_item_db.id), ) ) LOG.error(msg) raise Exception(msg) # Delete the entry from the scheduling queue. LOG.info( '[%s] Removing policy-delayed entry "%s" from the scheduling queue.', execution_queue_item_db.action_execution_id, str(execution_queue_item_db.id), ) ActionExecutionSchedulingQueue.delete(execution_queue_item_db) # Update the status of the liveaction and execution to requested. LOG.info( '[%s] Removing policy-delayed entry "%s" from the scheduling queue.', execution_queue_item_db.action_execution_id, str(execution_queue_item_db.id), ) liveaction_db = action_service.update_status( liveaction_db, action_constants.LIVEACTION_STATUS_REQUESTED ) execution_service.update_execution(liveaction_db)
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_next_execution(self): self.reset() schedule_q_dbs = [] delays = [100, 5000, 1000] 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'], ))) 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.scheduled_start_timestamp, test_case['delayed_start']) self.assertEqual(schedule_q_db.delay, test_case['delay']) self.assertEqual(schedule_q_db.liveaction_id, str(test_case['liveaction'].id))
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 _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 _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)