From 0dd13fad1bced76d77423e7f4d01b93c54930757 Mon Sep 17 00:00:00 2001 From: Stuart Young Date: Fri, 24 Aug 2018 11:37:34 -0400 Subject: [PATCH] add paver timeout decorator and npm installation logs --- lms/djangoapps/courseware/tests/test_i18n.py | 1 - openedx/core/djangoapps/dark_lang/tests.py | 1 - .../djangoapps/lang_pref/tests/test_api.py | 1 - pavelib/paver_tests/test_decorators.py | 30 ++++++++++ pavelib/paver_tests/test_prereqs.py | 48 +++++++-------- pavelib/paver_tests/utils.py | 8 +-- pavelib/prereqs.py | 48 ++++++++++++--- pavelib/utils/decorators.py | 58 +++++++++++++++++++ 8 files changed, 157 insertions(+), 38 deletions(-) create mode 100644 pavelib/paver_tests/test_decorators.py create mode 100644 pavelib/utils/decorators.py diff --git a/lms/djangoapps/courseware/tests/test_i18n.py b/lms/djangoapps/courseware/tests/test_i18n.py index 97a79c67da..68c22f36c4 100644 --- a/lms/djangoapps/courseware/tests/test_i18n.py +++ b/lms/djangoapps/courseware/tests/test_i18n.py @@ -8,7 +8,6 @@ import re from django.conf import settings from django.contrib.auth.models import User from django.urls import reverse, reverse_lazy -from django.test import TestCase from django.test.client import Client from django.utils import translation diff --git a/openedx/core/djangoapps/dark_lang/tests.py b/openedx/core/djangoapps/dark_lang/tests.py index d7fa371d79..17e361a9c4 100644 --- a/openedx/core/djangoapps/dark_lang/tests.py +++ b/openedx/core/djangoapps/dark_lang/tests.py @@ -5,7 +5,6 @@ import unittest import ddt from django.http import HttpRequest -from django.test import TestCase from django.test.client import Client from django.utils.translation import LANGUAGE_SESSION_KEY from mock import Mock diff --git a/openedx/core/djangoapps/lang_pref/tests/test_api.py b/openedx/core/djangoapps/lang_pref/tests/test_api.py index 9cbea1173f..4c6fd7bb32 100644 --- a/openedx/core/djangoapps/lang_pref/tests/test_api.py +++ b/openedx/core/djangoapps/lang_pref/tests/test_api.py @@ -2,7 +2,6 @@ """ Tests for the language API. """ from mock import patch -from django.test import TestCase from django.test.utils import override_settings from django.utils import translation from django.contrib.auth.models import User diff --git a/pavelib/paver_tests/test_decorators.py b/pavelib/paver_tests/test_decorators.py new file mode 100644 index 0000000000..20c2a926e8 --- /dev/null +++ b/pavelib/paver_tests/test_decorators.py @@ -0,0 +1,30 @@ +""" Tests for the utility decorators for Paver """ +import time + +import pytest + +from pavelib.utils.decorators import ( + timeout, TimeoutException +) + + +def test_function_under_timeout(): + + @timeout(1) + def sample_function_1(): + time.sleep(0.1) + return "sample text" + + value = sample_function_1() + assert value == "sample text" + + +def test_function_over_timeout(): + + @timeout(0.1) + def sample_function_2(): + time.sleep(1) + return "sample text" + + with pytest.raises(TimeoutException): + sample_function_2() diff --git a/pavelib/paver_tests/test_prereqs.py b/pavelib/paver_tests/test_prereqs.py index efbae4ab64..14919f14f5 100644 --- a/pavelib/paver_tests/test_prereqs.py +++ b/pavelib/paver_tests/test_prereqs.py @@ -5,11 +5,11 @@ Tests covering the Open edX Paver prequisites installation workflow import os import unittest -from mock import call, patch +from mock import patch from paver.easy import BuildFailure from pavelib.paver_tests.utils import PaverTestCase, fail_on_npm_install, unexpected_fail_on_npm_install -from pavelib.prereqs import no_prereq_install, node_prereqs_installation +import pavelib.prereqs class TestPaverPrereqInstall(unittest.TestCase): @@ -28,7 +28,7 @@ class TestPaverPrereqInstall(unittest.TestCase): _orig_environ = dict(os.environ) os.environ['NO_PREREQ_INSTALL'] = set_val self.assertEqual( - no_prereq_install(), + pavelib.prereqs.no_prereq_install(), expected_val, 'NO_PREREQ_INSTALL is set to {}, but we read it as {}'.format( set_val, expected_val), @@ -86,41 +86,43 @@ class TestPaverNodeInstall(PaverTestCase): # Ensure prereqs will be run os.environ['NO_PREREQ_INSTALL'] = 'false' - patcher = patch('pavelib.prereqs.sh', return_value=True) - self._mock_paver_sh = patcher.start() - self.addCleanup(patcher.stop) - def test_npm_install_with_subprocess_error(self): """ An exit with subprocess exit 1 is what paver receives when there is an npm install error ("cb() never called!"). Test that we can handle this kind of failure. For more info see TE-1767. """ - self._mock_paver_sh.side_effect = fail_on_npm_install - with self.assertRaises(BuildFailure): - node_prereqs_installation() - actual_calls = self._mock_paver_sh.mock_calls - + with patch('pavelib.utils.decorators.timeout') as _timeout_patch: + _timeout_patch.return_value = lambda x: x + reload(pavelib.prereqs) + with patch('subprocess.Popen') as _mock_popen: + _mock_popen.side_effect = fail_on_npm_install + with self.assertRaises(BuildFailure): + pavelib.prereqs.node_prereqs_installation() # npm install will be called twice - self.assertEqual(actual_calls.count(call('npm install')), 2) + self.assertEquals(_mock_popen.call_count, 2) def test_npm_install_called_once_when_successful(self): """ Vanilla npm install should only be calling npm install one time """ - node_prereqs_installation() - actual_calls = self._mock_paver_sh.mock_calls - + with patch('pavelib.utils.decorators.timeout') as _timeout_patch: + _timeout_patch.return_value = lambda x: x + reload(pavelib.prereqs) + with patch('subprocess.Popen') as _mock_popen: + pavelib.prereqs.node_prereqs_installation() # when there's no failure, npm install is only called once - self.assertEqual(actual_calls.count(call('npm install')), 1) + self.assertEquals(_mock_popen.call_count, 1) def test_npm_install_with_unexpected_subprocess_error(self): """ If there's some other error, only call npm install once, and raise a failure """ - self._mock_paver_sh.side_effect = unexpected_fail_on_npm_install - with self.assertRaises(BuildFailure): - node_prereqs_installation() - actual_calls = self._mock_paver_sh.mock_calls - - self.assertEqual(actual_calls.count(call('npm install')), 1) + with patch('pavelib.utils.decorators.timeout') as _timeout_patch: + _timeout_patch.return_value = lambda x: x + reload(pavelib.prereqs) + with patch('subprocess.Popen') as _mock_popen: + _mock_popen.side_effect = unexpected_fail_on_npm_install + with self.assertRaises(BuildFailure): + pavelib.prereqs.node_prereqs_installation() + self.assertEquals(_mock_popen.call_count, 1) diff --git a/pavelib/paver_tests/utils.py b/pavelib/paver_tests/utils.py index 2dbcd70cfb..3fb9ea55aa 100644 --- a/pavelib/paver_tests/utils.py +++ b/pavelib/paver_tests/utils.py @@ -89,23 +89,23 @@ def fail_on_pylint(*args): return -def fail_on_npm_install(*args): +def fail_on_npm_install(*args, **kwargs): # pylint: disable=unused-argument """ For our tests, we need the call for diff-quality running pycodestyle reports to fail, since that is what is going to fail when we pass in a percentage ("p") requirement. """ - if "npm install" in args[0]: + if ["npm", "install", "--verbose"] == args[0]: raise BuildFailure('Subprocess return code: 1') else: return -def unexpected_fail_on_npm_install(*args): +def unexpected_fail_on_npm_install(*args, **kwargs): # pylint: disable=unused-argument """ For our tests, we need the call for diff-quality running pycodestyle reports to fail, since that is what is going to fail when we pass in a percentage ("p") requirement. """ - if "npm install" in args[0]: + if ["npm", "install", "--verbose"] == args[0]: raise BuildFailure('Subprocess return code: 50') else: return diff --git a/pavelib/prereqs.py b/pavelib/prereqs.py index f39e776880..ac08c9507e 100644 --- a/pavelib/prereqs.py +++ b/pavelib/prereqs.py @@ -6,12 +6,15 @@ import hashlib import os import re import sys +import subprocess +import io from distutils import sysconfig from paver.easy import BuildFailure, sh, task from .utils.envs import Env from .utils.timer import timed +from .utils.decorators import timeout, TimeoutException PREREQS_STATE_DIR = os.getenv('PREREQ_CACHE_DIR', Env.REPO_ROOT / '.prereqs_cache') NO_PREREQ_MESSAGE = "NO_PREREQ_INSTALL is set, not installing prereqs" @@ -79,7 +82,7 @@ def compute_fingerprint(path_list): # For files, hash the contents of the file if os.path.isfile(path_item): - with open(path_item, "rb") as file_handle: + with io.open(path_item, "rb") as file_handle: hasher.update(file_handle.read()) return hasher.hexdigest() @@ -98,7 +101,7 @@ def prereq_cache(cache_name, paths, install_func): cache_file_path = os.path.join(PREREQS_STATE_DIR, "{}.sha1".format(cache_filename)) old_hash = None if os.path.isfile(cache_file_path): - with open(cache_file_path) as cache_file: + with io.open(cache_file_path, "rb") as cache_file: old_hash = cache_file.read() # Compare the old hash to the new hash @@ -112,7 +115,7 @@ def prereq_cache(cache_name, paths, install_func): # If the code executed within the context fails (throws an exception), # then this step won't get executed. create_prereqs_cache_dir() - with open(cache_file_path, "w") as cache_file: + with io.open(cache_file_path, "wb") as cache_file: # Since the pip requirement files are modified during the install # process, we need to store the hash generated AFTER the installation post_install_hash = compute_fingerprint(paths) @@ -125,19 +128,48 @@ def node_prereqs_installation(): """ Configures npm and installs Node prerequisites """ + + @timeout(limit=300) + def _run_npm_command(npm_command, npm_log_file): + """ + helper function for running the npm installation with a timeout. + The implementation of Paver's `sh` function returns before the forked + actually returns. Using a Popen object so that we can ensure that + the forked process has returned + """ + proc = subprocess.Popen(npm_command, stderr=npm_log_file) + proc.wait() + + # NPM installs hang sporadically. Log the installation process so that we + # determine if any packages are chronic offenders. + shard_str = os.getenv('SHARD', None) + if shard_str: + npm_log_file_path = '{}/npm-install.{}.log'.format(Env.GEN_LOG_DIR, shard_str) + else: + npm_log_file_path = '{}/npm-install.log'.format(Env.GEN_LOG_DIR) + npm_log_file = io.open(npm_log_file_path, 'wb') + npm_command = 'npm install --verbose'.split() + cb_error_text = "Subprocess return code: 1" # Error handling around a race condition that produces "cb() never called" error. This # evinces itself as `cb_error_text` and it ought to disappear when we upgrade # npm to 3 or higher. TODO: clean this up when we do that. try: - sh('npm install') + _run_npm_command(npm_command, npm_log_file) + except TimeoutException: + print "NPM installation took too long. Exiting..." + print "Check {} for more information".format(npm_log_file_path) + sys.exit(1) except BuildFailure, error_text: if cb_error_text in error_text: print "npm install error detected. Retrying..." - sh('npm install') + _run_npm_command(npm_command, npm_log_file) else: raise BuildFailure(error_text) + print "Successfully installed NPM packages. Log found at {}".format( + npm_log_file_path + ) def python_prereqs_installation(): @@ -192,7 +224,7 @@ def uninstall_python_packages(): """ if no_python_uninstall(): - print(NO_PYTHON_UNINSTALL_MESSAGE) + print NO_PYTHON_UNINSTALL_MESSAGE return # So that we don't constantly uninstall things, use a hash of the packages @@ -204,7 +236,7 @@ def uninstall_python_packages(): create_prereqs_cache_dir() if os.path.isfile(state_file_path): - with open(state_file_path) as state_file: + with io.open(state_file_path) as state_file: version = state_file.read() if version == expected_version: print 'Python uninstalls unchanged, skipping...' @@ -230,7 +262,7 @@ def uninstall_python_packages(): return # Write our version. - with open(state_file_path, "w") as state_file: + with io.open(state_file_path, "wb") as state_file: state_file.write(expected_version) diff --git a/pavelib/utils/decorators.py b/pavelib/utils/decorators.py new file mode 100644 index 0000000000..c47c65850a --- /dev/null +++ b/pavelib/utils/decorators.py @@ -0,0 +1,58 @@ +""" a collection of utililty decorators for paver tasks """ + +import multiprocessing +from functools import wraps + +import psutil + + +def timeout(limit=60): + """ + kill a function if it has not completed within a specified timeframe + """ + + def _handle_function_process(*args, **kwargs): + """ helper function for running a function and getting its output """ + queue = kwargs['queue'] + function = kwargs['function_to_call'] + function_args = args + function_kwargs = kwargs['function_kwargs'] + function_output = function(*function_args, **function_kwargs) + queue.put(function_output) + + def decorated_function(function): + """ the time-limited function returned by the timeout decorator """ + + def function_wrapper(*args, **kwargs): + """ + take a function and run it on a separate process, forcing it to + either give up its return value or throw a TimeoutException with + a specified timeframe (in seconds) + """ + queue = multiprocessing.Queue() + args_tuple = tuple(a for a in args) + meta_kwargs = { + 'function_to_call': function, 'queue': queue, + 'function_kwargs': kwargs + } + function_proc = multiprocessing.Process( + target=_handle_function_process, args=args_tuple, kwargs=meta_kwargs + ) + function_proc.start() + function_proc.join(float(limit)) + if function_proc.is_alive(): + pid = psutil.Process(function_proc.pid) + for child in pid.get_children(recursive=True): + child.terminate() + function_proc.terminate() + raise TimeoutException + function_output = queue.get() + return function_output + + return wraps(function)(function_wrapper) + + return decorated_function + + +class TimeoutException(Exception): + pass