From d121aeb0d0700ac340d6b9558647b4981c7e42b3 Mon Sep 17 00:00:00 2001 From: Drew Bollinger Date: Mon, 29 Apr 2024 14:10:28 -0700 Subject: [PATCH] feat: save build container metrics to API --- requirements.txt | 1 - src/build.py | 74 ++++++----- src/log_utils/monitoring.py | 19 ++- src/log_utils/remote_logs.py | 13 ++ src/runner/__init__.py | 30 +++-- src/steps/build.py | 213 +++++++++++++++----------------- src/steps/fetch.py | 2 +- test/test_build.py | 232 ++++++++++++++--------------------- test/test_fetch.py | 5 +- test/test_runner.py | 89 +++++++++++--- 10 files changed, 361 insertions(+), 317 deletions(-) diff --git a/requirements.txt b/requirements.txt index ba04984f..a1ca2a5a 100644 --- a/requirements.txt +++ b/requirements.txt @@ -1,6 +1,5 @@ requests==2.31.0 boto3==1.14.20 -humanize==4.4.0 stopit==1.1.2 psycopg2==2.9.9 cryptography==42.0.2 diff --git a/src/build.py b/src/build.py index 59a9ed58..207110e6 100644 --- a/src/build.py +++ b/src/build.py @@ -5,6 +5,7 @@ from datetime import datetime from stopit import TimeoutException, SignalTimeout as Timeout import boto3 +from functools import partial from common import CLONE_DIR_PATH @@ -14,7 +15,8 @@ ) from log_utils.remote_logs import ( post_build_complete, post_build_error, - post_build_timeout, post_build_processing + post_build_timeout, post_build_processing, + post_metrics, ) from crypto.decrypt import decrypt @@ -92,8 +94,14 @@ def build( logger = get_logger('main') - def run_step(returncode, msg): - if returncode != 0: + # partially apply the callback url to post_metrics + post_metrics_p = partial(post_metrics, status_callback) + + def run_step(step, msg, *args, **kwargs): + try: + step(*args, **kwargs) + except Exception as e: + logger.error(e) raise StepException(msg) logger.info(f'Running build for {owner}/{repository}/{branch}') @@ -104,7 +112,11 @@ def run_step(returncode, msg): # start a separate scheduled thread for memory/cpu monitoring MONITORING_INTERVAL = 30 monitoring_logger = get_logger('monitor') - thread = RepeatTimer(MONITORING_INTERVAL, log_monitoring_metrics, [monitoring_logger]) + thread = RepeatTimer( + MONITORING_INTERVAL, + log_monitoring_metrics, + [monitoring_logger, post_metrics_p], + ) thread.start() # S3 client used in multiple steps @@ -119,8 +131,9 @@ def run_step(returncode, msg): # FETCH # run_step( - fetch_repo(owner, repository, branch, github_token), - 'There was a problem fetching the repository, see the above logs for details.' + fetch_repo, + 'There was a problem fetching the repository, see the above logs for details.', + owner, repository, branch, github_token, ) commit_sha = fetch_commit_sha(CLONE_DIR_PATH) @@ -141,57 +154,62 @@ def run_step(returncode, msg): if federalist_config.full_clone(): run_step( - update_repo(CLONE_DIR_PATH), - 'There was a problem updating the repository, see the above logs for details.' + update_repo, + 'There was a problem updating the repository, see the above logs for details.', + CLONE_DIR_PATH, ) ## # BUILD # run_step( - setup_node(federalist_config.should_cache(), bucket, s3_client), - 'There was a problem setting up Node, see the above logs for details.' + setup_node, + 'There was a problem setting up Node, see the above logs for details.', + federalist_config.should_cache(), + bucket, + s3_client, + post_metrics_p, ) # Run the npm `federalist` task (if it is defined) run_step( - run_build_script( - branch, owner, repository, site_prefix, baseurl, decrypted_uevs - ), - 'There was a problem running the federalist script, see the above logs for details.' + run_build_script, + 'There was a problem running the federalist script, see the above logs for details.', # noqa: E501 + branch, owner, repository, site_prefix, baseurl, decrypted_uevs, ) # Run the appropriate build engine based on generator if generator == 'jekyll': run_step( - setup_ruby(), - 'There was a problem setting up Ruby, see the above logs for details.' + setup_ruby, + 'There was a problem setting up Ruby, see the above logs for details.', + federalist_config.should_cache(), post_metrics_p, ) run_step( - setup_bundler(federalist_config.should_cache(), bucket, s3_client), - 'There was a problem setting up Bundler, see the above logs for details.' + setup_bundler, + 'There was a problem setting up Bundler, see the above logs for details.', + federalist_config.should_cache(), bucket, s3_client, ) run_step( - build_jekyll( - branch, owner, repository, site_prefix, baseurl, config, decrypted_uevs - ), - 'There was a problem running Jekyll, see the above logs for details.' + build_jekyll, + 'There was a problem running Jekyll, see the above logs for details.', + branch, owner, repository, site_prefix, baseurl, config, decrypted_uevs, ) elif generator == 'hugo': # extra: --hugo-version (not yet used) run_step( - download_hugo(), - 'There was a problem downloading Hugo, see the above logs for details.' + download_hugo, + 'There was a problem downloading Hugo, see the above logs for details.', + post_metrics_p ) run_step( - build_hugo( - branch, owner, repository, site_prefix, baseurl, decrypted_uevs - ), - 'There was a problem running Hugo, see the above logs for details.' + build_hugo, + 'There was a problem running Hugo, see the above logs for details.', + branch, owner, repository, site_prefix, baseurl, decrypted_uevs, ) elif generator == 'static': diff --git a/src/log_utils/monitoring.py b/src/log_utils/monitoring.py index 521fc2ca..400a9810 100644 --- a/src/log_utils/monitoring.py +++ b/src/log_utils/monitoring.py @@ -1,6 +1,11 @@ from threading import Timer import psutil -from humanize import naturalsize + +max_metrics = dict( + cpu=0, + mem=0, + disk=0 +) # https://stackoverflow.com/a/48741004 @@ -10,8 +15,12 @@ def run(self): self.function(*self.args, **self.kwargs) -def log_monitoring_metrics(logger): +def log_monitoring_metrics(logger, post_metrics): disk = psutil.disk_usage("/") - logger.info(f'CPU Usage Percentage: {psutil.cpu_percent()}') - logger.info(f'Memory Usage Percentage: {psutil.virtual_memory().percent}') - logger.info(f'Disk usage: {naturalsize(disk.used)} / {naturalsize(disk.total)}') + + # compute new maximum metrics and post to the application + max_metrics["cpu"] = max(psutil.cpu_percent(), max_metrics["cpu"]) + max_metrics["mem"] = max(psutil.virtual_memory().percent, max_metrics["mem"]) + max_metrics["disk"] = max(disk.used, max_metrics["disk"]) + + post_metrics(dict(machine=max_metrics)) diff --git a/src/log_utils/remote_logs.py b/src/log_utils/remote_logs.py index 9013c70c..9da52a9f 100644 --- a/src/log_utils/remote_logs.py +++ b/src/log_utils/remote_logs.py @@ -2,6 +2,7 @@ import base64 import requests +from typing import Dict from .common import (STATUS_COMPLETE, STATUS_ERROR, STATUS_PROCESSING) @@ -63,3 +64,15 @@ def post_build_timeout(status_callback_url, commit_sha=None): # Post to the Pages web application with status and output post_status(status_callback_url, status=STATUS_ERROR, output=output, commit_sha=commit_sha) + + +def post_metrics(status_callback_url: str, metrics: Dict): + ''' + POST build metrics to the metrics API + ''' + url = status_callback_url.replace('status', 'metrics') + requests.post( + url, + json=metrics, + timeout=10 + ) diff --git a/src/runner/__init__.py b/src/runner/__init__.py index 7659bec5..13e82866 100644 --- a/src/runner/__init__.py +++ b/src/runner/__init__.py @@ -3,6 +3,7 @@ import pwd import shlex import subprocess # nosec +from io import StringIO NVM_PATH = '~/.nvm/nvm.sh' RVM_PATH = '/usr/local/rvm/scripts/rvm' @@ -13,26 +14,24 @@ def setuser(): os.setuid(pwd.getpwnam('customer').pw_uid) -def run(logger, command, cwd=None, env=None, shell=False, check=False, node=False, ruby=False): +def run(logger, command, cwd=None, env=None, shell=False, check=True, node=False, ruby=False, skip_log=False): # noqa: E501 ''' Run an OS command with provided cwd or env, stream logs to logger, and return the exit code. Errors that occur BEFORE the command is actually executed are caught and handled here. - Errors encountered by the executed command are NOT caught. Instead a non-zero exit code - will be returned to be handled by the caller. + Errors encountered by the executed command are caught unless `check=False`. In these cases a + non-zero exit code will be returned to be handled by the caller. See https://docs.python.org/3/library/subprocess.html#popen-constructor for details. ''' - # TODO - refactor to put the appropriate bundler binaries in PATH so this isn't necessary if ruby: command = f'source {RVM_PATH} && {command}' shell = True - # TODO - refactor to put the appropriate node/npm binaries in PATH so this isn't necessary if node: - command = f'source {NVM_PATH} && nvm use default && {command}' + command = f'source {NVM_PATH} && {command}' shell = True if isinstance(command, str) and not shell: @@ -41,6 +40,9 @@ def run(logger, command, cwd=None, env=None, shell=False, check=False, node=Fals # When a shell is needed, use `bash` instead of `sh` executable = '/bin/bash' if shell else None + # aggregate stdout in case we need to return + output = StringIO() + try: p = subprocess.Popen( # nosec command, @@ -56,12 +58,20 @@ def run(logger, command, cwd=None, env=None, shell=False, check=False, node=Fals preexec_fn=setuser ) while p.poll() is None: - logger.info(p.stdout.readline().strip()) + line = p.stdout.readline().strip() + if not skip_log: + logger.info(line) + output.write(line) - logger.info(p.stdout.readline().strip()) + line = p.stdout.readline().strip() + if not skip_log: + logger.info(line) + output.write(line) - if check and p.returncode: - raise subprocess.CalledProcessError(p.returncode, command) + if check: + if p.returncode: + raise subprocess.CalledProcessError(p.returncode, command) + return output.getvalue() return p.returncode diff --git a/src/steps/build.py b/src/steps/build.py index ae60cd58..93a96b15 100644 --- a/src/steps/build.py +++ b/src/steps/build.py @@ -7,7 +7,6 @@ import requests import shlex import subprocess # nosec -from subprocess import CalledProcessError # nosec import time import yaml @@ -99,9 +98,10 @@ def has_build_script(script_name): return False -def is_supported_ruby_version(version): +def check_supported_ruby_version(version): ''' Checks if the version defined in .ruby-version is supported + Raises a generic exception if not ''' is_supported = 0 @@ -109,31 +109,30 @@ def is_supported_ruby_version(version): logger = get_logger('setup-ruby') RUBY_VERSION_MIN = os.getenv('RUBY_VERSION_MIN') - is_supported = run( logger, f'ruby -e "exit Gem::Version.new(\'{shlex.split(version)[0]}\') >= Gem::Version.new(\'{RUBY_VERSION_MIN}\') ? 1 : 0"', # noqa: E501 cwd=CLONE_DIR_PATH, env={}, - ruby=True + ruby=True, + check=False, ) upgrade_msg = 'Please upgrade to an actively supported version, see https://www.ruby-lang.org/en/downloads/branches/ for details.' # noqa: E501 - if not is_supported: - logger.error( - 'ERROR: Unsupported ruby version specified in .ruby-version.') - logger.error(upgrade_msg) - if version == RUBY_VERSION_MIN: logger.warning( f'WARNING: Ruby {RUBY_VERSION_MIN} will soon reach end-of-life, at which point Pages will no longer support it.') # noqa: E501 logger.warning(upgrade_msg) - return is_supported + if not is_supported: + error = 'ERROR: Unsupported ruby version specified in .ruby-version.' + logger.error(error) + logger.error(upgrade_msg) + raise Exception(error) -def setup_node(should_cache: bool, bucket, s3_client): +def setup_node(should_cache: bool, bucket, s3_client, post_metrics): ''' Sets up node and installs dependencies. @@ -142,67 +141,69 @@ def setup_node(should_cache: bool, bucket, s3_client): ''' logger = get_logger('setup-node') - def runp(cmd): - return run(logger, cmd, cwd=CLONE_DIR_PATH, env={}, check=True, node=True) - - try: - NVMRC_PATH = CLONE_DIR_PATH / NVMRC - if NVMRC_PATH.is_file(): - # nvm will output the node and npm versions used - # the warning is currently non-reachable but leaving it in for October 2024 - # to warn about node 18 EOL - logger.info('Checking node version specified in .nvmrc') - runp(""" - RAW_VERSION=$(nvm version-remote $(cat .nvmrc)) - MAJOR_VERSION=$(echo $RAW_VERSION | cut -d. -f 1 | cut -dv -f 2) - if [[ "$MAJOR_VERSION" =~ ^(18|20)$ ]]; then - echo "Switching to node version $RAW_VERSION specified in .nvmrc" - - if [[ "$MAJOR_VERSION" -eq 16 ]]; then - echo "WARNING: Node $RAW_VERSION will reach end-of-life on 9-11-2023, at which point Pages will no longer support it." - echo "Please upgrade to LTS major version 18 or 20, see https://nodejs.org/en/about/releases/ for details." - fi - - nvm install $RAW_VERSION - nvm alias default $RAW_VERSION - else - echo "Unsupported node major version '$MAJOR_VERSION' specified in .nvmrc." + def runp(cmd, skip_log=False): + return run(logger, cmd, cwd=CLONE_DIR_PATH, env={}, node=True, skip_log=skip_log) + + NVMRC_PATH = CLONE_DIR_PATH / NVMRC + if NVMRC_PATH.is_file(): + # nvm will output the node and npm versions used + # the warning is currently non-reachable but leaving it in for October 2024 + # to warn about node 18 EOL + logger.info('Checking node version specified in .nvmrc') + runp(""" + RAW_VERSION=$(nvm version-remote $(cat .nvmrc)) + MAJOR_VERSION=$(echo $RAW_VERSION | cut -d. -f 1 | cut -dv -f 2) + if [[ "$MAJOR_VERSION" =~ ^(18|20)$ ]]; then + echo "Switching to node version $RAW_VERSION specified in .nvmrc" + + if [[ "$MAJOR_VERSION" -eq 16 ]]; then + echo "WARNING: Node $RAW_VERSION will reach end-of-life on 9-11-2023, at which point Pages will no longer support it." echo "Please upgrade to LTS major version 18 or 20, see https://nodejs.org/en/about/releases/ for details." - exit 1 fi - """) # noqa: E501 + + nvm install $RAW_VERSION + nvm alias default $RAW_VERSION + else + echo "Unsupported node major version '$MAJOR_VERSION' specified in .nvmrc." + echo "Please upgrade to LTS major version 18 or 20, see https://nodejs.org/en/about/releases/ for details." + exit 1 + fi + """) # noqa: E501 + else: + # output node and npm versions if the defaults are used + logger.info('Using default node version') + runp('nvm alias default $(nvm version)') + runp('echo Node version: $(node --version)') + runp('echo NPM version: $(npm --version)') + + # capture version and cache + node_version = runp('node --version', skip_log=True) + post_metrics({ + "engines": { + "node": dict(version=node_version, cache=should_cache) + } + }) + + cache_folder = None + PACKAGE_LOCK_PATH = CLONE_DIR_PATH / PACKAGE_LOCK + if PACKAGE_LOCK_PATH.is_file(): + if should_cache: + logger.info(f'{PACKAGE_LOCK} found. Attempting to download cache') + NM_FOLDER = CLONE_DIR_PATH / NODE_MODULES + cache_folder = CacheFolder(PACKAGE_LOCK_PATH, NM_FOLDER, bucket, s3_client, logger) + cache_folder.download_unzip() + + if PACKAGE_LOCK_PATH.is_file(): + if should_cache and cache_folder.exists(): + logger.info('skipping npm ci and using cache') else: - # output node and npm versions if the defaults are used - logger.info('Using default node version') - runp('nvm alias default $(nvm version)') - runp('echo Node version: $(node --version)') - runp('echo NPM version: $(npm --version)') - - cache_folder = None - PACKAGE_LOCK_PATH = CLONE_DIR_PATH / PACKAGE_LOCK - if PACKAGE_LOCK_PATH.is_file(): - if should_cache: - logger.info(f'{PACKAGE_LOCK} found. Attempting to download cache') - NM_FOLDER = CLONE_DIR_PATH / NODE_MODULES - cache_folder = CacheFolder(PACKAGE_LOCK_PATH, NM_FOLDER, bucket, s3_client, logger) - cache_folder.download_unzip() - - if PACKAGE_LOCK_PATH.is_file(): - if should_cache and cache_folder.exists(): - logger.info('skipping npm ci and using cache') - else: - logger.info('Installing dependencies in package-lock.json') - runp('npm set audit false') - runp('npm ci') - - if PACKAGE_LOCK_PATH.is_file() and should_cache: - if not cache_folder.exists(): - cache_folder.zip_upload_folder_to_s3() - - except (CalledProcessError, OSError, ValueError): - return 1 - - return 0 + logger.info('Installing dependencies in package-lock.json') + runp('npm set audit false') + runp('npm ci') + + if PACKAGE_LOCK_PATH.is_file() and should_cache: + if not cache_folder.exists(): + cache_folder.zip_upload_folder_to_s3() def run_build_script(branch, owner, repository, site_prefix, @@ -217,12 +218,11 @@ def run_build_script(branch, owner, repository, site_prefix, logger = get_logger(f'run-{script_name}-script') logger.info(f'Running {script_name} build script in package.json') env = build_env(branch, owner, repository, site_prefix, base_url, user_env_vars) - return run(logger, f'npm run {script_name}', cwd=CLONE_DIR_PATH, env=env, node=True) + run(logger, f'npm run {script_name}', cwd=CLONE_DIR_PATH, env=env, node=True) + return - return 0 - -def download_hugo(): +def download_hugo(post_metrics): logger = get_logger('download-hugo') HUGO_VERSION_PATH = CLONE_DIR_PATH / HUGO_VERSION @@ -240,6 +240,11 @@ def download_hugo(): if hugo_version: logger.info(f'Using hugo version in .hugo-version: {hugo_version}') + post_metrics({ + "engines": { + "hugo": dict(version=hugo_version) + } + }) else: raise RuntimeError(".hugo-version not found") ''' @@ -260,9 +265,9 @@ def download_hugo(): hugo_tar.write(chunk) HUGO_BIN_PATH = WORKING_DIR_PATH / HUGO_BIN - run(logger, f'tar -xzf {hugo_tar_path} -C {WORKING_DIR_PATH}', env={}, check=True) - run(logger, f'chmod +x {HUGO_BIN_PATH}', env={}, check=True) - return 0 + run(logger, f'tar -xzf {hugo_tar_path} -C {WORKING_DIR_PATH}', env={}) + run(logger, f'chmod +x {HUGO_BIN_PATH}', env={}) + return except Exception: failed_attempts += 1 logger.info( @@ -282,7 +287,7 @@ def build_hugo(branch, owner, repository, site_prefix, HUGO_BIN_PATH = WORKING_DIR_PATH / HUGO_BIN - run(logger, f'echo hugo version: $({HUGO_BIN_PATH} version)', env={}, check=True) + run(logger, f'echo hugo version: $({HUGO_BIN_PATH} version)', env={}) logger.info('Building site with hugo') @@ -291,10 +296,10 @@ def build_hugo(branch, owner, repository, site_prefix, hugo_args += f' --baseURL {base_url}' env = build_env(branch, owner, repository, site_prefix, base_url, user_env_vars) - return run(logger, f'{HUGO_BIN_PATH} {hugo_args}', cwd=CLONE_DIR_PATH, env=env, node=True) + run(logger, f'{HUGO_BIN_PATH} {hugo_args}', cwd=CLONE_DIR_PATH, env=env, node=True) -def setup_ruby(): +def setup_ruby(should_cache, post_metrics): ''' Sets up RVM and installs ruby Uses the ruby version specified in .ruby-version if present @@ -302,10 +307,8 @@ def setup_ruby(): logger = get_logger('setup-ruby') - def runp(cmd): - return run(logger, cmd, cwd=CLONE_DIR_PATH, env={}, ruby=True) - - returncode = 0 + def runp(cmd, skip_log=False): + return run(logger, cmd, cwd=CLONE_DIR_PATH, env={}, ruby=True, skip_log=skip_log) RUBY_VERSION_PATH = CLONE_DIR_PATH / RUBY_VERSION if RUBY_VERSION_PATH.is_file(): @@ -315,15 +318,16 @@ def runp(cmd): # escape-quote the value in case there's anything weird # in the .ruby-version file ruby_version = shlex.quote(ruby_version) - if is_supported_ruby_version(ruby_version): - returncode = runp(f'rvm install {ruby_version}') - else: - returncode = 1 - - if returncode: - return returncode + check_supported_ruby_version(ruby_version) + runp(f'rvm install {ruby_version}') - return runp('echo Ruby version: $(ruby -v)') + ruby_version = runp('ruby -v', skip_log=True) + post_metrics({ + "engines": { + "ruby": dict(version=ruby_version, cache=should_cache) + } + }) + runp('echo Ruby version: $(ruby -v)') def setup_bundler(should_cache: bool, bucket, s3_client): @@ -360,10 +364,7 @@ def runp(cmd): except Exception: raise RuntimeError('Invalid .bundler-version') - returncode = runp(f'gem install bundler --version "{version}"') - - if returncode: - return returncode + runp(f'gem install bundler --version "{version}"') cache_folder = None if GEMFILELOCK_PATH.is_file() and should_cache: @@ -381,10 +382,7 @@ def runp(cmd): cache_folder.download_unzip() logger.info('Installing dependencies in Gemfile') - returncode = runp('bundle install') - - if returncode: - return returncode + runp('bundle install') if GEMFILELOCK_PATH.is_file() and should_cache: # we also need to check for cache_folder here because we shouldn't cache if they didn't @@ -392,8 +390,6 @@ def runp(cmd): if cache_folder and not cache_folder.exists(): cache_folder.zip_upload_folder_to_s3() - return returncode - def update_jekyll_config(federalist_config={}, custom_config_path=''): logger = get_logger('build-jekyll') @@ -409,16 +405,15 @@ def update_jekyll_config(federalist_config={}, custom_config_path=''): try: custom_config = json.loads(custom_config_path) except json.JSONDecodeError: - logger.error('Could not load/parse custom yaml config.') - return 1 + error = 'Could not load/parse custom yaml config.' + logger.error(error) + raise Exception(error) config_yml = {**config_yml, **custom_config, **federalist_config} with JEKYLL_CONF_YML_PATH.open('w') as jekyll_conf_file: yaml.dump(config_yml, jekyll_conf_file, default_flow_style=False) - return 0 - def build_jekyll(branch, owner, repository, site_prefix, base_url='', config='', user_env_vars=[]): @@ -427,14 +422,11 @@ def build_jekyll(branch, owner, repository, site_prefix, ''' logger = get_logger('build-jekyll') - result = update_jekyll_config( + update_jekyll_config( dict(baseurl=base_url, branch=branch), config ) - if result != 0: - return result - jekyll_cmd = 'jekyll' GEMFILE_PATH = CLONE_DIR_PATH / GEMFILE @@ -446,14 +438,13 @@ def build_jekyll(branch, owner, repository, site_prefix, f'echo Building using Jekyll version: $({jekyll_cmd} -v)', cwd=CLONE_DIR_PATH, env={}, - check=True, ruby=True ) env = build_env(branch, owner, repository, site_prefix, base_url, user_env_vars) env['JEKYLL_ENV'] = 'production' - return run( + run( logger, f'{jekyll_cmd} build --destination {SITE_BUILD_DIR_PATH}', cwd=CLONE_DIR_PATH, diff --git a/src/steps/fetch.py b/src/steps/fetch.py index 30b27133..28e62136 100644 --- a/src/steps/fetch.py +++ b/src/steps/fetch.py @@ -50,7 +50,7 @@ def fetch_repo(owner, repository, branch, github_token=''): # nosec f'{CLONE_DIR_PATH}' ) - return run(logger, command, env=clone_env) + return run(logger, command, env=clone_env, check=False) def update_repo(clone_dir): diff --git a/test/test_build.py b/test/test_build.py index 60640d7c..5f2b8a09 100644 --- a/test/test_build.py +++ b/test/test_build.py @@ -1,7 +1,7 @@ import json import os from io import StringIO -from unittest.mock import call, patch +from unittest.mock import call, patch, Mock from subprocess import CalledProcessError # nosec import pytest @@ -15,7 +15,7 @@ run_build_script, setup_bundler, setup_node, setup_ruby ) from steps.build import ( - build_env, is_supported_ruby_version, BUNDLER_VERSION, GEMFILE, + build_env, check_supported_ruby_version, BUNDLER_VERSION, GEMFILE, GEMFILELOCK, HUGO_BIN, HUGO_VERSION, JEKYLL_CONFIG_YML, NVMRC, PACKAGE_JSON, PACKAGE_LOCK, RUBY_VERSION ) @@ -40,7 +40,7 @@ def patch_site_build_dir(monkeypatch): @pytest.fixture def patch_ruby_min_version(monkeypatch): - monkeypatch.setenv('RUBY_VERSION_MIN', '2.6.6') + monkeypatch.setenv('RUBY_VERSION_MIN', '3.0.0') @patch('steps.build.run') @@ -49,9 +49,8 @@ class TestSetupNode(): def test_it_uses_nvmrc_file_if_it_exists(self, mock_get_logger, mock_run, patch_clone_dir): create_file(patch_clone_dir / NVMRC, contents='6') - result = setup_node(False, None, None) - - assert result == 0 + mock_post_metrics = Mock() + setup_node(False, None, None, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-node') @@ -61,12 +60,13 @@ def test_it_uses_nvmrc_file_if_it_exists(self, mock_get_logger, mock_run, patch_ 'Checking node version specified in .nvmrc' ) + mock_post_metrics.assert_called_once() + def test_installs_deps(self, mock_get_logger, mock_run, patch_clone_dir): create_file(patch_clone_dir / PACKAGE_LOCK) - result = setup_node(False, None, None) - - assert result == 0 + mock_post_metrics = Mock() + setup_node(False, None, None, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-node') @@ -77,22 +77,25 @@ def test_installs_deps(self, mock_get_logger, mock_run, patch_clone_dir): call('Installing dependencies in package-lock.json') ]) - def callp(cmd): - return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, check=True, node=True) + def callp(cmd, skip_log=False): + return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, node=True, skip_log=skip_log) mock_run.assert_has_calls([ callp('echo Node version: $(node --version)'), callp('echo NPM version: $(npm --version)'), + callp('node --version', skip_log=True), callp('npm set audit false'), callp('npm ci'), ]) + mock_post_metrics.assert_called_once() + def test_returns_code_when_err(self, mock_get_logger, mock_run): mock_run.side_effect = CalledProcessError(1, 'command') - result = setup_node(False, None, None) - - assert result == 1 + mock_post_metrics = Mock() + with pytest.raises(CalledProcessError): + setup_node(False, None, None, mock_post_metrics) @patch('steps.build.run') @@ -115,9 +118,7 @@ def test_it_runs_federalist_script_when_it_exists(self, mock_get_logger, mock_ru base_url='/site/prefix' ) - result = run_build_script(**kwargs) - - assert result == mock_run.return_value + run_build_script(**kwargs) mock_get_logger.assert_called_once_with('run-federalist-script') @@ -152,9 +153,7 @@ def test_it_runs_pages_script_when_it_exists(self, mock_get_logger, mock_run, base_url='/site/prefix' ) - result = run_build_script(**kwargs) - - assert result == mock_run.return_value + run_build_script(**kwargs) mock_get_logger.assert_called_once_with('run-pages-script') @@ -190,9 +189,7 @@ def test_it_only_runs_pages_script_when_both_exist(self, mock_get_logger, mock_r base_url='/site/prefix' ) - result = run_build_script(**kwargs) - - assert result == mock_run.return_value + run_build_script(**kwargs) mock_get_logger.assert_called_once_with('run-pages-script') @@ -211,9 +208,7 @@ def test_it_only_runs_pages_script_when_both_exist(self, mock_get_logger, mock_r ) def test_it_does_not_run_otherwise(self, mock_get_logger, mock_run): - result = run_build_script('b', 'o', 'r', 'sp') - - assert result == 0 + run_build_script('b', 'o', 'r', 'sp') mock_get_logger.assert_not_called() mock_run.assert_not_called() @@ -221,132 +216,106 @@ def test_it_does_not_run_otherwise(self, mock_get_logger, mock_run): @patch('steps.build.run') @patch('steps.build.get_logger') -@patch('steps.build.is_supported_ruby_version') +@patch('steps.build.check_supported_ruby_version') class TestSetupRuby(): - def test_no_ruby_version_file(self, mock_is_supported_ruby_version, + def test_no_ruby_version_file(self, mock_check_supported_ruby_version, mock_get_logger, mock_run, patch_clone_dir): - mock_is_supported_ruby_version.return_value = 1 - - result = setup_ruby() - - assert result == mock_run.return_value + mock_post_metrics = Mock() + setup_ruby(False, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-ruby') - mock_logger = mock_get_logger.return_value - mock_run.assert_called_once_with( - mock_logger, - 'echo Ruby version: $(ruby -v)', - cwd=patch_clone_dir, - env={}, - ruby=True - ) + mock_post_metrics.assert_called_once() + + def callp(cmd, skip_log=False): + return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, ruby=True, skip_log=skip_log) + + mock_run.assert_has_calls([ + callp('ruby -v', skip_log=True), + callp('echo Ruby version: $(ruby -v)') + ]) def test_it_uses_ruby_version_if_it_exists(self, - mock_is_supported_ruby_version, + mock_check_supported_ruby_version, mock_get_logger, mock_run, patch_clone_dir): - mock_is_supported_ruby_version.return_value = 1 - - version = '2.3' + version = '3.1' create_file(patch_clone_dir / RUBY_VERSION, version) - mock_run.return_value = 0 - - result = setup_ruby() - - assert result == 0 + mock_post_metrics = Mock() + setup_ruby(False, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-ruby') mock_logger = mock_get_logger.return_value - def callp(cmd): - return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, ruby=True) + def callp(cmd, skip_log=False): + return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, ruby=True, skip_log=skip_log) mock_run.assert_has_calls([ callp(f'rvm install {version}'), + callp('ruby -v', skip_log=True), callp('echo Ruby version: $(ruby -v)') ]) def test_it_strips_and_quotes_ruby_version(self, - mock_is_supported_ruby_version, + mock_check_supported_ruby_version, mock_get_logger, mock_run, patch_clone_dir): - mock_is_supported_ruby_version.return_value = 1 - - version = ' $2.3 ' - + version = ' $3.1 ' create_file(patch_clone_dir / RUBY_VERSION, version) - mock_run.return_value = 0 - - result = setup_ruby() - - assert result == 0 + mock_post_metrics = Mock() + setup_ruby(False, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-ruby') mock_logger = mock_get_logger.return_value - def callp(cmd): - return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, ruby=True) + def callp(cmd, skip_log=False): + return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, ruby=True, skip_log=skip_log) mock_logger.info.assert_has_calls([ call('Using ruby version in .ruby-version'), ]) mock_run.assert_has_calls([ - callp("rvm install '$2.3'"), + callp("rvm install '$3.1'"), + callp('ruby -v', skip_log=True), callp('echo Ruby version: $(ruby -v)'), ]) - def test_it_returns_error_code_when_rvm_install_fails(self, - mock_is_supported_ruby_version, - mock_get_logger, mock_run, - patch_clone_dir): - - mock_is_supported_ruby_version.return_value = 1 - - version = '2.3' - - mock_run.return_value = 1 + def test_it_errors_when_rvm_install_fails(self, + mock_check_supported_ruby_version, + mock_get_logger, mock_run, + patch_clone_dir): + version = '3.1' create_file(patch_clone_dir / RUBY_VERSION, version) - result = setup_ruby() + error = 'error installing ruby' + mock_run.side_effect = Exception(error) - assert result == 1 + mock_post_metrics = Mock() + with pytest.raises(Exception) as einfo: + setup_ruby(False, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-ruby') - mock_logger = mock_get_logger.return_value - - mock_logger.info.assert_has_calls([ - call('Using ruby version in .ruby-version'), - ]) - - mock_run.assert_called_once_with( - mock_logger, 'rvm install 2.3', cwd=patch_clone_dir, env={}, ruby=True - ) + assert str(einfo.value).strip() == error def test_it_outputs_warning_if_eol_approaching(self, - mock_is_supported_ruby_version, + mock_check_supported_ruby_version, mock_get_logger, mock_run, patch_ruby_min_version): min_ruby_version = os.getenv('RUBY_VERSION_MIN') - - mock_run.return_value = 1 - - result = is_supported_ruby_version(min_ruby_version) - - assert result == 1 + check_supported_ruby_version(min_ruby_version) mock_logger = mock_get_logger.return_value @@ -357,15 +326,16 @@ def test_it_outputs_warning_if_eol_approaching(self, ]) def test_it_outputs_warning_if_not_supported(self, - mock_is_supported_ruby_version, - mock_get_logger, mock_run): + mock_check_supported_ruby_version, + mock_get_logger, mock_run, patch_ruby_min_version): version = '2.3' - mock_run.return_value = 0 - result = is_supported_ruby_version(version) + with pytest.raises(Exception) as einfo: + check_supported_ruby_version(version) - assert result == 0 + error = 'ERROR: Unsupported ruby version specified in .ruby-version.' + assert str(einfo.value).strip() == error mock_logger = mock_get_logger.return_value @@ -379,9 +349,7 @@ def test_it_outputs_warning_if_not_supported(self, @patch('steps.build.get_logger') class TestSetupBundler(): def test_when_no_gemfile_just_load_jekyll(self, mock_get_logger, mock_run, patch_clone_dir): - result = setup_bundler(False, None, None) - - assert result == mock_run.return_value + setup_bundler(False, None, None) mock_get_logger.assert_called_once_with('setup-bundler') @@ -403,9 +371,7 @@ def test_it_uses_default_version_if_only_gemfile_exits(self, mock_get_logger, mock_run.return_value = 0 - result = setup_bundler(False, None, None) - - assert result == 0 + setup_bundler(False, None, None) mock_get_logger.assert_called_once_with('setup-bundler') @@ -433,9 +399,7 @@ def test_it_uses_bundler_version_if_gemfile_and_bundler_file_exists(self, mock_g mock_run.return_value = 0 - result = setup_bundler(False, None, None) - - assert result == 0 + setup_bundler(False, None, None) mock_get_logger.assert_called_once_with('setup-bundler') @@ -471,9 +435,7 @@ def test_with_no_gemfile(self, mock_get_logger, mock_run, patch_clone_dir, base_url='/site/prefix', config=json.dumps(dict(boop='beep')) ) - result = build_jekyll(**kwargs) - - assert result == mock_run.return_value + build_jekyll(**kwargs) mock_get_logger.assert_has_calls([call('build-jekyll'), call('build-jekyll')]) @@ -491,7 +453,6 @@ def test_with_no_gemfile(self, mock_get_logger, mock_run, patch_clone_dir, f'echo Building using Jekyll version: $({command} -v)', cwd=patch_clone_dir, env={}, - check=True, ruby=True, ), call( @@ -516,9 +477,7 @@ def test_with_gemfile(self, mock_get_logger, mock_run, patch_clone_dir, patch_si base_url='/site/prefix', config=json.dumps(dict(boop='beep')) ) - result = build_jekyll(**kwargs) - - assert result == mock_run.return_value + build_jekyll(**kwargs) mock_get_logger.assert_has_calls([call('build-jekyll'), call('build-jekyll')]) @@ -536,7 +495,6 @@ def test_with_gemfile(self, mock_get_logger, mock_run, patch_clone_dir, patch_si f'echo Building using Jekyll version: $({command} -v)', cwd=patch_clone_dir, env={}, - check=True, ruby=True, ), call( @@ -580,14 +538,14 @@ def test_it_is_callable(self, mock_get_logger, mock_run, patch_working_dir, patc 'https://github.com/gohugoio/hugo/releases/download/v' f'{version}/hugo_{version}_Linux-64bit.tar.gz' ) + print(dl_url) create_file(patch_clone_dir / HUGO_VERSION, version) + mock_post_metrics = Mock() with requests_mock.Mocker() as m: m.get(dl_url, text='fake-data') - result = download_hugo() - - assert result == 0 + download_hugo(mock_post_metrics) mock_get_logger.assert_called_once_with('download-hugo') @@ -600,8 +558,8 @@ def test_it_is_callable(self, mock_get_logger, mock_run, patch_working_dir, patc ]) mock_run.assert_has_calls([ - call(mock_logger, tar_cmd, env={}, check=True), - call(mock_logger, chmod_cmd, env={}, check=True) + call(mock_logger, tar_cmd, env={}), + call(mock_logger, chmod_cmd, env={}) ]) def test_it_is_callable_retry(self, mock_get_logger, mock_run, patch_working_dir, @@ -616,6 +574,7 @@ def test_it_is_callable_retry(self, mock_get_logger, mock_run, patch_working_dir create_file(patch_clone_dir / HUGO_VERSION, version) + mock_post_metrics = Mock() with requests_mock.Mocker() as m: m.get(dl_url, [ dict(exc=requests.exceptions.ConnectTimeout), @@ -625,9 +584,7 @@ def test_it_is_callable_retry(self, mock_get_logger, mock_run, patch_working_dir dict(text='fake-data') ]) - result = download_hugo() - - assert result == 0 + download_hugo(mock_post_metrics) mock_get_logger.assert_called_once_with('download-hugo') @@ -644,8 +601,8 @@ def test_it_is_callable_retry(self, mock_get_logger, mock_run, patch_working_dir ]) mock_run.assert_has_calls([ - call(mock_logger, tar_cmd, env={}, check=True), - call(mock_logger, chmod_cmd, env={}, check=True) + call(mock_logger, tar_cmd, env={}), + call(mock_logger, chmod_cmd, env={}) ]) def test_it_is_exception(self, mock_get_logger, mock_run, patch_working_dir, patch_clone_dir): @@ -657,6 +614,7 @@ def test_it_is_exception(self, mock_get_logger, mock_run, patch_working_dir, pat create_file(patch_clone_dir / HUGO_VERSION, version) + mock_post_metrics = Mock() with pytest.raises(Exception): with requests_mock.Mocker() as m: m.get(dl_url, [ @@ -667,7 +625,7 @@ def test_it_is_exception(self, mock_get_logger, mock_run, patch_working_dir, pat dict(exc=requests.exceptions.ConnectTimeout), ]) - download_hugo() + download_hugo(mock_post_metrics) mock_get_logger.assert_called_once_with('download-hugo') @@ -709,9 +667,7 @@ def test_it_calls_hugo_as_expected(self, mock_get_logger, mock_run, base_url='/site/prefix' ) - result = build_hugo(**kwargs) - - assert result == mock_run.return_value + build_hugo(**kwargs) mock_get_logger.assert_called_once_with('build-hugo') @@ -726,14 +682,13 @@ def test_it_calls_hugo_as_expected(self, mock_get_logger, mock_run, mock_logger, f'echo hugo version: $({hugo_path} version)', env={}, - check=True ), call( mock_logger, hugo_call, cwd=patch_clone_dir, env=build_env(*kwargs.values()), - node=True + node=True, ) ]) @@ -827,9 +782,7 @@ def test_it_uses_ruby_cache_when_gemfile_lock(self, mock_sp_run, mock_cache_fold mock_run.return_value = 0 - result = setup_bundler(True, None, None) - - assert result == 0 + setup_bundler(True, None, None) mock_get_logger.assert_called_once_with('setup-bundler') @@ -843,7 +796,7 @@ def test_it_uses_ruby_cache_when_gemfile_lock(self, mock_sp_run, mock_cache_fold mock_cache_folder.assert_called_once() - def callp(cmd): + def callp(cmd, skip_log=False): return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, ruby=True) mock_run.assert_has_calls([ @@ -856,9 +809,8 @@ def test_it_uses_node_cache_when_package_lock(self, mock_sp_run, mock_cache_fold create_file(patch_clone_dir / PACKAGE_JSON) create_file(patch_clone_dir / PACKAGE_LOCK, contents='hashable') - result = setup_node(True, None, None) - - assert result == 0 + mock_post_metrics = Mock() + setup_node(True, None, None, mock_post_metrics) mock_get_logger.assert_called_once_with('setup-node') @@ -872,8 +824,8 @@ def test_it_uses_node_cache_when_package_lock(self, mock_sp_run, mock_cache_fold mock_cache_folder.assert_called_once() - def callp(cmd): - return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, check=True, node=True) + def callp(cmd, skip_log=False): + return call(mock_logger, cmd, cwd=patch_clone_dir, env={}, node=True, skip_log=skip_log) mock_run.assert_has_calls([ callp('echo Node version: $(node --version)'), diff --git a/test/test_fetch.py b/test/test_fetch.py index 7ce96ccc..957200c5 100644 --- a/test/test_fetch.py +++ b/test/test_fetch.py @@ -28,7 +28,7 @@ def test_runs_expected_cmds(self, mock_get_logger, mock_run): mock_get_logger.assert_called_once_with('clone') - mock_run.assert_called_once_with(mock_get_logger.return_value, command, env=clone_env) + mock_run.assert_called_once_with(mock_get_logger.return_value, command, env=clone_env, check=False) # noqa: 501 def test_runs_expected_cmds_with_gh_token(self, mock_get_logger, mock_run): owner = 'owner-2' @@ -44,7 +44,7 @@ def test_runs_expected_cmds_with_gh_token(self, mock_get_logger, mock_run): mock_get_logger.assert_called_once_with('clone') - mock_run.assert_called_once_with(mock_get_logger.return_value, command, env=clone_env) + mock_run.assert_called_once_with(mock_get_logger.return_value, command, env=clone_env, check=False) # noqa: 501 class TestCloneRepoNoMock(unittest.TestCase): @@ -57,6 +57,7 @@ def test_no_github_permission_warning(self): repository = 'cg-site' branch = 'master' + # TODO: this is a totally useless test because the CI runner doesn't have git with self._caplog.at_level(logging.INFO): fetch_repo(owner, repository, branch) diff --git a/test/test_runner.py b/test/test_runner.py index c2a85b35..ce9ea7a7 100644 --- a/test/test_runner.py +++ b/test/test_runner.py @@ -13,7 +13,7 @@ def test_run(mock_popen): mock_popen.return_value = Mock(returncode=0, stdout=Mock(readline=Mock(return_value='foobar'))) - result = run(mock_logger, command) + run(mock_logger, command) mock_popen.assert_called_once_with( shlex.split(command), @@ -31,8 +31,6 @@ def test_run(mock_popen): mock_logger.info.assert_called_once_with('foobar') - assert result == 0 - @patch('subprocess.Popen', autospec=True) def test_run_popen_failure(mock_popen): @@ -41,7 +39,8 @@ def test_run_popen_failure(mock_popen): mock_popen.side_effect = ValueError('ugh') - result = run(mock_logger, command) + with raises(ValueError): + run(mock_logger, command) mock_popen.assert_called_once_with( shlex.split(command), @@ -60,18 +59,18 @@ def test_run_popen_failure(mock_popen): mock_logger.error.assert_any_call('Encountered a problem invoking Popen.') mock_logger.error.assert_any_call('ugh') - assert result == 1 - @patch('subprocess.Popen', autospec=True) -def test_run_popen_failure_check_true(mock_popen): +def test_run_popen_failure_check_false(mock_popen): mock_logger = Mock() command = 'foobar' + return_code = 1 mock_popen.side_effect = ValueError('ugh') - with raises(ValueError, match='ugh'): - run(mock_logger, command, check=True) + result = run(mock_logger, command, check=False) + + assert result == return_code mock_popen.assert_called_once_with( shlex.split(command), @@ -92,13 +91,39 @@ def test_run_popen_failure_check_true(mock_popen): @patch('subprocess.Popen', autospec=True) -def test_run_os_failure(mock_popen): +def test_run_popen_output(mock_popen): mock_logger = Mock() command = 'foobar' - mock_popen.side_effect = OSError('ugh') + string_output = 'string_output' + mock_popen.return_value = Mock(returncode=0, stdout=Mock(readline=Mock(return_value=string_output))) # noqa: E501 result = run(mock_logger, command) + assert result == string_output + + mock_popen.assert_called_once_with( + shlex.split(command), + cwd=None, + env=None, + shell=False, + executable=None, + stderr=subprocess.STDOUT, + stdout=subprocess.PIPE, + bufsize=1, + encoding='utf-8', + text=True, + preexec_fn=setuser, + ) + + +@patch('subprocess.Popen', autospec=True) +def test_run_os_failure_check_false(mock_popen): + mock_logger = Mock() + command = 'foobar' + + mock_popen.side_effect = OSError('ugh') + + result = run(mock_logger, command, check=False) mock_popen.assert_called_once_with( shlex.split(command), @@ -130,7 +155,7 @@ def test_run_os_failure_check_true(mock_popen): mock_popen.side_effect = OSError('ugh') with raises(OSError, match='ugh'): - run(mock_logger, command, check=True) + run(mock_logger, command) mock_popen.assert_called_once_with( shlex.split(command), @@ -153,14 +178,14 @@ def test_run_os_failure_check_true(mock_popen): @patch('subprocess.Popen', autospec=True) -def test_run_command_failure(mock_popen): +def test_run_command_failure_check_false(mock_popen): mock_logger = Mock() command = 'foobar' return_code = 2 - mock_popen.return_value = Mock(returncode=return_code, stdout=Mock(readline=Mock())) + mock_popen.return_value = Mock(returncode=return_code, stdout=Mock(readline=Mock(return_value='text'))) # noqa: E501 - result = run(mock_logger, command) + result = run(mock_logger, command, check=False) mock_popen.assert_called_once_with( shlex.split(command), @@ -185,10 +210,10 @@ def test_run_command_failure_check_true(mock_popen): command = 'foobar' return_code = 2 - mock_popen.return_value = Mock(returncode=return_code, stdout=Mock(readline=Mock())) + mock_popen.return_value = Mock(returncode=return_code, stdout=Mock(readline=Mock(return_value='text'))) # noqa: E501 with raises(subprocess.CalledProcessError): - run(mock_logger, command, check=True) + run(mock_logger, command) mock_popen.assert_called_once_with( shlex.split(command), @@ -217,7 +242,7 @@ def test_run_with_node(mock_popen): run(mock_logger, command, cwd=cwd, env=env, node=True) mock_popen.assert_called_once_with( - f'source {NVM_PATH} && nvm use default && {command}', + f'source {NVM_PATH} && {command}', cwd=cwd, env=env, shell=True, # nosec @@ -262,6 +287,32 @@ def test_access_environ(): command = 'cat /proc/1/environ' env = {} - run(mock_logger, command, env=env) + run(mock_logger, command, env=env, check=False) mock_logger.info.assert_any_call('cat: /proc/1/environ: Permission denied') + + +@patch('subprocess.Popen', autospec=True) +def test_run_skip_log(mock_popen): + mock_logger = Mock() + command = 'foobar' + + mock_popen.return_value = Mock(returncode=0, stdout=Mock(readline=Mock(return_value='foobar'))) + + run(mock_logger, command, skip_log=True) + + mock_popen.assert_called_once_with( + shlex.split(command), + cwd=None, + env=None, + shell=False, + executable=None, + stderr=subprocess.STDOUT, + stdout=subprocess.PIPE, + bufsize=1, + encoding='utf-8', + text=True, + preexec_fn=setuser, + ) + + mock_logger.info.assert_not_called()