Merge pull request #532 from freedomofpress/531-long-live-sys-usb

Safely shut down sys-usb; tweak logging

launcher/sdw_updater_gui/Updater.py

@@ -402,14 +402,14 @@ def shutdown_and_start_vms():
     correct order of operations, as sd-whonix cannot shutdown if sd-proxy is powered
     on, for example.
 
-    System AppVMs(sys-net, sys-firewall and sys-usb) will need to be killed and restarted
-    in case they are being used by another non-workstation VM.
+    All system AppVMs (sys-net, sys-firewall and sys-usb) need to be restarted.
+    We use qvm-kill for sys-firewall and sys-net, because a shutdown may fail
+    if they are currently in use as NetVMs by any of the user's other VMs.
     """
 
     sdw_vms_in_order = [
         "sd-app",
         "sd-proxy",
-        "sys-whonix",
         "sd-whonix",
         "sd-gpg",
         "sd-log",
@@ -418,26 +418,36 @@ def shutdown_and_start_vms():
     # All TemplateVMs minus dom0
     sdw_templates = [val for key, val in current_templates.items() if key != "dom0"]
 
-    sdlog.info("Ensure TemplateVMs are shut down")
+    sdlog.info("Shutting down SDW TemplateVMs for updates")
     for vm in sdw_templates:
         _safely_shutdown_vm(vm)
 
-    sdlog.info("Shutting down SDW VMs for updates")
+    sdlog.info("Shutting down SDW AppVMs for updates")
     for vm in sdw_vms_in_order:
         _safely_shutdown_vm(vm)
 
-    sys_vms_in_order = ["sys-firewall", "sys-net", "sys-usb"]
-    sdlog.info("Killing system fedora-based VMs for updates")
-    for vm in sys_vms_in_order:
+    # System VMs that can be safely shut down (order should not matter, but will
+    # be respected).
+    safe_sys_vms_in_order = ["sys-usb", "sys-whonix"]
+    for vm in safe_sys_vms_in_order:
+        sdlog.info("Safely shutting down system VM: {}".format(vm))
+        _safely_shutdown_vm(vm)
+
+    # TODO: Use of qvm-kill should be considered unsafe and may have unexpected
+    # side effects. We should aim for a more graceful shutdown strategy.
+    unsafe_sys_vms_in_order = ["sys-firewall", "sys-net"]
+    for vm in unsafe_sys_vms_in_order:
+        sdlog.info("Killing system VM: {}".format(vm))
         try:
             subprocess.check_output(["qvm-kill", vm], stderr=subprocess.PIPE)
         except subprocess.CalledProcessError as e:
-            sdlog.error("Error while killing {}".format(vm))
+            sdlog.error("Error while killing system VM: {}".format(vm))
             sdlog.error(str(e))
             sdlog.error(str(e.stderr))
 
-    sdlog.info("Starting system fedora-based VMs after updates")
-    for vm in reversed(sys_vms_in_order):
+    all_sys_vms_in_order = safe_sys_vms_in_order + unsafe_sys_vms_in_order
+    sdlog.info("Starting fedora-based system VMs after updates")
+    for vm in reversed(all_sys_vms_in_order):
         _safely_start_vm(vm)
 
     sdlog.info("Starting SDW VMs after updates")

launcher/tests/test_updater.py

@@ -676,12 +676,16 @@ def test_shutdown_and_start_vms(
     sys_vm_kill_calls = [
         call(["qvm-kill", "sys-firewall"], stderr=-1),
         call(["qvm-kill", "sys-net"], stderr=-1),
-        call(["qvm-kill", "sys-usb"], stderr=-1),
     ]
-    sys_vm_start_calls = [
+    sys_vm_shutdown_calls = [
         call("sys-usb"),
+        call("sys-whonix"),
+    ]
+    sys_vm_start_calls = [
         call("sys-net"),
         call("sys-firewall"),
+        call("sys-whonix"),
+        call("sys-usb"),
     ]
     template_vm_calls = [
         call("fedora-30"),
@@ -696,14 +700,15 @@ def test_shutdown_and_start_vms(
     app_vm_calls = [
         call("sd-app"),
         call("sd-proxy"),
-        call("sys-whonix"),
         call("sd-whonix"),
         call("sd-gpg"),
         call("sd-log"),
     ]
     updater.shutdown_and_start_vms()
     mocked_output.assert_has_calls(sys_vm_kill_calls)
-    mocked_shutdown.assert_has_calls(template_vm_calls + app_vm_calls)
+    mocked_shutdown.assert_has_calls(
+        template_vm_calls + app_vm_calls + sys_vm_shutdown_calls
+    )
     app_vm_calls_reversed = list(reversed(app_vm_calls))
     mocked_start.assert_has_calls(sys_vm_start_calls + app_vm_calls_reversed)
     assert not mocked_error.called
@@ -723,17 +728,16 @@ def test_shutdown_and_start_vms_sysvm_fail(
     sys_vm_kill_calls = [
         call(["qvm-kill", "sys-firewall"], stderr=-1),
         call(["qvm-kill", "sys-net"], stderr=-1),
-        call(["qvm-kill", "sys-usb"], stderr=-1),
     ]
     sys_vm_start_calls = [
-        call("sys-usb"),
         call("sys-net"),
         call("sys-firewall"),
+        call("sys-whonix"),
+        call("sys-usb"),
     ]
     app_vm_calls = [
         call("sd-app"),
         call("sd-proxy"),
-        call("sys-whonix"),
         call("sd-whonix"),
         call("sd-gpg"),
         call("sd-log"),
@@ -749,13 +753,10 @@ def test_shutdown_and_start_vms_sysvm_fail(
         call("securedrop-workstation-buster"),
     ]
     error_calls = [
-        call("Error while killing sys-firewall"),
-        call("Command 'check_output' returned non-zero exit status 1."),
-        call("None"),
-        call("Error while killing sys-net"),
+        call("Error while killing system VM: sys-firewall"),
         call("Command 'check_output' returned non-zero exit status 1."),
         call("None"),
-        call("Error while killing sys-usb"),
+        call("Error while killing system VM: sys-net"),
         call("Command 'check_output' returned non-zero exit status 1."),
         call("None"),
     ]