def testSyncRequest_processError(self, mock_queue, mock_process):
request_sync_monitor.Monitor(REQUEST_ID)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
sync_status = sync_key.get()
sync_status.has_new_command_events = True
sync_status.put()
mock_process.side_effect = RuntimeError
datastore_test_util.CreateRequest(request_id=REQUEST_ID,
user='******',
command_infos=[
datastore_entities.CommandInfo(
command_line='command_line2',
cluster='cluster',
run_target='run_target')
],
state=common.RequestState.QUEUED)
with self.assertRaises(RuntimeError):
request_sync_monitor.SyncRequest(REQUEST_ID)
mock_process.assert_called_once_with(REQUEST_ID)
mock_queue.assert_called_once_with(REQUEST_ID) # Call from Monitor()
sync_status = sync_key.get()
self.assertTrue(sync_status.has_new_command_events)
def testSyncRequest_noRequest(self, mock_update, mock_queue, mock_process):
mock_update.return_value = True
request_sync_monitor.SyncRequest(REQUEST_ID)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
self.assertIsNone(sync_key.get())
mock_queue.assert_not_called()
mock_process.assert_not_called()
def testMonitor(self):
request_sync_monitor.Monitor(REQUEST_ID)
tasks = self.mock_task_scheduler.GetTasks(
queue_names=(request_sync_monitor.REQUEST_SYNC_QUEUE, ))
self.assertLen(tasks, 1)
task = json.loads(tasks[0].payload)
self.assertEqual(REQUEST_ID, task[request_sync_monitor.REQUEST_ID_KEY])
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
sync_status = sync_key.get()
self.assertEqual(REQUEST_ID, sync_status.request_id)
def testStoreCommandEvent(self):
request_sync_monitor.Monitor(REQUEST_ID)
event = _AddCommandEvent()
raw_events = datastore_entities.RawCommandEvent.query(
datastore_entities.RawCommandEvent.request_id == REQUEST_ID,
namespace=common.NAMESPACE).fetch()
self.assertLen(raw_events, 1)
self.assertEqual(event.event_dict, raw_events[0].payload)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
self.assertTrue(sync_key.get().has_new_command_events)
def testUpdateSyncStatus_force(self, mock_now):
now = datetime.datetime.utcnow()
mock_now.return_value = now
request_sync_monitor.Monitor(REQUEST_ID)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
sync_status = sync_key.get()
sync_status.last_sync_time = now - datetime.timedelta(minutes=2)
sync_status.put()
self.assertTrue(request_sync_monitor._UpdateSyncStatus(REQUEST_ID))
sync_status = sync_key.get()
self.assertEqual(now, sync_status.last_sync_time)
def testUpdateSyncStatus_noSyncTime(self, mock_now):
now = datetime.datetime.utcnow()
mock_now.return_value = now
request_sync_monitor.Monitor(REQUEST_ID)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
sync_status = sync_key.get()
sync_status.has_new_command_events = False
sync_status.put()
self.assertTrue(request_sync_monitor._UpdateSyncStatus(REQUEST_ID))
sync_status = sync_key.get()
self.assertFalse(sync_status.has_new_command_events)
self.assertEqual(now, sync_status.last_sync_time)
def testUpdateSyncStatus_noEvents(self, mock_now):
last_sync = datetime.datetime(2021, 1, 1) # last synced 1 second ago
now = datetime.datetime(2021, 1, 1, 0, 0, 1)
mock_now.return_value = now
request_sync_monitor.Monitor(REQUEST_ID)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
sync_status = sync_key.get()
sync_status.has_new_command_events = False
sync_status.last_sync_time = last_sync
sync_status.put()
self.assertFalse(request_sync_monitor._UpdateSyncStatus(REQUEST_ID))
sync_status = sync_key.get()
self.assertEqual(last_sync, sync_status.last_sync_time)
def testSyncRequest_finalRequest(self, mock_update, mock_queue,
mock_process):
mock_update.return_value = True
request = datastore_test_util.CreateRequest(
request_id=REQUEST_ID,
user='******',
command_infos=[
datastore_entities.CommandInfo(command_line='command_line2',
cluster='cluster',
run_target='run_target')
],
state=common.RequestState.COMPLETED)
request.put()
request_sync_monitor.SyncRequest(REQUEST_ID)
sync_key = request_sync_monitor.GetRequestSyncStatusKey(REQUEST_ID)
self.assertIsNone(sync_key.get())
mock_process.assert_called_once_with(REQUEST_ID)
mock_queue.assert_not_called()
def ProcessCommandEvent(event):
"""Processes a command event.
Args:
event: a CommandEvent object.
"""
logging.debug("Processing command event: %s", str(event))
command = command_manager.GetCommand(event.request_id, event.command_id)
LogCommandEventMetrics(command=command, event=event)
request_sync_key = request_sync_monitor.GetRequestSyncStatusKey(
event.request_id)
if request_sync_key.get():
request_sync_monitor.StoreCommandEvent(event)
else:
logging.debug("No request sync found for %s. Using legacy processing.",
event.request_id)
# This can also happen if TFC received late events on final requests.
metric.command_event_legacy_processing_count.Increment({})
# We keep the legacy processing as some use cases depend on having command
# attempt data updated even after the request is final:
# Eg: measuring fuzzing time
commander.ProcessCommandEvent(event)