Merge pull request #690 from freedomofpress/688-detailed-logs

Add detailed logging to separate logfile

launcher/Makefile

@@ -8,7 +8,7 @@ bandit:
 
 .PHONY: test
 test:
-	pytest --cov-report term-missing --cov=sdw_notify --cov=sdw_updater_gui/ --cov=sdw_util -v tests/
+	python -m pytest --cov-report term-missing --cov=sdw_notify --cov=sdw_updater_gui/ --cov=sdw_util -v tests/
 
 black: ## Runs the black code formatter on the launcher code
 	black --check --line-length=100 .

launcher/sdw-launcher.py

@@ -4,7 +4,6 @@
 from sdw_updater_gui import Updater
 from sdw_updater_gui.UpdaterApp import launch_securedrop_client
 from sdw_updater_gui.Updater import should_launch_updater
-import logging
 import sys
 import argparse
 
@@ -36,8 +35,9 @@ def launch_updater():
 
 
 def main(argv):
-    sdlog = logging.getLogger(__name__)
     Util.configure_logging(Updater.LOG_FILE)
+    Util.configure_logging(Updater.DETAIL_LOG_FILE, Updater.DETAIL_LOGGER_PREFIX, backup_count=10)
+    sdlog = Util.get_logger()
     lock_handle = Util.obtain_lock(Updater.LOCK_FILE)
     if lock_handle is None:
         # Preflight updater already running or problems accessing lockfile.

launcher/sdw_notify/Notify.py

@@ -2,12 +2,12 @@
 Utility library for warning the user that security updates have not been applied
 in some time.
 """
-import logging
 import os
 
 from datetime import datetime
+from sdw_util import Util
 
-sdlog = logging.getLogger(__name__)
+sdlog = Util.get_logger(module=__name__)
 
 # The directory where status files and logs are stored
 BASE_DIRECTORY = os.path.join(os.path.expanduser("~"), ".securedrop_launcher")

launcher/sdw_updater_gui/Updater.py

@@ -8,11 +8,11 @@
 """
 
 import json
-import logging
 import os
 import subprocess
 from datetime import datetime, timedelta
 from enum import Enum
+from sdw_util import Util
 
 DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
 DEFAULT_HOME = ".securedrop_launcher"
@@ -22,15 +22,17 @@
 FLAG_FILE_LAST_UPDATED_DOM0 = os.path.join(DEFAULT_HOME, "sdw-last-updated")
 LOCK_FILE = "sdw-launcher.lock"
 LOG_FILE = "launcher.log"
-
+DETAIL_LOG_FILE = "launcher-detail.log"
+DETAIL_LOGGER_PREFIX = "detail"  # For detailed logs such as Salt states
 
 # We use a hardcoded temporary directory path in dom0. As dom0 is not
 # a multi-user environment, we can safely assume that only the Updater is
 # managing that filepath. Later on, we should consider porting the check-migration
 # logic to leverage the Qubes Python API.
 MIGRATION_DIR = "/tmp/sdw-migrations"  # nosec
 
-sdlog = logging.getLogger(__name__)
+sdlog = Util.get_logger(module=__name__)
+detail_log = Util.get_logger(prefix=DETAIL_LOGGER_PREFIX, module=__name__)
 
 # The are the TemplateVMs that require full patch level at boot in order to start the client,
 # as well as their associated TemplateVMs.
