Merge pull request #82 from jupyterhub/logging

Log bootstrap / installer messages to file as well

bootstrap/bootstrap.py

@@ -14,28 +14,45 @@ Constraints:
 import os
 import subprocess
 import sys
+import logging
+
 
 
 def main():
     install_prefix = os.environ.get('TLJH_INSTALL_PREFIX', '/opt/tljh')
     hub_prefix = os.path.join(install_prefix, 'hub')
 
-    print('Checking if TLJH is already installed...')
+    # 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'))
+    logger.addHandler(file_logger)
+
+    stderr_logger = logging.StreamHandler()
+    stderr_logger.setFormatter(logging.Formatter('%(message)s'))
+    logger.addHandler(stderr_logger)
+    logger.setLevel(logging.INFO)
+
+    logger.info('Checking if TLJH is already installed...')
     if os.path.exists(os.path.join(hub_prefix, 'bin', 'python3')):
-        print('TLJH already installed, upgrading...')
+        logger.info('TLJH already installed, upgrading...')
         initial_setup = False
     else:
-        print('Setting up hub environment')
+        logger.info('Setting up hub environment')
         initial_setup = True
-        subprocess.check_output(['apt-get', 'update', '--yes'])
+        subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT)
-        subprocess.check_output(['apt-get', 'install', '--yes', 'python3', 'python3-venv'])
+        subprocess.check_output(['apt-get', 'install', '--yes', 'python3', 'python3-venv'], stderr=subprocess.STDOUT)
+        logger.info('Installed python & virtual environment')
         os.makedirs(hub_prefix, exist_ok=True)
-        subprocess.check_output(['python3', '-m', 'venv', hub_prefix])
+        subprocess.check_output(['python3', '-m', 'venv', hub_prefix], stderr=subprocess.STDOUT)
+        logger.info('Set up hub virtual environment')
 
     if initial_setup:
-        print('Setting up TLJH installer...')
+        logger.info('Setting up TLJH installer...')
     else:
-        print('Upgrading TLJH installer...')
+        logger.info('Upgrading TLJH installer...')
 
     pip_flags = ['--upgrade']
     if os.environ.get('TLJH_BOOTSTRAP_DEV', 'no') == 'yes':
@@ -48,9 +65,10 @@ def main():
     subprocess.check_output([
         os.path.join(hub_prefix, 'bin', 'pip'),
         'install'
-    ] + pip_flags + [tljh_repo_path])
+    ] + pip_flags + [tljh_repo_path], stderr=subprocess.STDOUT)
+    logger.info('Setup tljh package')
 
