add paver timeout decorator and npm installation logs

This commit is contained in:
Stuart Young
2018-08-24 11:37:34 -04:00
parent e14f70035e
commit 0dd13fad1b
8 changed files with 157 additions and 38 deletions

View File

@@ -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

View File

@@ -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

View File

@@ -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

View File

@@ -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()

View File

@@ -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)

View File

@@ -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

View File

@@ -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)

View File

@@ -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