Fix/scorecard silent failure

collectoss/tasks/git/dependency_tasks/core.py

@@ -7,9 +7,13 @@
 from collectoss.tasks.git.dependency_tasks.dependency_util import dependency_calculator as dep_calc
 from collectoss.tasks.util.worker_util import parse_json_from_subprocess_call
 from collectoss.tasks.git.util.facade_worker.facade_worker.utilitymethods import get_absolute_repo_path
 from collectoss.tasks.github.util.github_random_key_auth import GithubRandomKeyAuth
 from collectoss.tasks.util.metadata_exception import MetadataException
 
+# scorecard clones the repo and runs every check against the forge API, so it is slow;
+# this bounds how long one repo may hold a secondary worker slot before it is given up on
+SCORECARD_TIMEOUT_SECONDS = 600
+
 
 def generate_deps_data(logger, repo_git):
         """Run dependency logic on repo and stores data in database
@@ -86,16 +90,19 @@
     key_handler = GithubApiKeyHandler(logger)       
     SystemEnv.set('GITHUB_AUTH_TOKEN', key_handler.get_random_key())
 
-    try: 
-        required_output = parse_json_from_subprocess_call(logger,['./scorecard', command, '--format=json'],cwd=path_to_scorecard)
-
+    required_output = None
+    try:
+        required_output = parse_json_from_subprocess_call(logger,['./scorecard', command, '--format=json'],cwd=path_to_scorecard,timeout=SCORECARD_TIMEOUT_SECONDS)
+
         logger.info('adding to database...')
         logger.debug(f"output: {required_output}")
 
         if not required_output.get('checks'):
-            logger.info('No scorecard checks found!')
-            return
-
+            raise MetadataException(
+                ValueError("scorecard returned no checks"),
+                f"no scorecard checks for {path}; output: {required_output}"
+            )
+
         #Store the overall score first
         to_insert = []
         overall_deps_scorecard = {
@@ -131,7 +138,11 @@
 
         logger.info(f"Done generating scorecard for repo {repo_id} from path {path}")
 
-    except Exception as e: 
-
+    except MetadataException:
+        # already carries the reason scorecard failed; re-wrapping would bury it
+        raise
+
+    except Exception as e:
+
         logger.exception("Error generating scorecard", exc_info=e)
         raise MetadataException(e, f"required_output: {required_output}; error {e}")

collectoss/tasks/util/metadata_exception.py

@@ -4,3 +4,9 @@ def __init__(self, original_exception, additional_metadata):
         self.additional_metadata = additional_metadata
 
         super().__init__(f"{str(self.original_exception)} | Additional metadata: {self.additional_metadata}")
+
+    def __reduce__(self):
+        # billiard pickles task exceptions to send them from the worker child to the
+        # parent; the default reduce replays __init__ with the single formatted message
+        # and fails on the missing second argument, masking the real failure
+        return (self.__class__, (self.original_exception, self.additional_metadata))

collectoss/tasks/util/worker_util.py

@@ -128,15 +128,28 @@
             #Else increase its weight
             return -1 * factor
 
-def parse_json_from_subprocess_call(logger, subprocess_arr, cwd=None):
+def parse_json_from_subprocess_call(logger, subprocess_arr, cwd=None, timeout=None):
     logger.info(f"running subprocess {subprocess_arr[0]}")
-    if cwd:
-        p = subprocess.run(subprocess_arr,cwd=cwd,capture_output=True, text=True, timeout=None)
-    else:
-        p = subprocess.run(subprocess_arr,capture_output=True, text=True, timeout=None)
-
+    try:
+        p = subprocess.run(subprocess_arr,cwd=cwd,capture_output=True, text=True, timeout=timeout)
+    except subprocess.TimeoutExpired as e:
+        logger.error(f"subprocess {subprocess_arr[0]} timed out after {timeout} seconds")
+        raise MetadataException(e, f"{subprocess_arr[0]} timed out after {timeout} seconds")
+
     logger.info('subprocess completed... ')
 
+    # the subprocess reports why it failed on stderr, so it always needs to reach the
+    # logs; without it a failed call is indistinguishable from one that found nothing
+    if p.stderr:
+        logger.warning(f"subprocess {subprocess_arr[0]} stderr: {p.stderr}")
+
+    if p.returncode != 0:
+        logger.error(f"subprocess {subprocess_arr[0]} exited with code {p.returncode}")
+        raise MetadataException(
+            subprocess.CalledProcessError(p.returncode, subprocess_arr, p.stdout, p.stderr),
+            f"{subprocess_arr[0]} exited with code {p.returncode}; stderr: {p.stderr}"
+        )
+
     output = p.stdout
 
     try: