[Android] Adding debug logs

src/clusterfuzz/_internal/bot/testcase_manager.py

@@ -336,6 +336,10 @@ def run_testcase(thread_index, file_path, gestures, env_copy):
     command = get_command_line_for_application(
         file_path, user_profile_index=thread_index, needs_http=needs_http)
 
+    logs.debug(
+        f'[TestcaseManager] Running testcase (thread {thread_index}): '
+        f'command={command}, needs_http={needs_http}, gestures={gestures}')
+
     # Run testcase.
     return process_handler.run_process(
         command,
@@ -1243,7 +1247,8 @@ def check_for_bad_build(job_type: str,
     os.environ['APP_ARGS'] = job_default_args
 
   try:
-    command = get_command_line_for_application(file_to_run='', needs_http=False)
+    command = get_command_line_for_application(
+        file_to_run='', needs_http=False, write_command_line_file=True)
   finally:
     if orig_app_args is not None:
       os.environ['APP_ARGS'] = orig_app_args
@@ -1273,30 +1278,26 @@ def check_for_bad_build(job_type: str,
   process_handler.terminate_stale_application_instances()
 
   # Check if the build is bad.
+  logs.info(
+      f'Starting bad build check for {job_type} at r{crash_revision} with '
+      f'command: {command} (timeout={fast_warmup_timeout})')
   return_code, crash_time, output = process_handler.run_process(
       command,
       timeout=fast_warmup_timeout,
       current_working_directory=app_directory)
   crash_result = CrashResult(return_code, crash_time, output)
+  logs.info(
+      f'Bad build check run_process completed: return_code={return_code}, '
+      f'is_crash={crash_result.is_crash(ignore_state=True)}, '
+      f'crash_type={crash_result.get_type()}')
 
   # 1. Need to account for startup crashes with no crash state. E.g. failed to
   #    load shared library. So, ignore state for comparison.
   # 2. Ignore leaks as they don't block a build from reporting regular crashes
   #    and also don't impact regression range calculations.
-  if (crash_result.is_crash(ignore_state=True) and
-      not crash_result.should_ignore() and
-      not crash_result.get_type() in ['Direct-leak', 'Indirect-leak']):
-    is_bad_build = True
-    build_run_console_output = utils.get_crash_stacktrace_output(
-        command,
-        crash_result.get_stacktrace(symbolized=True),
-        crash_result.get_stacktrace(symbolized=False))
-    logs.info(
-        f'Bad build for {job_type} detected at r{crash_revision}: ' +
-        f'return code = {return_code}, crash type = {crash_result.get_type()}',
-        raw_output=output,
-        output=build_run_console_output)
-  elif environment.is_android():
+  # 3. On Android, if the application process is not running after startup,
+  #    the build is bad.
+  if environment.is_android():
     package_name = android.app.get_package_name()
     if (package_name and
         not android.adb.get_process_and_child_pids(package_name)):
@@ -1309,6 +1310,20 @@ def check_for_bad_build(job_type: str,
           'startup.',
           raw_output=output,
           output=build_run_console_output)
+  elif (crash_result.is_crash(ignore_state=True) and
+        not crash_result.should_ignore() and
+        not crash_result.get_type() in ['Direct-leak', 'Indirect-leak']):
+
+    is_bad_build = True
+    build_run_console_output = utils.get_crash_stacktrace_output(
+        command,
+        crash_result.get_stacktrace(symbolized=True),
+        crash_result.get_stacktrace(symbolized=False))
+    logs.info(
+        f'Bad build for {job_type} detected at r{crash_revision}: ' +
+        f'return code = {return_code}, crash type = {crash_result.get_type()}',
+        raw_output=output,
+        output=build_run_console_output)
 
   # Exit all running instances.
   process_handler.terminate_stale_application_instances()

src/clusterfuzz/_internal/metrics/logs.py

@@ -53,6 +53,8 @@
 _is_already_handling_uncaught = False
 _default_extras = {}
 
+BASE_LOGGING_LEVEL = logging.DEBUG
+
 
 def _increment_error_count():
   """"Increment the error count metric."""
@@ -115,7 +117,7 @@ def get_handler_config(filename, backup_count):
 
   return {
       'class': 'logging.handlers.RotatingFileHandler',
-      'level': logging.INFO,
+      'level': BASE_LOGGING_LEVEL,
       'formatter': 'simple',
       'filename': file_path,
       'maxBytes': max_bytes,
@@ -396,7 +398,7 @@ def json_fields_filter(record):
 
 def configure_appengine():
   """Configure logging for App Engine."""
-  logging.getLogger().setLevel(logging.INFO)
+  logging.getLogger().setLevel(BASE_LOGGING_LEVEL)
 
   if os.getenv('LOCAL_DEVELOPMENT') or environment.is_running_unit_tests():
     return
@@ -458,12 +460,12 @@ def k8s_label_filter(record):
     return True
 
   handler.addFilter(k8s_label_filter)
-  handler.setLevel(logging.INFO)
+  handler.setLevel(BASE_LOGGING_LEVEL)
   formatter = JsonFormatter()
   handler.setFormatter(formatter)
 
   logging.getLogger().addHandler(handler)
-  logging.getLogger().setLevel(logging.INFO)
+  logging.getLogger().setLevel(BASE_LOGGING_LEVEL)
 
 
 def configure_cloud_logging():
@@ -527,7 +529,7 @@ def cloud_label_filter(record):
     return True
 
   handler.addFilter(cloud_label_filter)
-  handler.setLevel(logging.INFO)
+  handler.setLevel(BASE_LOGGING_LEVEL)
   formatter = JsonFormatter()
   handler.setFormatter(formatter)
 
@@ -549,7 +551,7 @@ def configure_swarming(name: str, extras: dict[str, str] | None = None) -> None:
     configure_cloud_logging()
 
   logger = logging.getLogger(name)
-  logger.setLevel(logging.INFO)
+  logger.setLevel(BASE_LOGGING_LEVEL)
   set_logger(logger)
 
   sys.excepthook = uncaught_exception_handler
@@ -574,13 +576,13 @@ def configure(name, extras=None):
     return
 
   if _console_logging_enabled():
-    logging.basicConfig(level=logging.INFO)
+    logging.basicConfig(level=BASE_LOGGING_LEVEL)
   if _file_logging_enabled():
     config.dictConfig(get_logging_config_dict(name))
   if _cloud_logging_enabled():
     configure_cloud_logging()
   logger = logging.getLogger(name)
-  logger.setLevel(logging.INFO)
+  logger.setLevel(BASE_LOGGING_LEVEL)
   set_logger(logger)
 
   # Set _default_extras so they can be used later.
@@ -769,6 +771,11 @@ def warning(message, **extras):
   emit(logging.WARN, message, exc_info=sys.exc_info(), **extras)
 
 
+def debug(message, **extras):
+  """Logs the debug message."""
+  emit(logging.DEBUG, message, **extras)
+
+
 def error(message, **extras):
   """Logs the error in the error log file."""
   exception = extras.pop('exception', None)

src/clusterfuzz/_internal/platforms/android/adb.py

@@ -679,14 +679,18 @@ def run_command(cmd, log_output=False, timeout=None, recover=True):
   if isinstance(cmd, list):
     cmd = ' '.join([str(i) for i in cmd])
   if log_output:
-    logs.info('Running: adb %s' % cmd)
+    logs.info(f'[ADB] Running: {cmd}')
+  else:
+    logs.debug(f'[ADB] Running: {cmd}')
   if not timeout:
     timeout = ADB_TIMEOUT
 
   output = execute_command(get_adb_command_line(cmd), timeout)
   if not recover:
     if log_output:
-      logs.info('Output: (%s)' % output)
+      logs.info(f'[ADB] Output for {cmd}: {output}')
+    else:
+      logs.debug(f'[ADB] Output for {cmd}: {output}')
     return output
 
   device_not_found_string_with_serial = DEVICE_NOT_FOUND_STRING.format(
@@ -915,3 +919,17 @@ def write_data_to_file(contents, file_path, should_reboot=True):
     else:
       # Manually revert /system to read-only since we aren't rebooting.
       run_shell_command('mount -o ro,remount /system', root=True)
+
+
+def get_activity_exit_info(app_package: str) -> str:
+  """Get dumpsys activity exit-info output for the given application package.
+
+  Args:
+    app_package: Name of the application package.
+
+  Returns:
+    Dumpsys output for the application package.
+  """
+  dumpsys_output = run_shell_command(
+      ['dumpsys', 'activity', 'exit-info', app_package])
+  return dumpsys_output

src/clusterfuzz/_internal/platforms/android/constants.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 """Common constants."""
 
+from enum import IntEnum
 import re
 
 DEVICE_DOWNLOAD_DIR = '/sdcard/Download'
@@ -86,3 +87,42 @@
 # Restrict pixel6 from picking up generic Android jobs to avoid
 # Binary Mismatch: Hence, 'ANDROID:PIXEL6' is added to the list.
 DEVICES_WITH_NO_FALLBACK_QUEUE_LIST = ['ANDROID:PIXEL6']
+
+
+class ExitReason(IntEnum):
+  """Android process exit reasons from ApplicationExitInfo. Taken from
+  https://developer.android.com/reference/android/app/ApplicationExitInfo
+  """
+
+  UNKNOWN = 0
+  EXIT_SELF = 1
+  SIGNALED = 2
+  LOW_MEMORY = 3
+  CRASH = 4
+  CRASH_NATIVE = 5
+  ANR = 6
+  INITIALIZATION_FAILURE = 7
+  PERMISSION_CHANGE = 8
+  EXCESSIVE_RESOURCE_USAGE = 9
+  USER_REQUESTED = 10
+  USER_STOPPED = 11
+  DEPENDENCY_DIED = 12
+  OTHER_KILLS_BY_SYSTEM = 13
+  FREEZER = 14
+  PACKAGE_STATE_CHANGE = 15
+  PACKAGE_UPDATED = 16
+  REASON_MEMORY_LIMITER = 17
+  REASON_ANOMALY = 18
+
+
+class ExitStatus(IntEnum):
+  """Process exit signal statuses corresponding to POSIX signals.
+
+  See: https://developer.android.com/reference/android/os/Process
+  """
+
+  SIGQUIT = 3
+  SIGILL = 4
+  SIGABRT = 6
+  SIGKILL = 9
+  SIGSEGV = 11

src/clusterfuzz/_internal/platforms/android/fetch_artifact.py

@@ -56,7 +56,7 @@ def _call_android_api_enabled():
   Disabled always if invoked in a uworker
   """
   if environment.is_uworker():
-    logs.info('AndroidBuildAPI access disabled for uworker.')
+    logs.debug('AndroidBuildAPI access disabled for uworker.')
     return False
 
   flag = feature_flags.FeatureFlags.CALL_ANDROID_API.flag
@@ -66,10 +66,10 @@ def _call_android_api_enabled():
 def _download_artifact(client, bid, target, attempt_id, name, output_directory,
                        output_filename):
   """Download one artifact."""
-  logs.info('reached download_artifact')
-  logs.info('artifact to download: %s' % name)
-  logs.info('output_directory: %s' % output_directory)
-  logs.info('output_filename: %s' % output_filename)
+  logs.debug('reached download_artifact')
+  logs.debug('artifact to download: %s' % name)
+  logs.debug('output_directory: %s' % output_directory)
+  logs.debug('output_filename: %s' % output_filename)
 
   logs.info(
       'AndroidBuildAPI download_artifact started.',
@@ -126,9 +126,9 @@ def _download_artifact(client, bid, target, attempt_id, name, output_directory,
         status='skipped_exists')
     return output_path
 
-  logs.info('Downloading artifact %s.' % name)
+  logs.debug('Downloading artifact %s.' % name)
   output_dir = os.path.dirname(output_path)
-  logs.info('Output dir: %s' % output_dir)
+  logs.debug('Output dir: %s' % output_dir)
   if not os.path.exists(output_dir):
     logs.info(f'Creating directory {output_dir}')
     os.makedirs(output_dir, exist_ok=True)
@@ -147,7 +147,7 @@ def _download_artifact(client, bid, target, attempt_id, name, output_directory,
   success = client.download_artifact_file(bid, target, attempt_id, name,
                                           output_path)
   if not success:
-    logs.error(
+    logs.warning(
         'AndroidBuildAPI download_artifact failed.',
         api_version=API_VERSION,
         operation='download_artifact',
@@ -185,7 +185,7 @@ def _get_artifacts_for_build(client,
         target=target)
     return []
 
-  logs.info(
+  logs.debug(
       'AndroidBuildAPI get_artifacts_for_build started.',
       api_version=API_VERSION,
       operation='get_artifacts_for_build',
@@ -196,7 +196,7 @@ def _get_artifacts_for_build(client,
 
   artifacts = client.list_artifacts(bid, target, attempt_id, regexp=regexp)
 
-  logs.info(
+  logs.debug(
       'AndroidBuildAPI get_artifacts_for_build completed.',
       api_version=API_VERSION,
       operation='get_artifacts_for_build',
@@ -219,13 +219,13 @@ def _get_client():
   build_apiary_service_account_private_key = db_config.get_value(
       'build_apiary_service_account_private_key')
   if not build_apiary_service_account_private_key:
-    logs.info(
+    logs.warning(
         'Android build apiary credentials are not set, skip artifact fetch.')
     return None
 
   key_dict = json.loads(build_apiary_service_account_private_key)
 
-  logs.info(
+  logs.debug(
       'AndroidBuildAPI client initialization started.', api_version=API_VERSION)
 
   try:
@@ -241,7 +241,7 @@ def _get_client():
 
 def _get_stable_build_info():
   """Return stable artifact for cuttlefish branch and target."""
-  logs.info('Reached get_stable_build_info')
+  logs.debug('Reached get_stable_build_info')
   stable_build_info = STABLE_CUTTLEFISH_BUILD
 
   try:
@@ -260,8 +260,7 @@ def _get_stable_build_info():
 def get_latest_artifact_info(branch, target, signed=False, stable_build=False):
   """Return latest artifact for a branch and target."""
   if not _call_android_api_enabled():
-    logs.warning(
-        'Android build API is disabled by feature flag call_android_api.')
+    logs.info('Android build API is disabled by feature flag call_android_api.')
     return None
 
   client = _get_client()

src/clusterfuzz/_internal/platforms/android/logger.py

@@ -124,3 +124,8 @@ def log_output(additional_flags=''):
 def log_output_before_last_reboot():
   """Return log data from last reboot without noise and some normalization."""
   return log_output(additional_flags='-L')
+
+
+def log_activity_manager_output():
+  """Return activity manager log output."""
+  return adb.run_command(['logcat', '-d', '-s', 'ActivityManager:I'])

src/clusterfuzz/_internal/platforms/android/symbols_downloader.py

@@ -198,8 +198,8 @@ def download_trusty_symbols_if_needed(symbols_directory, app_name, bid):
   if not bid:
     build_info = fetch_artifact.get_latest_artifact_info(branch, ab_target)
     if not build_info:
-      logs.error(f'Unable to fetch build info for branch {branch} '
-                 f'and target {ab_target}.')
+      logs.warning(f'Unable to fetch build info for branch {branch} '
+                   f'and target {ab_target}.')
       return
     bid = build_info['bid']