Packages in dom0 are not being updated

[conorsch]

Discovered during post-release testing of 0.5.1 today (#643). The graphical updater has stopped running qubes-dom0-update as part of its standard logic, so new RPMs, such as 0.5.1, are not being installed automatically. The upstream qubes-update-gui tool is unaffected, and continues to work properly.

The problem was introduced in 0.5.0, via the template consolidation PR, specifically this line: https://github.com/freedomofpress/securedrop-workstation/pull/619/files#diff-d0118b9cd7e4fe0ee2bfa80461f1aa3329be6f49d0b29c5874fde88ad7e1e1f0R179

Although the call to Updater.apply_updates() properly passes in dom0 as a target, the generator returned by that function is never iterated over, so the logic in the function never executes. Compare with the call to the same function lower down, where the results are iterated over: https://github.com/freedomofpress/securedrop-workstation/pull/619/files#diff-d0118b9cd7e4fe0ee2bfa80461f1aa3329be6f49d0b29c5874fde88ad7e1e1f0R197-R201

Let's modify that logic to ensure that dom0 packages are updated as a first step. In order for this change to land, we'll need to release a 0.5.2, and once it's available, instruct pilot participants to run sudo qubes-dom0-update manually to pull down the latest. Thereafter, a new invocation of the GUI updater will work as expected.

[conorsch]

Tested an upgrade from 0.5.1 clean install to 0.5.2, confirmed the update logic is restored. Log messages below to illustrate.

full launcher.log, included before and after upgrade

2020-11-23 11:05:08,139 - __main__:46(main) INFO: Starting SecureDrop Launcher
2020-11-23 11:05:08,140 - sdw_updater_gui.Updater:294(read_dom0_update_flag_from_disk) INFO: Cannot read dom0 status flag, assuming first run
2020-11-23 11:05:08,140 - sdw_updater_gui.Updater:458(should_launch_updater) INFO: Update status not available, launching updater.
2020-11-23 11:05:08,849 - sdw_updater_gui.UpdaterApp:126(apply_all_updates) INFO: Starting UpgradeThread
2020-11-23 11:05:08,852 - sdw_updater_gui.Updater:337(apply_dom0_state) INFO: Applying dom0 state
2020-11-23 11:05:08,867 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 5%
2020-11-23 11:05:08,868 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 10%
2020-11-23 11:05:22,348 - sdw_updater_gui.Updater:340(apply_dom0_state) INFO: Dom0 state applied
2020-11-23 11:05:22,348 - sdw_updater_gui.Updater:88(apply_updates) INFO: Applying all updates
2020-11-23 11:05:22,348 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 15%
2020-11-23 11:05:22,348 - sdw_updater_gui.Updater:150(_apply_updates_vm) INFO: Updating whonix-gw-15
2020-11-23 11:06:08,836 - sdw_updater_gui.Updater:161(_apply_updates_vm) INFO: whonix-gw-15 update successful
2020-11-23 11:06:08,837 - sdw_updater_gui.Updater:150(_apply_updates_vm) INFO: Updating sd-large-buster-template
2020-11-23 11:06:08,840 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 15%
2020-11-23 11:07:01,538 - sdw_updater_gui.Updater:161(_apply_updates_vm) INFO: sd-large-buster-template update successful
2020-11-23 11:07:01,539 - sdw_updater_gui.Updater:150(_apply_updates_vm) INFO: Updating sd-small-buster-template
2020-11-23 11:07:01,542 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 40%
2020-11-23 11:07:54,124 - sdw_updater_gui.Updater:161(_apply_updates_vm) INFO: sd-small-buster-template update successful
2020-11-23 11:07:54,124 - sdw_updater_gui.Updater:150(_apply_updates_vm) INFO: Updating fedora-32
2020-11-23 11:07:54,124 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 65%
2020-11-23 11:08:52,447 - sdw_updater_gui.Updater:161(_apply_updates_vm) INFO: fedora-32 update successful
2020-11-23 11:08:52,447 - sdw_updater_gui.Updater:369(shutdown_and_start_vms) INFO: Shutting down SDW TemplateVMs for updates
2020-11-23 11:08:52,447 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 90%
2020-11-23 11:08:53,028 - sdw_updater_gui.Updater:373(shutdown_and_start_vms) INFO: Shutting down SDW AppVMs for updates
2020-11-23 11:09:04,107 - sdw_updater_gui.Updater:381(shutdown_and_start_vms) INFO: Safely shutting down system VM: sys-usb
2020-11-23 11:09:09,045 - sdw_updater_gui.Updater:381(shutdown_and_start_vms) INFO: Safely shutting down system VM: sys-whonix
2020-11-23 11:09:13,050 - sdw_updater_gui.Updater:388(shutdown_and_start_vms) INFO: Killing system VM: sys-firewall
2020-11-23 11:09:16,718 - sdw_updater_gui.Updater:388(shutdown_and_start_vms) INFO: Killing system VM: sys-net
2020-11-23 11:09:19,618 - sdw_updater_gui.Updater:397(shutdown_and_start_vms) INFO: Starting fedora-based system VMs after updates
2020-11-23 11:09:19,769 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sys-net: b'default-mgmt-dvm\ndom0\nwork\n'
2020-11-23 11:09:37,165 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sys-firewall: b'default-mgmt-dvm\ndom0\nsys-net\nwork\n'
2020-11-23 11:09:45,568 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sys-whonix: b'default-mgmt-dvm\ndom0\nsys-firewall\nsys-net\nwork\n'
2020-11-23 11:09:53,144 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sys-usb: b'default-mgmt-dvm\ndom0\nsys-firewall\nsys-net\nsys-whonix\nwork\n'
2020-11-23 11:10:06,927 - sdw_updater_gui.Updater:401(shutdown_and_start_vms) INFO: Starting SDW VMs after updates
2020-11-23 11:10:07,186 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sd-log: b'default-mgmt-dvm\ndom0\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\nwork\n'
2020-11-23 11:10:27,835 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sd-gpg: b'default-mgmt-dvm\ndom0\nsd-log\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\nwork\n'
2020-11-23 11:10:47,238 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sd-whonix: b'default-mgmt-dvm\ndom0\nsd-gpg\nsd-log\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\nwork\n'
2020-11-23 11:10:55,108 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sd-proxy: b'default-mgmt-dvm\ndom0\nsd-gpg\nsd-log\nsd-whonix\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\nwork\n'
2020-11-23 11:11:16,985 - sdw_updater_gui.Updater:421(_safely_start_vm) INFO: VMs running before start of sd-app: b'default-mgmt-dvm\ndom0\nsd-gpg\nsd-log\nsd-proxy\nsd-whonix\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\nwork\n'
2020-11-23 11:11:36,451 - sdw_updater_gui.Updater:294(read_dom0_update_flag_from_disk) INFO: Cannot read dom0 status flag, assuming first run
2020-11-23 11:11:36,451 - sdw_updater_gui.Updater:207(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in sd-app
2020-11-23 11:11:38,859 - sdw_updater_gui.Updater:216(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in dom0
2020-11-23 11:11:38,861 - sdw_updater_gui.Updater:175(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-11-23 11:11:38 in sd-app
2020-11-23 11:11:39,118 - sdw_updater_gui.Updater:188(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-11-23 11:11:38 in dom0
2020-11-23 11:11:39,119 - sdw_updater_gui.UpdaterApp:77(upgrade_status) INFO: Signal: upgrade_status {'recommended_action': <UpdateStatus.UPDATES_OK: '0'>, 'whonix-gw-15': <UpdateStatus.UPDATES_OK: '0'>, 'sd-large-buster-template': <UpdateStatus.UPDATES_OK: '0'>, 'sd-small-buster-template': <UpdateStatus.UPDATES_OK: '0'>, 'fedora-32': <UpdateStatus.UPDATES_OK: '0'>}
2020-11-23 11:11:39,123 - sdw_updater_gui.UpdaterApp:90(upgrade_status) INFO: VMs have been succesfully updated, OK to start client
2020-11-23 11:13:30,099 - sdw_updater_gui.UpdaterApp:27(launch_securedrop_client) INFO: Launching SecureDrop client
2020-11-23 11:59:16,199 - __main__:46(main) INFO: Starting SecureDrop Launcher
2020-11-23 11:59:16,211 - sdw_updater_gui.Updater:438(should_launch_updater) INFO: Updates OK and interval not expired, launching client.
2020-11-23 11:59:16,212 - sdw_updater_gui.UpdaterApp:27(launch_securedrop_client) INFO: Launching SecureDrop client
2020-11-23 12:03:34,296 - __main__:46(main) INFO: Starting SecureDrop Launcher
2020-11-23 12:03:34,298 - sdw_updater_gui.Updater:443(should_launch_updater) INFO: Update interval expired: launching updater.
2020-11-23 12:03:37,631 - sdw_updater_gui.UpdaterApp:126(apply_all_updates) INFO: Starting UpgradeThread
2020-11-23 12:03:37,701 - sdw_updater_gui.Updater:88(apply_updates) INFO: Applying all updates to VMs: ['dom0']
2020-11-23 12:03:37,719 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 5%
2020-11-23 12:03:41,660 - sdw_updater_gui.Updater:133(_check_updates_dom0) INFO: No updates available for dom0
2020-11-23 12:03:41,660 - sdw_updater_gui.Updater:346(apply_dom0_state) INFO: Applying dom0 state
2020-11-23 12:03:41,664 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 10%
2020-11-23 12:03:41,676 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 10%
2020-11-23 12:04:02,926 - sdw_updater_gui.Updater:349(apply_dom0_state) INFO: Dom0 state applied
2020-11-23 12:04:02,927 - sdw_updater_gui.Updater:88(apply_updates) INFO: Applying all updates to VMs: {'fedora-32', 'whonix-gw-15', 'sd-small-buster-template', 'sd-large-buster-template'}
2020-11-23 12:04:02,927 - sdw_updater_gui.Updater:159(_apply_updates_vm) INFO: Updating fedora-32
2020-11-23 12:04:02,927 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 15%
2020-11-23 12:04:57,425 - sdw_updater_gui.Updater:170(_apply_updates_vm) INFO: fedora-32 update successful
2020-11-23 12:04:57,425 - sdw_updater_gui.Updater:159(_apply_updates_vm) INFO: Updating whonix-gw-15
2020-11-23 12:04:57,425 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 30%
2020-11-23 12:05:46,310 - sdw_updater_gui.Updater:170(_apply_updates_vm) INFO: whonix-gw-15 update successful
2020-11-23 12:05:46,310 - sdw_updater_gui.Updater:159(_apply_updates_vm) INFO: Updating sd-small-buster-template
2020-11-23 12:05:46,310 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 45%
2020-11-23 12:06:41,850 - sdw_updater_gui.Updater:170(_apply_updates_vm) INFO: sd-small-buster-template update successful
2020-11-23 12:06:41,850 - sdw_updater_gui.Updater:159(_apply_updates_vm) INFO: Updating sd-large-buster-template
2020-11-23 12:06:41,850 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 60%
2020-11-23 12:07:38,774 - sdw_updater_gui.Updater:170(_apply_updates_vm) INFO: sd-large-buster-template update successful
2020-11-23 12:07:38,774 - sdw_updater_gui.Updater:378(shutdown_and_start_vms) INFO: Shutting down SDW TemplateVMs for updates
2020-11-23 12:07:38,779 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 75%
2020-11-23 12:07:39,378 - sdw_updater_gui.Updater:382(shutdown_and_start_vms) INFO: Shutting down SDW AppVMs for updates
2020-11-23 12:07:57,232 - sdw_updater_gui.Updater:390(shutdown_and_start_vms) INFO: Safely shutting down system VM: sys-usb
2020-11-23 12:08:01,849 - sdw_updater_gui.Updater:390(shutdown_and_start_vms) INFO: Safely shutting down system VM: sys-whonix
2020-11-23 12:08:05,687 - sdw_updater_gui.Updater:397(shutdown_and_start_vms) INFO: Killing system VM: sys-firewall
2020-11-23 12:08:08,626 - sdw_updater_gui.Updater:397(shutdown_and_start_vms) INFO: Killing system VM: sys-net
2020-11-23 12:08:11,325 - sdw_updater_gui.Updater:406(shutdown_and_start_vms) INFO: Starting fedora-based system VMs after updates
2020-11-23 12:08:11,472 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sys-net: b'dom0\n'
2020-11-23 12:08:22,575 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sys-firewall: b'dom0\nsys-net\n'
2020-11-23 12:08:31,073 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sys-whonix: b'dom0\nsys-firewall\nsys-net\n'
2020-11-23 12:08:37,898 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sys-usb: b'dom0\nsys-firewall\nsys-net\nsys-whonix\n'
2020-11-23 12:08:49,801 - sdw_updater_gui.Updater:410(shutdown_and_start_vms) INFO: Starting SDW VMs after updates
2020-11-23 12:08:50,026 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sd-log: b'dom0\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\n'
2020-11-23 12:09:07,944 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sd-gpg: b'dom0\nsd-log\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\n'
2020-11-23 12:09:24,920 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sd-whonix: b'dom0\nsd-gpg\nsd-log\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\n'
2020-11-23 12:09:32,821 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sd-proxy: b'dom0\nsd-gpg\nsd-log\nsd-whonix\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\n'
2020-11-23 12:09:53,265 - sdw_updater_gui.Updater:430(_safely_start_vm) INFO: VMs running before start of sd-app: b'dom0\nsd-gpg\nsd-log\nsd-proxy\nsd-whonix\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\n'
2020-11-23 12:10:12,282 - sdw_updater_gui.Updater:216(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in sd-app
2020-11-23 12:10:14,734 - sdw_updater_gui.Updater:225(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in dom0
2020-11-23 12:10:14,736 - sdw_updater_gui.Updater:184(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-11-23 12:10:14 in sd-app
2020-11-23 12:10:14,998 - sdw_updater_gui.Updater:197(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-11-23 12:10:14 in dom0
2020-11-23 12:10:14,999 - sdw_updater_gui.UpdaterApp:77(upgrade_status) INFO: Signal: upgrade_status {'whonix-gw-15': <UpdateStatus.UPDATES_OK: '0'>, 'fedora-32': <UpdateStatus.UPDATES_OK: '0'>, 'dom0': <UpdateStatus.UPDATES_OK: '0'>, 'recommended_action': <UpdateStatus.UPDATES_OK: '0'>, 'apply_dom0': '0', 'sd-small-buster-template': <UpdateStatus.UPDATES_OK: '0'>, 'sd-large-buster-template': <UpdateStatus.UPDATES_OK: '0'>}
2020-11-23 12:10:15,003 - sdw_updater_gui.UpdaterApp:90(upgrade_status) INFO: VMs have been succesfully updated, OK to start client
2020-11-23 12:18:25,173 - sdw_updater_gui.UpdaterApp:27(launch_securedrop_client) INFO: Launching SecureDrop client

To make a bit clearer, here are the specific differences verifying upgrade functionality:

Before

2020-11-23 11:05:08,849 - sdw_updater_gui.UpdaterApp:126(apply_all_updates) INFO: Starting UpgradeThread
2020-11-23 11:05:08,852 - sdw_updater_gui.Updater:337(apply_dom0_state) INFO: Applying dom0 state
2020-11-23 11:05:08,867 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 5%
2020-11-23 11:05:08,868 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 10%
2020-11-23 11:05:22,348 - sdw_updater_gui.Updater:340(apply_dom0_state) INFO: Dom0 state applied
2020-11-23 11:05:22,348 - sdw_updater_gui.Updater:88(apply_updates) INFO: Applying all updates

After

2020-11-23 12:03:37,631 - sdw_updater_gui.UpdaterApp:126(apply_all_updates) INFO: Starting UpgradeThread
2020-11-23 12:03:37,701 - sdw_updater_gui.Updater:88(apply_updates) INFO: Applying all updates to VMs: ['dom0']
2020-11-23 12:03:37,719 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 5%
2020-11-23 12:03:41,660 - sdw_updater_gui.Updater:133(_check_updates_dom0) INFO: No updates available for dom0
2020-11-23 12:03:41,660 - sdw_updater_gui.Updater:346(apply_dom0_state) INFO: Applying dom0 state
2020-11-23 12:03:41,664 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 10%
2020-11-23 12:03:41,676 - sdw_updater_gui.UpdaterApp:117(update_progress_bar) INFO: Signal: Progress 10%
2020-11-23 12:04:02,926 - sdw_updater_gui.Updater:349(apply_dom0_state) INFO: Dom0 state applied

The "No updates available for dom0" message in the "After" logs shows that the function executed properly:

securedrop-workstation/launcher/sdw_updater_gui/Updater.py

Line 133 in 9cb41a8

sdlog.info("No updates available for dom0")