Merge pull request #337 from yuvipanda/better-output

Provide much better error messages

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
+    """
+    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('Ran {command} with exit code {code}'.format(
+            command=printable_command, code=proc.returncode
+        ))
+        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(
+            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,21 @@ 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_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)
 
     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 +124,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)
+        run_subprocess(['apt-get', 'update', '--yes'])
-        subprocess.check_output(['apt-get', 'install', '--yes', 'software-properties-common'], stderr=subprocess.STDOUT)
+        run_subprocess(['apt-get', 'install', '--yes', 'software-properties-common'])
-        subprocess.check_output(['add-apt-repository', 'universe'], stderr=subprocess.STDOUT)
+        run_subprocess(['add-apt-repository', 'universe'])
 
-        subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT)
+        run_subprocess(['apt-get', 'update', '--yes'])
-        subprocess.check_output(['apt-get', 'install', '--yes', 
+        run_subprocess(['apt-get', 'install', '--yes', 
-            'git',
             'python3',
             'python3-venv',
-            'python3-pip'
+            'python3-pip',
-        ], stderr=subprocess.STDOUT)
+            '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 +153,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...')

dev-requirements.txt

@@ -1,4 +1,5 @@
 pytest
 pytest-cov
+pytest-mock
 codecov
 pytoml

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

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

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)
+        utils.run_subprocess(['apt-get', 'update', '--yes'])
-    subprocess.check_output([
+    utils.run_subprocess([
         'apt-get',
         'install',
         '--yes'
-    ] + packages, stderr=subprocess.STDOUT)
+    ] + packages)

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)

tljh/installer.py

@@ -22,6 +22,7 @@ from tljh import (
     systemd,
     traefik,
     user,
+    utils
 )
 from .config import (
     CONFIG_DIR,
@@ -35,7 +36,6 @@ from .yaml import yaml
 
 HERE = os.path.abspath(os.path.dirname(__file__))
 
-
 logger = logging.getLogger("tljh")
 
 def ensure_node():
@@ -172,7 +172,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'

tljh/utils.py

@@ -0,0 +1,36 @@
+"""
+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('Ran {command} with exit code {code}'.format(
+            command=printable_command, code=proc.returncode
+        ))
+        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(
+            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())