-    print('Starting TLJH installer...')
+    logger.info('Starting TLJH installer...')
     os.execv(
         os.path.join(hub_prefix, 'bin', 'python3'),
         [

docs/troubleshooting/logs.rst

@@ -10,6 +10,8 @@ before things went bad, and can help us understand the problem so we can fix it.
 
 TLJH collects logs from JupyterHub, Configurable HTTP Proxy, & from each individual
 user's notebook server. All the logs are accessible via `journalctl <https://www.freedesktop.org/software/systemd/man/journalctl.html>`_.
+The installer also writes logs to disk, to help with cases where the
+installer did not succeed.
 
 .. warning::
 
@@ -17,6 +19,14 @@ user's notebook server. All the logs are accessible via `journalctl <https://www
    a problem you might have, be careful to redact any private information (such
    as usernames) from the snippet first!
 
+.. _troubleshooting/logs#installer:
+
+Installer Logs
+==============
+
+The JupyterHub installer writes log messages to ``/opt/tljh/installer.log``.
+This is very useful if the installation fails for any reason.
+
 .. _troubleshoot_logs_jupyterhub:
 
 JupyterHub Logs

tljh/apt.py

@@ -14,7 +14,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.run(['apt-key', 'add', '-'], input=key, check=True)
+    subprocess.check_output(['apt-key', 'add', '-'], input=key, stderr=subprocess.STDOUT)
 
 
 def add_source(name, source_url, section):
@@ -24,7 +24,7 @@ def add_source(name, source_url, section):
     distro is determined from /etc/os-release
     """
     # lsb_release is not installed in most docker images by default
-    distro = subprocess.check_output(['/bin/bash', '-c', 'source /etc/os-release && echo ${VERSION_CODENAME}']).decode().strip()
+    distro = subprocess.check_output(['/bin/bash', '-c', 'source /etc/os-release && echo ${VERSION_CODENAME}'], stderr=subprocess.STDOUT).decode().strip()
     line = f'deb {source_url} {distro} {section}'
     with open(os.path.join('/etc/apt/sources.list.d/', name + '.list'), 'a+') as f:
         # Write out deb line only if it already doesn't exist
@@ -32,7 +32,7 @@ def add_source(name, source_url, section):
             f.seek(0)
             f.write(line)
             f.truncate()
-            subprocess.check_output(['apt-get', 'update', '--yes'])
+            subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT)
 
 
 def install_packages(packages):
@@ -41,9 +41,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'])
+        subprocess.check_output(['apt-get', 'update', '--yes'], stderr=subprocess.STDOUT)
     subprocess.check_output([
         'apt-get',
         'install',
         '--yes'
-    ] + packages)
+    ] + packages, stderr=subprocess.STDOUT)

tljh/conda.py

@@ -32,7 +32,7 @@ def check_miniconda_version(prefix, version):
         installed_version = subprocess.check_output([
             os.path.join(prefix, 'bin', 'conda'),
             '-V'
-        ]).decode().strip().split()[1]
+        ], stderr=subprocess.STDOUT).decode().strip().split()[1]
         return V(installed_version) >= V(version)
     except (subprocess.CalledProcessError, FileNotFoundError):
         # Conda doesn't exist
@@ -90,7 +90,7 @@ def ensure_conda_packages(prefix, packages):
         '-c', 'conda-forge',  # Make customizable if we ever need to
         '--json',
         '--prefix', abspath
-    ] + packages).decode()
+    ] + packages, stderr=subprocess.STDOUT).decode()
     # `conda install` outputs JSON lines for fetch updates,
     # and a undelimited output at the end. There is no reasonable way to
     # parse this outside of this kludge.
@@ -115,7 +115,7 @@ def ensure_pip_packages(prefix, packages):
     subprocess.check_output(pip_executable + [
         'install',
         '--no-cache-dir',
-    ] + packages)
+    ] + packages, stderr=subprocess.STDOUT)
 
 
 def ensure_pip_requirements(prefix, requirements_path):
@@ -131,4 +131,4 @@ def ensure_pip_requirements(prefix, requirements_path):
         'install',
         '-r',
         requirements_path
-    ])
+    ], stderr=subprocess.STDOUT)

tljh/installer.py

@@ -4,6 +4,7 @@ import secrets
 import subprocess
 import sys
 import time
+import logging
 from urllib.error import HTTPError
 from urllib.request import urlopen, URLError
 
@@ -20,6 +21,19 @@ HERE = os.path.abspath(os.path.dirname(__file__))
 
 rt_yaml = YAML()
 
+# 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'))
+logger.addHandler(file_logger)
+
+stderr_logger = logging.StreamHandler()
+stderr_logger.setFormatter(logging.Formatter('%(message)s'))
+logger.addHandler(stderr_logger)
+logger.setLevel(logging.INFO)
+
 
 def ensure_node():
     """
@@ -89,9 +103,9 @@ def ensure_chp_package(prefix):
     Ensure CHP is installed
     """
     if not os.path.exists(os.path.join(prefix, 'node_modules', '.bin', 'configurable-http-proxy')):
-        subprocess.check_call([
+        subprocess.check_output([
             'npm', 'install', 'configurable-http-proxy@3.1.0'
-        ], cwd=prefix)
+        ], cwd=prefix, stderr=subprocess.STDOUT)
 
 
 def ensure_jupyterhub_service(prefix):
@@ -160,7 +174,7 @@ def ensure_usergroups():
     user.ensure_group('jupyterhub-admins')
     user.ensure_group('jupyterhub-users')
 
-    print("Granting passwordless sudo to JupyterHub admins...")
+    logger.info("Granting passwordless sudo to JupyterHub admins...")
     with open('/etc/sudoers.d/jupyterhub-admins', 'w') as f:
         # JupyterHub admins should have full passwordless sudo access
         f.write('%jupyterhub-admins ALL = (ALL) NOPASSWD: ALL\n')
@@ -174,12 +188,12 @@ def ensure_user_environment(user_requirements_txt_file):
     """
     Set up user conda environment with required packages
     """
-    print("Setting up user environment...")
+    logger.info("Setting up user environment...")
     miniconda_version = '4.5.4'
     miniconda_installer_md5 = "a946ea1d0c4a642ddf0c3a26a18bb16d"
 
     if not conda.check_miniconda_version(USER_ENV_PREFIX, miniconda_version):
-        print('Downloading & setting up user environment...')
+        logger.info('Downloading & setting up user environment...')
         with conda.download_miniconda_installer(miniconda_version, miniconda_installer_md5) as installer_path:
             conda.install_miniconda(installer_path, USER_ENV_PREFIX)
 
@@ -210,7 +224,7 @@ def ensure_admins(admins):
     """
     if not admins:
         return
-    print("Setting up admin users")
+    logger.info("Setting up admin users")
     config_path = os.path.join(INSTALL_PREFIX, 'config.yaml')
     if os.path.exists(config_path):
         with open(config_path, 'r') as f:
@@ -234,7 +248,7 @@ def ensure_jupyterhub_running(times=4):
 
     for i in range(times):
         try:
-            print('Waiting for JupyterHub to come up ({}/{} tries)'.format(i + 1, times))
+            logger.info('Waiting for JupyterHub to come up ({}/{} tries)'.format(i + 1, times))
             urlopen('http://127.0.0.1')
             return
         except HTTPError as h:
@@ -269,19 +283,21 @@ def main():
 
     args = argparser.parse_args()
 
+
+
     ensure_admins(args.admin)
 
     ensure_usergroups()
     ensure_user_environment(args.user_requirements_txt_url)
 
-    print("Setting up JupyterHub...")
+    logger.info("Setting up JupyterHub...")
     ensure_node()
     ensure_jupyterhub_package(HUB_ENV_PREFIX)
     ensure_chp_package(HUB_ENV_PREFIX)
     ensure_jupyterhub_service(HUB_ENV_PREFIX)
     ensure_jupyterhub_running()
 
-    print("Done!")
+    logger.info("Done!")
 
 
 if __name__ == '__main__':