From 7071332445fee750947f523027fa6793eb983a9b Mon Sep 17 00:00:00 2001 From: yuvipanda Date: Sun, 19 May 2019 13:45:57 -0700 Subject: [PATCH 1/3] Provide much better error messages - When processes fail, they actually print a failure message on the user's terminal - Regardless of success or failure, we print all output to /opt/tljh/installer.log This should make debugging people's issues *much* easier, since we can actually see the output of failing commands rather than having to guess. --- bootstrap/bootstrap.py | 59 ++++++++++++++++++++++++++++++++---------- tljh/apt.py | 11 ++++---- tljh/conda.py | 17 ++++++------ tljh/installer.py | 4 +-- tljh/utils.py | 37 ++++++++++++++++++++++++++ 5 files changed, 99 insertions(+), 29 deletions(-) create mode 100644 tljh/utils.py diff --git a/bootstrap/bootstrap.py b/bootstrap/bootstrap.py index d1c961a..3370d70 100644 --- a/bootstrap/bootstrap.py +++ b/bootstrap/bootstrap.py @@ -18,6 +18,7 @@ import sys import logging import shutil +logger = logging.getLogger(__name__) def get_os_release_variable(key): """ @@ -32,6 +33,36 @@ def get_os_release_variable(key): "source /etc/os-release && echo ${{{key}}}".format(key=key) ]).decode().strip() +# Copied into tljh/utils.py. Make sure the copies are exactly the same! +def run_subprocess(cmd, *args, **kwargs): + """ + Run given cmd with smart output behavior. + + If command succeeds, print output to debug logging. + If it fails, print output to info logging. + + In TLJH, this sends successful output to the installer log, + and failed output directly to the user's screen + """ + proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, *args, **kwargs) + printable_command = ' '.join(cmd) + if proc.returncode != 0: + # Our process failed! Show output to the user + logger.error(proc.stdout.decode()) + e = Exception( 'command {command} failed with return code {code}'.format( + printable_command, proc.returncode + )) + logging.exception(e) + raise e + else: + # This goes into installer.log + logger.debug('Ran {command} with exit code {code}'.format( + command=printable_command, code=proc.returncode + )) + # This produces multi line log output, unfortunately. Not sure how to fix. + # For now, prioritizing human readability over machine readability. + logger.debug(proc.stdout.decode()) + def validate_host(): """ Make sure TLJH is installable in current host @@ -65,17 +96,17 @@ def main(): hub_prefix = os.path.join(install_prefix, 'hub') # Set up logging to print to a file and to stderr - logger = logging.getLogger(__name__) - os.makedirs(install_prefix, exist_ok=True) file_logger = logging.FileHandler(os.path.join(install_prefix, 'installer.log')) file_logger.setFormatter(logging.Formatter('%(asctime)s %(message)s')) + file_logger.setLevel(logging.DEBUG) logger.addHandler(file_logger) stderr_logger = logging.StreamHandler() stderr_logger.setFormatter(logging.Formatter('%(message)s')) + stderr_logger.setLevel(logging.INFO) logger.addHandler(stderr_logger) - logger.setLevel(logging.INFO) + logger.setLevel(logging.DEBUG) logger.info('Checking if TLJH is already installed...') if os.path.exists(os.path.join(hub_prefix, 'bin', 'python3')): @@ -89,20 +120,20 @@ def main(): # that's where the python3-pip package lives. In some very minimal base # VM images, it looks like the universe repository is disabled by default, # causing bootstrapping to fail. - subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT) - subprocess.check_output(['apt-get', 'install', '--yes', 'software-properties-common'], stderr=subprocess.STDOUT) - subprocess.check_output(['add-apt-repository', 'universe'], stderr=subprocess.STDOUT) + run_subprocess(['apt-get', 'update', '--yes']) + run_subprocess(['apt-get', 'install', '--yes', 'software-properties-common']) + run_subprocess(['add-apt-repository', 'universe']) - subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT) - subprocess.check_output(['apt-get', 'install', '--yes', - 'git', + run_subprocess(['apt-get', 'update', '--yes']) + run_subprocess(['apt-get', 'install', '--yes', 'python3', 'python3-venv', - 'python3-pip' - ], stderr=subprocess.STDOUT) + 'python3-pip', + 'git' + ]) logger.info('Installed python & virtual environment') os.makedirs(hub_prefix, exist_ok=True) - subprocess.check_output(['python3', '-m', 'venv', hub_prefix], stderr=subprocess.STDOUT) + run_subprocess(['python3', '-m', 'venv', hub_prefix]) logger.info('Set up hub virtual environment') if initial_setup: @@ -118,10 +149,10 @@ def main(): 'git+https://github.com/jupyterhub/the-littlest-jupyterhub.git' ) - subprocess.check_output([ + run_subprocess([ os.path.join(hub_prefix, 'bin', 'pip'), 'install' - ] + pip_flags + [tljh_repo_path], stderr=subprocess.STDOUT) + ] + pip_flags + [tljh_repo_path]) logger.info('Setup tljh package') logger.info('Starting TLJH installer...') diff --git a/tljh/apt.py b/tljh/apt.py index fe8ddc0..d2c5fec 100644 --- a/tljh/apt.py +++ b/tljh/apt.py @@ -3,6 +3,7 @@ Utilities for working with the apt package manager """ import os import subprocess +from tljh import utils def trust_gpg_key(key): @@ -14,7 +15,7 @@ def trust_gpg_key(key): # If gpg2 doesn't exist, install it. if not os.path.exists('/usr/bin/gpg2'): install_packages(['gnupg2']) - subprocess.check_output(['apt-key', 'add', '-'], input=key, stderr=subprocess.STDOUT) + utils.run_subprocess(['apt-key', 'add', '-'], input=key) def add_source(name, source_url, section): @@ -32,7 +33,7 @@ def add_source(name, source_url, section): f.seek(0) f.write(line) f.truncate() - subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT) + utils.run_subprocess(['apt-get', 'update', '--yes']) def install_packages(packages): @@ -41,9 +42,9 @@ def install_packages(packages): """ # Check if an apt-get update is required if len(os.listdir('/var/lib/apt/lists')) == 0: - subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT) - subprocess.check_output([ + utils.run_subprocess(['apt-get', 'update', '--yes']) + utils.run_subprocess([ 'apt-get', 'install', '--yes' - ] + packages, stderr=subprocess.STDOUT) + ] + packages) diff --git a/tljh/conda.py b/tljh/conda.py index 35d45fc..ebd8d86 100644 --- a/tljh/conda.py +++ b/tljh/conda.py @@ -9,6 +9,7 @@ import contextlib import tempfile import requests from distutils.version import LooseVersion as V +from tljh import utils def md5_file(fname): @@ -68,22 +69,22 @@ def fix_permissions(prefix): Run after each install command. """ - subprocess.check_call( + utils.run_subprocess( ["chown", "-R", "{}:{}".format(os.getuid(), os.getgid()), prefix] ) - subprocess.check_call(["chmod", "-R", "o-w", prefix]) + utils.run_subprocess(["chmod", "-R", "o-w", prefix]) def install_miniconda(installer_path, prefix): """ Install miniconda with installer at installer_path under prefix """ - subprocess.check_output([ + utils.run_subprocess([ '/bin/bash', installer_path, '-u', '-b', '-p', prefix - ], stderr=subprocess.STDOUT) + ]) # fix permissions on initial install # a few files have the wrong ownership and permissions initially # when the installer is run as root @@ -128,10 +129,10 @@ def ensure_pip_packages(prefix, packages): abspath = os.path.abspath(prefix) pip_executable = [os.path.join(abspath, 'bin', 'python'), '-m', 'pip'] - subprocess.check_output(pip_executable + [ + utils.run_subprocess(pip_executable + [ 'install', '--no-cache-dir', - ] + packages, stderr=subprocess.STDOUT) + ] + packages) fix_permissions(prefix) @@ -144,9 +145,9 @@ def ensure_pip_requirements(prefix, requirements_path): abspath = os.path.abspath(prefix) pip_executable = [os.path.join(abspath, 'bin', 'python'), '-m', 'pip'] - subprocess.check_output(pip_executable + [ + utils.run_subprocess(pip_executable + [ 'install', '-r', requirements_path - ], stderr=subprocess.STDOUT) + ]) fix_permissions(prefix) diff --git a/tljh/installer.py b/tljh/installer.py index b44782b..76a403d 100644 --- a/tljh/installer.py +++ b/tljh/installer.py @@ -20,6 +20,7 @@ from tljh import ( systemd, traefik, user, + utils ) from .config import ( CONFIG_DIR, @@ -33,7 +34,6 @@ from .yaml import yaml HERE = os.path.abspath(os.path.dirname(__file__)) - logger = logging.getLogger("tljh") def ensure_node(): @@ -170,7 +170,7 @@ def ensure_jupyterlab_extensions(): '@jupyterlab/hub-extension', '@jupyter-widgets/jupyterlab-manager' ] - subprocess.check_output([ + utils.run_subprocess([ os.path.join(USER_ENV_PREFIX, 'bin/jupyter'), 'labextension', 'install' diff --git a/tljh/utils.py b/tljh/utils.py new file mode 100644 index 0000000..03e09ec --- /dev/null +++ b/tljh/utils.py @@ -0,0 +1,37 @@ +""" +Miscelaneous functions useful in at least two places unrelated to each other +""" +import subprocess +import logging + + +# Copied into bootstrap/bootstrap.py. Make sure these two copies are exactly the same! +def run_subprocess(cmd, *args, **kwargs): + """ + Run given cmd with smart output behavior. + + If command succeeds, print output to debug logging. + If it fails, print output to info logging. + + In TLJH, this sends successful output to the installer log, + and failed output directly to the user's screen + """ + logger = logging.getLogger('tljh') + proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, *args, **kwargs) + printable_command = ' '.join(cmd) + if proc.returncode != 0: + # Our process failed! Show output to the user + logger.error(proc.stdout.decode()) + e = Exception( 'command {command} failed with return code {code}'.format( + printable_command, proc.returncode + )) + logger.exception(e) + raise e + else: + # This goes into installer.log + logger.debug('Ran {command} with exit code {code}'.format( + command=printable_command, code=proc.returncode + )) + # This produces multi line log output, unfortunately. Not sure how to fix. + # For now, prioritizing human readability over machine readability. + logger.debug(proc.stdout.decode()) \ No newline at end of file From f5ecce77a1adb0b554005dce825e99a430012049 Mon Sep 17 00:00:00 2001 From: yuvipanda Date: Sun, 19 May 2019 14:24:57 -0700 Subject: [PATCH 2/3] Add unit tests for run_subprocess --- bootstrap/bootstrap.py | 10 +++++----- dev-requirements.txt | 1 + tests/test_utils.py | 21 +++++++++++++++++++++ tljh/utils.py | 9 ++++----- 4 files changed, 31 insertions(+), 10 deletions(-) create mode 100644 tests/test_utils.py diff --git a/bootstrap/bootstrap.py b/bootstrap/bootstrap.py index 3370d70..ad013ca 100644 --- a/bootstrap/bootstrap.py +++ b/bootstrap/bootstrap.py @@ -44,16 +44,16 @@ def run_subprocess(cmd, *args, **kwargs): In TLJH, this sends successful output to the installer log, and failed output directly to the user's screen """ + logger = logging.getLogger('tljh') proc = subprocess.run(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, *args, **kwargs) printable_command = ' '.join(cmd) if proc.returncode != 0: # Our process failed! Show output to the user - logger.error(proc.stdout.decode()) - e = Exception( 'command {command} failed with return code {code}'.format( - printable_command, proc.returncode + logger.error('Ran {command} with exit code {code}'.format( + command=printable_command, code=proc.returncode )) - logging.exception(e) - raise e + logger.error(proc.stdout.decode()) + raise subprocess.CalledProcessError(cmd=cmd, returncode=proc.returncode) else: # This goes into installer.log logger.debug('Ran {command} with exit code {code}'.format( diff --git a/dev-requirements.txt b/dev-requirements.txt index 166dd49..6296fdd 100644 --- a/dev-requirements.txt +++ b/dev-requirements.txt @@ -1,4 +1,5 @@ pytest pytest-cov +pytest-mock codecov pytoml \ No newline at end of file diff --git a/tests/test_utils.py b/tests/test_utils.py new file mode 100644 index 0000000..b123c95 --- /dev/null +++ b/tests/test_utils.py @@ -0,0 +1,21 @@ +import pytest +from tljh import utils +import subprocess +import logging + + +def test_run_subprocess_exception(mocker): + logger = logging.getLogger('tljh') + mocker.patch.object(logger, 'error') + with pytest.raises(subprocess.CalledProcessError): + utils.run_subprocess( + ['/bin/bash', '-c', 'echo error; exit 1'] + ) + logger.error.assert_called_with('error\n') + + +def test_run_subprocess(mocker): + logger = logging.getLogger('tljh') + mocker.patch.object(logger, 'debug') + utils.run_subprocess(['/bin/bash', '-c', 'echo success']) + logger.debug.assert_called_with('success\n') \ No newline at end of file diff --git a/tljh/utils.py b/tljh/utils.py index 03e09ec..395d395 100644 --- a/tljh/utils.py +++ b/tljh/utils.py @@ -21,12 +21,11 @@ def run_subprocess(cmd, *args, **kwargs): printable_command = ' '.join(cmd) if proc.returncode != 0: # Our process failed! Show output to the user - logger.error(proc.stdout.decode()) - e = Exception( 'command {command} failed with return code {code}'.format( - printable_command, proc.returncode + logger.error('Ran {command} with exit code {code}'.format( + command=printable_command, code=proc.returncode )) - logger.exception(e) - raise e + logger.error(proc.stdout.decode()) + raise subprocess.CalledProcessError(cmd=cmd, returncode=proc.returncode) else: # This goes into installer.log logger.debug('Ran {command} with exit code {code}'.format( From 8ec3fab3f3614287a584e311109f091a33440a8d Mon Sep 17 00:00:00 2001 From: yuvipanda Date: Sun, 19 May 2019 23:19:21 -0700 Subject: [PATCH 3/3] Make installer.log non-readable by non-root users Doesn't have any sensitive info right now but might in the future. Fixes #142 --- bootstrap/bootstrap.py | 6 +++++- integration-tests/test_install.py | 6 ++++++ 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/bootstrap/bootstrap.py b/bootstrap/bootstrap.py index ad013ca..98e7245 100644 --- a/bootstrap/bootstrap.py +++ b/bootstrap/bootstrap.py @@ -97,7 +97,11 @@ def main(): # Set up logging to print to a file and to stderr os.makedirs(install_prefix, exist_ok=True) - file_logger = logging.FileHandler(os.path.join(install_prefix, 'installer.log')) + file_logger_path = os.path.join(install_prefix, 'installer.log') + file_logger = logging.FileHandler(file_logger_path) + # installer.log should be readable only by root + os.chmod(file_logger_path, 0o500) + file_logger.setFormatter(logging.Formatter('%(asctime)s %(message)s')) file_logger.setLevel(logging.DEBUG) logger.addHandler(file_logger) diff --git a/integration-tests/test_install.py b/integration-tests/test_install.py index 1b27eea..d3aa712 100644 --- a/integration-tests/test_install.py +++ b/integration-tests/test_install.py @@ -117,6 +117,12 @@ def test_admin_writable(): permissions_test(ADMIN_GROUP, sys.prefix, writable=True, dirs_only=True) +def test_installer_log_readable(): + # Test that installer.log is owned by root, and not readable by anyone else + file_stat = os.stat('/opt/tljh/installer.log') + assert file_stat.st_uid == 0 + assert file_stat.st_mode == 0o100500 + @pytest.mark.parametrize("group", [ADMIN_GROUP, USER_GROUP]) def test_user_env_readable(group): # every file in user env should be readable by everyone