diff --git a/collectoss/tasks/git/dependency_tasks/core.py b/collectoss/tasks/git/dependency_tasks/core.py index 0648231b0..127c059ea 100644 --- a/collectoss/tasks/git/dependency_tasks/core.py +++ b/collectoss/tasks/git/dependency_tasks/core.py @@ -10,6 +10,10 @@ 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 @@ def generate_scorecard(logger, repo_git): 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 @@ def generate_scorecard(logger, repo_git): 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}") diff --git a/collectoss/tasks/util/metadata_exception.py b/collectoss/tasks/util/metadata_exception.py index a861badac..1290e8240 100644 --- a/collectoss/tasks/util/metadata_exception.py +++ b/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)) diff --git a/collectoss/tasks/util/worker_util.py b/collectoss/tasks/util/worker_util.py index 1b30e66c5..7481384ac 100644 --- a/collectoss/tasks/util/worker_util.py +++ b/collectoss/tasks/util/worker_util.py @@ -128,15 +128,28 @@ def calculate_date_weight_from_timestamps(added,last_collection,domain_start_day #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: