Log minimization progress. (#4467)

In application logs for debugging and in testcase comments for user
understanding.

Bug: https://crbug.com/380264190

Author: letitz

src/clusterfuzz/_internal/bot/tasks/utasks/minimize_task.py

@@ -452,6 +452,9 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
   warmup_timeout = environment.get_value('WARMUP_TIMEOUT')
   required_arguments = environment.get_value('REQUIRED_APP_ARGS', '')
 
+  logs.info('Warming up for minimization, checking for crashes ' +
+            f'(thread count: {max_threads}).')
+
   # Add any testcase-specific required arguments if needed.
   additional_required_arguments = testcase.get_metadata(
       'additional_required_app_args')
@@ -474,6 +477,7 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
 
   saved_unsymbolized_crash_state, flaky_stack, crash_times = (
       check_for_initial_crash(test_runner, crash_retries, testcase))
+  logs.info(f'Warmup crashed {crash_times}/{crash_retries} times.')
 
   # If the warmup crash occurred but we couldn't reproduce this in with
   # multiple processes running in parallel, try to minimize single threaded.
@@ -490,6 +494,7 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
 
     saved_unsymbolized_crash_state, flaky_stack, crash_times = (
         check_for_initial_crash(test_runner, crash_retries, testcase))
+    logs.info(f'Single-threaded warmup crashed {crash_times} times.')
 
   if not crash_times:
     # We didn't crash at all. This might be a legitimately unreproducible
@@ -519,12 +524,13 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
 
   # Use the max crash time unless this would be greater than the max timeout.
   test_timeout = min(max(crash_times), max_timeout) + 1
-  logs.info(f'Using timeout {test_timeout} (was {max_timeout})')
+  logs.info(f'Using per-test timeout {test_timeout} (was {max_timeout})')
   test_runner.timeout = test_timeout
 
-  logs.info('Starting minimization.')
+  logs.info(f'Starting minimization with overall {deadline}s timeout.')
 
   if should_attempt_phase(testcase, MinimizationPhase.GESTURES):
+    logs.info('Starting gesture minimization phase.')
     gestures = minimize_gestures(test_runner, testcase)
 
     # We can't call check_deadline_exceeded_and_store_partial_minimized_testcase
@@ -547,39 +553,51 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
     minimize_task_output.minimization_phase = MinimizationPhase.MAIN_FILE
 
     if time.time() > test_runner.deadline:
+      logs.info('Timed out during gesture minimization.')
       return uworker_msg_pb2.Output(  # pylint: disable=no-member
           minimize_task_output=minimize_task_output,
           error_type=uworker_msg_pb2.ErrorType.  # pylint: disable=no-member
-          MINIMIZE_DEADLINE_EXCEEDED_IN_MAIN_FILE_PHASE)
+          MINIMIZE_DEADLINE_EXCEEDED_IN_MAIN_FILE_PHASE,
+          error_message='Timed out during gesture minimization.')
+
+    logs.info('Minimized gestures.')
 
   # Minimize the main file.
   data = utils.get_file_contents_with_fatal_error_on_failure(testcase_file_path)
   if should_attempt_phase(testcase, MinimizationPhase.MAIN_FILE):
+    logs.info('Starting main file minimization phase.')
     data = minimize_main_file(test_runner, testcase_file_path, data)
 
     if check_deadline_exceeded_and_store_partial_minimized_testcase(
         deadline, testcase, input_directory, file_list, data,
         testcase_file_path, minimize_task_input, minimize_task_output):
+      logs.info('Timed out during main file minimization.')
       return uworker_msg_pb2.Output(  # pylint: disable=no-member
           error_type=uworker_msg_pb2.ErrorType.MINIMIZE_DEADLINE_EXCEEDED,  # pylint: disable=no-member
+          error_message='Timed out during main file minimization.',
           minimize_task_output=minimize_task_output)
 
+    logs.info('Minimized main file.')
     testcase.set_metadata('minimization_phase', MinimizationPhase.FILE_LIST,
                           False)
     minimize_task_output.minimization_phase = MinimizationPhase.FILE_LIST
 
   # Minimize the file list.
   if should_attempt_phase(testcase, MinimizationPhase.FILE_LIST):
     if environment.get_value('MINIMIZE_FILE_LIST', True):