@@ -60,13 +62,21 @@ def run_full_install():
     """
     sdlog.info("Running 'sdw-admin --apply' to apply full system state")
     apply_cmd = ["sdw-admin", "--apply"]
+    apply_cmd_for_log = (" ").join(apply_cmd)
     try:
-        subprocess.check_call(apply_cmd)
+        output = subprocess.check_output(apply_cmd)
     except subprocess.CalledProcessError as e:
-        sdlog.error("Failed to apply full system state. Please review system logs.")
+        sdlog.error("Failed to apply full system state. Please review {}.".format(DETAIL_LOG_FILE))
         sdlog.error(str(e))
+        clean_output = Util.strip_ansi_colors(e.output.decode("utf-8").strip())
+        detail_log.error(
+            "Output from failed command: {}\n{}".format(apply_cmd_for_log, clean_output)
+        )
         return UpdateStatus.UPDATES_FAILED
 
+    clean_output = Util.strip_ansi_colors(output.decode("utf-8").strip())
+    detail_log.info("Output from command: {}\n{}".format(apply_cmd_for_log, clean_output))
+
     # Clean up flag requesting migration. Shell out since root created it.
     rm_flag_cmd = ["sudo", "rm", "-rf", MIGRATION_DIR]
     try:
@@ -252,11 +262,11 @@ def _write_updates_status_flag_to_disk(status):
 
 def last_required_reboot_performed():
     """
-        Checks if the dom0 flag file indicates that a reboot is required, and
-        if so, will check current uptime with the data at which the reboot
-        was requested. This will be used by the _write_updates_status_flag_to_disk
-        function to preserve the status UPDATES_REQUIRED instead of updating.
-        """
+    Checks if the dom0 flag file indicates that a reboot is required, and
+    if so, will check current uptime with the data at which the reboot
+    was requested. This will be used by the _write_updates_status_flag_to_disk
+    function to preserve the status UPDATES_REQUIRED instead of updating.
+    """
     flag_contents = read_dom0_update_flag_from_disk(with_timestamp=True)
 
     # No flag exists on disk (yet)
@@ -358,13 +368,19 @@ def apply_dom0_state():
     ensure it is environment-specific.
     """
     sdlog.info("Applying dom0 state")
+    cmd = ["sudo", "qubesctl", "--show-output", "state.highstate"]
+    cmd_for_log = " ".join(cmd)
     try:
-        subprocess.check_call(["sudo", "qubesctl", "--show-output", "state.highstate"])
+        output = subprocess.check_output(cmd)
         sdlog.info("Dom0 state applied")
+        clean_output = Util.strip_ansi_colors(output.decode("utf-8").strip())
+        detail_log.info("Output from command: {}\n{}".format(cmd_for_log, clean_output))
         return UpdateStatus.UPDATES_OK
     except subprocess.CalledProcessError as e:
-        sdlog.error("Failed to apply dom0 state")
+        sdlog.error("Failed to apply dom0 state. See {} for details.".format(DETAIL_LOG_FILE))
         sdlog.error(str(e))
+        clean_output = Util.strip_ansi_colors(e.output.decode("utf-8").strip())
+        detail_log.error("Output from failed command: {}\n{}".format(cmd_for_log, clean_output))
         return UpdateStatus.UPDATES_FAILED
 
 

launcher/sdw_updater_gui/UpdaterApp.py

@@ -2,7 +2,6 @@
 from sdw_updater_gui import Updater
 from sdw_updater_gui.Updater import UpdateStatus
 from sdw_util import Util
-import logging
 import subprocess
 import sys
 
@@ -16,7 +15,7 @@
     from sdw_updater_gui.UpdaterAppUi import Ui_UpdaterDialog
 
 
-logger = logging.getLogger(__name__)
+logger = Util.get_logger(module=__name__)
 
 
 def launch_securedrop_client():

launcher/sdw_util/Util.py

@@ -5,6 +5,7 @@
 import fcntl
 import os
 import logging
+import re
 import subprocess
 
 from logging.handlers import TimedRotatingFileHandler
@@ -27,24 +28,33 @@
 # Format for those logs
 LOG_FORMAT = "%(asctime)s - %(name)s:%(lineno)d(%(funcName)s) " "%(levelname)s: %(message)s"
 
-sdlog = logging.getLogger(__name__)
+# Namespace for primary logger, additional namespaces should be defined by module user
+SD_LOGGER_PREFIX = "sd"
 
+sdlog = logging.getLogger(SD_LOGGER_PREFIX + "." + __name__)
 
-def configure_logging(log_file):
+
+def configure_logging(log_file, logger_namespace=SD_LOGGER_PREFIX, backup_count=0):
     """
     All logging related settings are set up by this function.
