diff --git a/src/clusterfuzz/_internal/bot/tasks/utasks/fuzz_task.py b/src/clusterfuzz/_internal/bot/tasks/utasks/fuzz_task.py index e25f5e12ef1..efec8df083a 100644 --- a/src/clusterfuzz/_internal/bot/tasks/utasks/fuzz_task.py +++ b/src/clusterfuzz/_internal/bot/tasks/utasks/fuzz_task.py @@ -1479,7 +1479,7 @@ def _append(old, new_values): def run_engine_fuzzer(engine_impl, target_name, sync_corpus_directory, - testcase_directory): + testcase_directory, steps_time_tracker): """Run engine for fuzzing.""" if environment.is_trusted_host(): from clusterfuzz._internal.bot.untrusted_runner import tasks_host @@ -1494,7 +1494,8 @@ def run_engine_fuzzer(engine_impl, target_name, sync_corpus_directory, target_path = engine_common.find_fuzzer_path(build_dir, target_name) if target_path is None: raise FuzzTargetNotFoundError(f'{target_path} is not found.') - options = engine_impl.prepare(sync_corpus_directory, target_path, build_dir) + with steps_time_tracker.track('engine_prepare'): + options = engine_impl.prepare(sync_corpus_directory, target_path, build_dir) fuzz_test_timeout = environment.get_value('FUZZ_TEST_TIMEOUT') additional_processing_time = engine_impl.fuzz_additional_processing_timeout( @@ -1805,7 +1806,7 @@ def do_engine_fuzzing(self, engine_impl): self.job_type) as tracker: result, cur_fuzzer_metadata, fuzzing_strategies = run_engine_fuzzer( engine_impl, self.fuzz_target.binary, sync_corpus_directory, - self.testcase_directory) + self.testcase_directory, self.steps_time_tracker) # Timeouts are only accounted for in libfuzzer, this can be None tracker.timeout = bool(result.timed_out) except FuzzTargetNotFoundError: diff --git a/src/clusterfuzz/_internal/bot/untrusted_runner/tasks_impl.py b/src/clusterfuzz/_internal/bot/untrusted_runner/tasks_impl.py index 3479dbd4fe8..d3d6604f164 100644 --- a/src/clusterfuzz/_internal/bot/untrusted_runner/tasks_impl.py +++ b/src/clusterfuzz/_internal/bot/untrusted_runner/tasks_impl.py @@ -18,6 +18,7 @@ from clusterfuzz._internal.bot import testcase_manager from clusterfuzz._internal.bot.tasks.utasks import fuzz_task +from clusterfuzz._internal.metrics import monitor from clusterfuzz._internal.protos import untrusted_runner_pb2 from clusterfuzz.fuzz import engine @@ -49,9 +50,10 @@ def _pack_values(values): def engine_fuzz(request, _): """Run engine fuzzer.""" engine_impl = engine.get(request.engine) + tracker = monitor.TimeStatTracker() result, fuzzer_metadata, strategies = fuzz_task.run_engine_fuzzer( engine_impl, request.target_name, request.sync_corpus_directory, - request.testcase_directory) + request.testcase_directory, tracker) crashes = [ untrusted_runner_pb2.EngineCrash( diff --git a/src/clusterfuzz/_internal/metrics/fuzzer_stats.py b/src/clusterfuzz/_internal/metrics/fuzzer_stats.py index fd408405911..717cc7ffa4f 100644 --- a/src/clusterfuzz/_internal/metrics/fuzzer_stats.py +++ b/src/clusterfuzz/_internal/metrics/fuzzer_stats.py @@ -51,6 +51,11 @@ 'type': 'INTERVAL', 'mode': 'NULLABLE', }, + { + 'name': 'engine_prepare', + 'type': 'INTERVAL', + 'mode': 'NULLABLE', + }, ] JOB_RUN_SCHEMA = { 'fields': [ diff --git a/src/clusterfuzz/_internal/tests/core/bot/tasks/utasks/fuzz_task_test.py b/src/clusterfuzz/_internal/tests/core/bot/tasks/utasks/fuzz_task_test.py index ca66f0b3648..bc45b377e9a 100644 --- a/src/clusterfuzz/_internal/tests/core/bot/tasks/utasks/fuzz_task_test.py +++ b/src/clusterfuzz/_internal/tests/core/bot/tasks/utasks/fuzz_task_test.py @@ -2094,6 +2094,91 @@ def setUp(self): self.mock.get_arbitrary_signed_upload_urls.return_value = ['http://a'] * 100 self.mock.last_updated.return_value = None + monitor.metrics_store().reset_for_testing() + + def _create_engine_fuzzing_session(self): + """Creates a FuzzingSession ready for do_engine_fuzzing.""" + target = 'test_target' + fuzz_task_input = uworker_msg_pb2.FuzzTaskInput( + fuzz_target=uworker_io.entity_to_protobuf( + data_types.FuzzTarget(engine='libFuzzer', binary=target)),) + uworker_input = uworker_msg_pb2.Input( + fuzzer_name='libFuzzer_fuzz', + job_type='libfuzzer_asan_test', + fuzz_task_input=fuzz_task_input) + session = fuzz_task.FuzzingSession(uworker_input, 60) + session.testcase_directory = os.environ['FUZZ_INPUTS'] + session.data_directory = '/data_dir' + + os.environ['FUZZ_TARGET'] = target + os.environ['APP_REVISION'] = '1' + os.environ['FUZZ_TEST_TIMEOUT'] = '2000' + os.environ['BOT_NAME'] = 'hostname.company.com' + os.environ['FUZZ_LOGS_BUCKET'] = '/fuzz-logs' + return session + + def _create_engine_impl(self): + """Creates a mock engine whose fuzz call yields no crashes.""" + engine_impl = mock.Mock() + engine_impl.name = 'libFuzzer' + engine_impl.prepare.return_value = engine.FuzzOptions( + '/corpus', ['arg'], {}) + engine_impl.fuzz.side_effect = lambda *_: engine.FuzzResult( + 'logs', ['cmd'], [], {'stat': 1}, 42.0) + engine_impl.fuzz_additional_processing_timeout.return_value = 1337 + return engine_impl + + def _get_engine_prepare_dist(self, success): + return monitoring_metrics.FUZZ_TASK_STEPS_DURATION.get({ + 'fuzzer': 'libFuzzer_fuzz', + 'job': 'libfuzzer_asan_test', + 'platform': environment.platform(), + 'runtime': environment.get_runtime().value, + 'step': 'engine_prepare', + 'success': success, + }) + + @mock.patch('clusterfuzz._internal.metrics.monitor.time') + def test_engine_prepare_accumulated_over_rounds(self, mock_monitor_time): + """Test that engine_prepare is tracked once per round and accumulated.""" + mock_time = helpers.MockTime(start_time=100.0) + mock_monitor_time.time.side_effect = mock_time.time + session = self._create_engine_fuzzing_session() + engine_impl = self._create_engine_impl() + + def prepare(*_): + mock_time.advance(1.5) + return engine.FuzzOptions('/corpus', ['arg'], {}) + + engine_impl.prepare.side_effect = prepare + + session.do_engine_fuzzing(engine_impl) + + # MAX_TESTCASES is 2, so there are two rounds of 1.5 seconds each. + self.assertEqual(2, engine_impl.prepare.call_count) + self.assertEqual( + datetime.timedelta(seconds=3), + session.steps_time_tracker.stats['engine_prepare']) + dist = self._get_engine_prepare_dist(success=True) + self.assertEqual(2, dist.count) + self.assertAlmostEqual(3.0, dist.sum) + self.assertEqual(0, self._get_engine_prepare_dist(success=False).count) + + def test_engine_prepare_exception(self): + """Test that an exception in engine prepare is tracked as a failure.""" + session = self._create_engine_fuzzing_session() + engine_impl = self._create_engine_impl() + engine_impl.prepare.side_effect = RuntimeError('prepare failed') + + with self.assertRaises(RuntimeError): + session.do_engine_fuzzing(engine_impl) + + engine_impl.fuzz.assert_not_called() + self.assertIn('engine_prepare', session.steps_time_tracker.stats) + # The task stops at the first failing round. + self.assertEqual(1, self._get_engine_prepare_dist(success=False).count) + self.assertEqual(0, self._get_engine_prepare_dist(success=True).count) + def test_basic(self): """Test basic fuzzing session.""" target = 'test_target' @@ -2213,7 +2298,7 @@ def test_run_engine_fuzzer(self): result, fuzzer_metadata, strategies = fuzz_task.run_engine_fuzzer( libfuzzer_engine.Engine(), 'test_fuzzer', corpus_directory, - testcase_directory) + testcase_directory, monitor.TimeStatTracker()) self.assertIn( 'ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000', result.logs)