+      logs.info('Starting file list minimization phase.')
       file_list = minimize_file_list(test_runner, file_list, input_directory,
                                      testcase_file_path)
 
       if check_deadline_exceeded_and_store_partial_minimized_testcase(
           deadline, testcase, input_directory, file_list, data,
           testcase_file_path, minimize_task_input, minimize_task_output):
+        logs.info('Timed out during file list minimization.')
         return uworker_msg_pb2.Output(  # pylint: disable=no-member
             error_type=uworker_msg_pb2.ErrorType.MINIMIZE_DEADLINE_EXCEEDED,  # pylint: disable=no-member
+            error_message='Timed out during file list minimization.',
             minimize_task_output=minimize_task_output)
+      logs.info('Minimized file list.')
     else:
       logs.info('Skipping minimization of file list.')
 
@@ -590,16 +608,21 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
   # Minimize any files remaining in the file list.
   if should_attempt_phase(testcase, MinimizationPhase.RESOURCES):
     if environment.get_value('MINIMIZE_RESOURCES', True):
+      logs.info('Starting resources minimization phase.')
       for dependency in file_list:
         minimize_resource(test_runner, dependency, input_directory,
                           testcase_file_path)
 
         if check_deadline_exceeded_and_store_partial_minimized_testcase(
             deadline, testcase, input_directory, file_list, data,
             testcase_file_path, minimize_task_input, minimize_task_output):
+          logs.info('Timed out during resources minimization.')
           return uworker_msg_pb2.Output(  # pylint: disable=no-member
               error_type=uworker_msg_pb2.ErrorType.MINIMIZE_DEADLINE_EXCEEDED,  # pylint: disable=no-member
+              error_message='Timed out during resources minimization.',
               minimize_task_output=minimize_task_output)
+
+      logs.info('Minimized resources.')
     else:
       logs.info('Skipping minimization of resources.')
 
@@ -608,6 +631,7 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
     minimize_task_output.minimization_phase = MinimizationPhase.ARGUMENTS
 
   if should_attempt_phase(testcase, MinimizationPhase.ARGUMENTS):
+    logs.info('Starting arguments minimization phase.')
     app_arguments = minimize_arguments(test_runner, app_arguments)
 
     # Arguments must be stored here in case we time out below.
@@ -617,10 +641,16 @@ def utask_main(uworker_input: uworker_msg_pb2.Input):  # pylint: disable=no-memb
     if check_deadline_exceeded_and_store_partial_minimized_testcase(
         deadline, testcase, input_directory, file_list, data,
         testcase_file_path, minimize_task_input, minimize_task_output):
+      logs.info('Timed out during arguments minimization.')
       return uworker_msg_pb2.Output(  # pylint: disable=no-member
           error_type=uworker_msg_pb2.ErrorType.MINIMIZE_DEADLINE_EXCEEDED,  # pylint: disable=no-member
+          error_message='Timed out during arguments minimization.',
           minimize_task_output=minimize_task_output)
 
+    logs.info('Minimized arguments.')
+
+  logs.info('Finished minization.')
+
   command = testcase_manager.get_command_line_for_application(
       testcase_file_path, app_args=app_arguments, needs_http=testcase.http_flag)
   last_crash_result = test_runner.last_failing_result
@@ -748,6 +778,10 @@ def handle_minimize_crash_too_flaky(output):
 def handle_minimize_deadline_exceeded_in_main_file_phase(output):
   """Reschedules the minimize task when the deadline is exceeded just before
   starting the main file phase."""
+  testcase = data_handler.get_testcase_by_id(output.uworker_input.testcase_id)
+  data_handler.update_testcase_comment(
+      testcase, data_types.TaskState.WIP,
+      'Timed out before even minimizing the main file. Retrying.')
   tasks.add_task('minimize', output.uworker_input.testcase_id,
                  output.uworker_input.job_type)
 
@@ -762,6 +796,9 @@ def handle_minimize_deadline_exceeded(output: uworker_msg_pb2.Output):  # pylint
     _skip_minimization(testcase,
                        'Exceeded minimization deadline too many times.')
   else:
+    data_handler.update_testcase_comment(
+        testcase, data_types.TaskState.WIP,
+        output.error_message + f' Retrying (attempt #{attempts + 1}).')
     testcase.set_metadata('minimization_deadline_exceeded_attempts',
                           attempts + 1)
     tasks.add_task('minimize', output.uworker_input.testcase_id,