+
+    `log_file` - the filename
+    `logger_namespace - the prefix used for all log events by this logger
+    `backup_count` - if nonzero, at most backup_count files will be kept
     """
 
     if not os.path.exists(LOG_DIRECTORY):
         os.makedirs(LOG_DIRECTORY)
 
     formatter = logging.Formatter((LOG_FORMAT))
 
-    handler = TimedRotatingFileHandler(os.path.join(LOG_DIRECTORY, log_file))
+    handler = TimedRotatingFileHandler(
+        os.path.join(LOG_DIRECTORY, log_file), backupCount=backup_count
+    )
     handler.setFormatter(formatter)
     handler.setLevel(logging.INFO)
 
-    log = logging.getLogger()
+    log = logging.getLogger(logger_namespace)
     log.setLevel(logging.INFO)
     log.addHandler(handler)
 
@@ -163,3 +173,17 @@ def get_qt_version():
         return version
     else:
         raise ValueError("Qt version not supported: {}".format(version_str))
+
+
+def get_logger(prefix=SD_LOGGER_PREFIX, module=None):
+    if module is None:
+        return logging.getLogger(prefix)
+    else:
+        return logging.getLogger(prefix + "." + module)
+
+
+def strip_ansi_colors(str):
+    """
+    Strip ANSI colors from command output
+    """
+    return re.sub(r"\u001b\[.*?[@-~]", "", str)

launcher/tests/test_updater.py

@@ -780,7 +780,7 @@ def test_should_run_updater_invalid_status_value(mocked_write):
             assert updater.should_launch_updater(TEST_INTERVAL) is True
 
 
-@mock.patch("subprocess.check_call")
+@mock.patch("subprocess.check_output", side_effect=[b""])
 @mock.patch("Updater.sdlog.error")
 @mock.patch("Updater.sdlog.info")
 def test_apply_dom0_state_success(mocked_info, mocked_error, mocked_subprocess):
@@ -794,15 +794,16 @@ def test_apply_dom0_state_success(mocked_info, mocked_error, mocked_subprocess):
 
 
 @mock.patch(
-    "subprocess.check_call", side_effect=[subprocess.CalledProcessError(1, "check_call"), "0"],
+    "subprocess.check_output",
+    side_effect=[subprocess.CalledProcessError(1, cmd="check_output", output=b"")],
 )
 @mock.patch("Updater.sdlog.error")
 @mock.patch("Updater.sdlog.info")
 def test_apply_dom0_state_failure(mocked_info, mocked_error, mocked_subprocess):
     updater.apply_dom0_state()
     log_error_calls = [
-        call("Failed to apply dom0 state"),
-        call("Command 'check_call' returned non-zero exit status 1."),
+        call("Failed to apply dom0 state. See launcher-detail.log for details."),
+        call("Command 'check_output' returned non-zero exit status 1."),
     ]
     mocked_subprocess.assert_called_once_with(
         ["sudo", "qubesctl", "--show-output", "state.highstate"]
@@ -830,8 +831,9 @@ def test_migration_not_required(mocked_info, mocked_listdir, mocked_exists):
 
 
 @mock.patch("Updater.sdlog.info")
+@mock.patch("subprocess.check_output", return_value=b"")
 @mock.patch("subprocess.check_call")
-def test_run_full_install(mocked_call, mocked_info):
+def test_run_full_install(mocked_call, mocked_output, mocked_info):
     """
     When a full migration is requested
       And the migration succeeds
@@ -843,15 +845,22 @@ def test_run_full_install(mocked_call, mocked_info):
     MIGRATION_DIR = "/tmp/potato"  # nosec
     with mock.patch("Updater.MIGRATION_DIR", MIGRATION_DIR):
         result = updater.run_full_install()
-    calls = [call(["sdw-admin", "--apply"]), call(["sudo", "rm", "-rf", MIGRATION_DIR])]
-    assert mocked_call.call_count == 2
+    check_outputs = [call(["sdw-admin", "--apply"])]
+    check_calls = [call(["sudo", "rm", "-rf", MIGRATION_DIR])]
+    assert mocked_output.call_count == 1
+    assert mocked_call.call_count == 1
     assert result == UpdateStatus.UPDATES_OK
-    mocked_call.assert_has_calls(calls, any_order=False)
+    mocked_output.assert_has_calls(check_outputs, any_order=False)
+    mocked_call.assert_has_calls(check_calls, any_order=False)
 
 
 @mock.patch("Updater.sdlog.error")
-@mock.patch("subprocess.check_call", side_effect=subprocess.CalledProcessError(1, "check_call"))
-def test_run_full_install_with_error(mocked_call, mocked_error):
+@mock.patch(
+    "subprocess.check_output",
+    side_effect=[subprocess.CalledProcessError(1, cmd="check_output", output=b"")],
+)
+@mock.patch("subprocess.check_call", return_value=0)
+def test_run_full_install_with_error(mocked_call, mocked_output, mocked_error):
     """
     When a full migration is requested
       And the migration fails in any way
@@ -863,17 +872,19 @@ def test_run_full_install_with_error(mocked_call, mocked_error):
     with mock.patch("Updater.MIGRATION_DIR", MIGRATION_DIR):
         result = updater.run_full_install()
     calls = [call(["sdw-admin", "--apply"])]
-    assert mocked_call.call_count == 1
+    assert mocked_output.call_count == 1
+    assert mocked_call.call_count == 0
     assert mocked_error.called
     assert result == UpdateStatus.UPDATES_FAILED
-    mocked_call.assert_has_calls(calls, any_order=False)
+    mocked_output.assert_has_calls(calls, any_order=False)
 
 
 @mock.patch("Updater.sdlog.error")
+@mock.patch("subprocess.check_output", return_value=b"")
 @mock.patch(
-    "subprocess.check_call", side_effect=[None, subprocess.CalledProcessError(1, "check_call")]
+    "subprocess.check_call", side_effect=[subprocess.CalledProcessError(1, cmd="check_call")]
 )
-def test_run_full_install_with_flag_error(mocked_call, mocked_error):
+def test_run_full_install_with_flag_error(mocked_call, mocked_output, mocked_error):
     """
     When a full migration is requested
       And the migration succeeds
@@ -884,8 +895,11 @@ def test_run_full_install_with_flag_error(mocked_call, mocked_error):
     MIGRATION_DIR = "/tmp/potato"  # nosec
     with mock.patch("Updater.MIGRATION_DIR", MIGRATION_DIR):
         result = updater.run_full_install()
-    calls = [call(["sdw-admin", "--apply"]), call(["sudo", "rm", "-rf", MIGRATION_DIR])]
-    assert mocked_call.call_count == 2
+    check_outputs = [call(["sdw-admin", "--apply"])]
+    check_calls = [call(["sudo", "rm", "-rf", MIGRATION_DIR])]
+    assert mocked_output.call_count == 1
+    assert mocked_call.call_count == 1
     assert mocked_error.called
     assert result == UpdateStatus.UPDATES_FAILED
-    mocked_call.assert_has_calls(calls, any_order=False)
+    mocked_output.assert_has_calls(check_outputs, any_order=False)
+    mocked_call.assert_has_calls(check_calls, any_order=False)

launcher/tests/test_util.py

@@ -289,3 +289,16 @@ def test_pick_bad_qt(
         "Util.OS_RELEASE_FILE", os.path.join(FIXTURES_PATH, "os-release-qubes-4.0")
     ), pytest.raises(ValueError):
         util.get_qt_version()
+
+
+def test_get_logger():
+    """
+    Test whether the logging utility functions returns namespaced loggers in
+    the `prefix.module` format.
+    """
+    test_prefix = "potato"
+    test_module = "salad"
+    logger = util.get_logger(prefix=test_prefix)
+    assert logger.name == test_prefix
+    logger = util.get_logger(prefix=test_prefix, module=test_module)
+    assert logger.name == "{}.{}".format(test_prefix, test_module)