Improve logging of updater failure cases

[conorsch]

To aid in debugging the custom updater logic, let's add more informative logging when errors are encountered. We currently log that an error occurred during VM start or stop, e.g.

securedrop-workstation/launcher/sdw_updater_gui/Updater.py

Lines 449 to 453 in f2afb12

	try:
	subprocess.check_call(["qvm-start", "--skip-if-running", vm])
	except subprocess.CalledProcessError as e:
	sdlog.error("Error while starting {}".format(vm))
	sdlog.error(str(e))

but not what the specific error was. We'd need to catch stderr and log that, as well. Since we're still using subprocess to shell out, we'll have to use PIPE for stderr, otherwise the "stderr" attribute on the exception will be empty.

We also have a request for explicit logging of xl list before the start actions #498 (comment), which sounds like a great idea. Non-decoded bytestrings should be logged to ensure that newlines aren't interpreted.

[conorsch]

Slight change of plans, based on local testing.

We also have a request for explicit logging of xl list before the start actions

Rather than using xl list, let's use qvm-ls --running --raw-list. Reason being, the former results in inscrutable log lines, whereas the latter is pretty readable. We lose the xid info, but for the purpose of figuring out "which VMs were running ahead of time VM 'x' was started," it should be more than sufficient.

Comparison of log verbosity

Too verbose by far

2020-04-01 17:53:03,242 - sdw_updater_gui.Updater:417(shutdown_and_start_vms) INFO: Shutting down SDW VMs for updates
2020-04-01 17:53:03,449 - sdw_updater_gui.Updater:445(_safely_shutdown_vm) ERROR: Failed to shut down sys-whonix
2020-04-01 17:53:03,449 - sdw_updater_gui.Updater:446(_safely_shutdown_vm) ERROR: Command '['qvm-shutdown', '--wait', 'sys-whonix']' returned non-zero exit status 1
2020-04-01 17:53:03,449 - sdw_updater_gui.Updater:447(_safely_shutdown_vm) ERROR: b'qvm-shutdown: error: Failed to shut down: sys-whonix\n'
2020-04-01 17:53:13,876 - sdw_updater_gui.Updater:422(shutdown_and_start_vms) INFO: Killing system fedora-based VMs for updates
2020-04-01 17:53:28,997 - sdw_updater_gui.Updater:431(shutdown_and_start_vms) INFO: Starting system fedora-based VMs after updates
2020-04-01 17:53:29,022 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3992     4     r-----    9454.1\nfpf-vault                                   18   733     2     -b----      80.7\nfpf-infra                                   19  2044     2     -b----     167.1\nsd-dev                                      20  1820     2     -b----     131.7\nfpf-web                                     21  5983     2     -b----    7979.5\nfpf-vpn                                     22   733     2     -b----      73.4\nfpf-vidchat                                 23  3165     2     -b----   10468.3\nsys-firewall-inner                          24   733     2     -b----      70.2\nfpf-email                                   27  1781     2     -b----     132.5\nfpf-signal                                  38  1983     2     -b----    2801.7\n(null)                                      61     0     2     --p--d     739.2\nsys-whonix                                  75  1983     2     -b----     270.4\nsd-devices                                  76  1652     2     -b----      62.3\nsd-devices-dm                               77   144     1     -b----     413.4\nanon-whonix                                 80  3846     2     -b----     240.4\nsd-log                                     144   400     1     ------       0.0\nsd-log-dm                                  145   144     1     r-----       0.9\n'
2020-04-01 17:53:44,931 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3989     4     r-----    9463.6\nfpf-vault                                   18   733     2     -b----      80.8\nfpf-infra                                   19  1979     2     -b----     167.2\nsd-dev                                      20  1758     2     -b----     131.8\nfpf-web                                     21  5983     2     -b----    7980.5\nfpf-vpn                                     22   733     2     -b----      73.5\nfpf-vidchat                                 23  3083     2     -b----   10469.4\nsys-firewall-inner                          24   733     2     -b----      70.2\nfpf-email                                   27  1719     2     -b----     132.6\nfpf-signal                                  38  1983     2     -b----    2802.7\nsys-whonix                                  75  1958     2     -b----     270.8\nsd-devices                                  76  1593     2     -b----      62.5\nsd-devices-dm                               77   144     1     -b----     413.9\nanon-whonix                                 80  3754     2     -b----     240.6\nsd-log                                     144   400     2     ------      13.0\nsd-log-dm                                  145   144     1     -b----       4.1\nsys-usb                                    146   284     2     r-----       4.8\nsys-usb-dm                                 147   144     1     -b----       7.1\n'
2020-04-01 17:54:05,920 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3981     4     r-----    9485.4\nfpf-vault                                   18   733     2     -b----      80.8\nfpf-infra                                   19  1772     2     -b----     167.4\nsd-dev                                      20  1559     2     -b----     132.0\nfpf-web                                     21  5983     2     -b----    7981.7\nfpf-vpn                                     22   733     2     -b----      73.7\nfpf-vidchat                                 23  2840     2     -b----   10470.8\nsys-firewall-inner                          24   733     2     -b----      70.3\nfpf-email                                   27  1521     2     -b----     132.8\nfpf-signal                                  38  1983     2     -b----    2804.1\nsys-whonix                                  75  1752     2     -b----     271.5\nsd-devices                                  76  1398     2     -b----      62.7\nsd-devices-dm                               77   144     1     -b----     414.5\nanon-whonix                                 80  3489     2     -b----     240.9\nsd-log                                     144  1360     2     -b----      22.7\nsd-log-dm                                  145   144     1     -b----       4.6\nsys-usb                                    146   284     2     -b----      11.6\nsys-usb-dm                                 147   144     1     -b----       7.5\nsys-net                                    148   384     2     r-----       5.3\nsys-net-dm                                 149   144     1     -b----       7.3\n'
2020-04-01 17:54:16,211 - sdw_updater_gui.Updater:435(shutdown_and_start_vms) INFO: Starting SDW VMs after updates
2020-04-01 17:54:16,269 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3978     4     r-----    9499.9\nfpf-vault                                   18   733     2     -b----      80.9\nfpf-infra                                   19  1727     2     -b----     167.6\nsd-dev                                      20  1517     2     -b----     132.1\nfpf-web                                     21  5983     2     -b----    7983.8\nfpf-vpn                                     22   733     2     -b----      73.9\nfpf-vidchat                                 23  2775     2     r-----   10471.9\nsys-firewall-inner                          24   733     2     -b----      70.3\nfpf-email                                   27  1480     2     -b----     132.8\nfpf-signal                                  38  1983     2     r-----    2805.3\nsys-whonix                                  75  1707     2     ------     271.9\nsd-devices                                  76  1360     2     -b----      62.8\nsd-devices-dm                               77   144     1     ------     414.9\nanon-whonix                                 80  3411     2     -b----     241.1\nsd-log                                     144  1323     2     -b----      22.8\nsd-log-dm                                  145   144     1     -b----       4.9\nsys-usb                                    146   284     2     -b----      11.9\nsys-usb-dm                                 147   144     1     -b----       7.6\nsys-net                                    148   384     2     ------      11.5\nsys-net-dm                                 149   144     1     -b----       7.5\nsys-firewall                               150   399     2     ------       6.2\n'
2020-04-01 17:54:16,461 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3978     4     r-----    9500.5\nfpf-vault                                   18   733     2     -b----      80.9\nfpf-infra                                   19  1727     2     -b----     167.6\nsd-dev                                      20  1517     2     -b----     132.1\nfpf-web                                     21  5983     2     -b----    7983.8\nfpf-vpn                                     22   733     2     -b----      73.9\nfpf-vidchat                                 23  2775     2     r-----   10472.0\nsys-firewall-inner                          24   733     2     -b----      70.3\nfpf-email                                   27  1480     2     -b----     132.8\nfpf-signal                                  38  1983     2     -b----    2805.3\nsys-whonix                                  75  1707     2     ------     271.9\nsd-devices                                  76  1360     2     -b----      62.8\nsd-devices-dm                               77   144     1     -b----     414.9\nanon-whonix                                 80  3411     2     -b----     241.1\nsd-log                                     144  1323     2     -b----      22.8\nsd-log-dm                                  145   144     1     -b----       4.9\nsys-usb                                    146   284     2     -b----      11.9\nsys-usb-dm                                 147   144     1     -b----       7.6\nsys-net                                    148   384     2     -b----      11.5\nsys-net-dm                                 149   144     1     -b----       7.5\nsys-firewall                               150   399     2     -b----       6.2\n'
2020-04-01 17:54:42,891 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3976     4     r-----    9514.2\nfpf-vault                                   18   733     2     -b----      80.9\nfpf-infra                                   19  1615     2     -b----     167.9\nsd-dev                                      20  1411     2     -b----     132.2\nfpf-web                                     21  5983     2     -b----    7989.0\nfpf-vpn                                     22   733     2     -b----      74.3\nfpf-vidchat                                 23  2638     2     -b----   10474.4\nsys-firewall-inner                          24   733     2     -b----      70.4\nfpf-email                                   27  1375     2     -b----     133.0\nfpf-signal                                  38  1983     2     r-----    2807.1\nsys-whonix                                  75  1596     2     -b----     273.1\nsd-devices                                  76  1258     2     -b----      62.9\nsd-devices-dm                               77   144     1     -b----     415.6\nanon-whonix                                 80  3259     2     -b----     241.4\nsd-log                                     144  1221     2     -b----      23.1\nsd-log-dm                                  145   144     1     -b----       5.7\nsys-usb                                    146   284     2     -b----      12.2\nsys-usb-dm                                 147   144     1     -b----       8.0\nsys-net                                    148   384     2     -b----      11.8\nsys-net-dm                                 149   144     1     -b----       7.9\nsys-firewall                               150   733     2     -b----       8.4\nsd-gpg                                     151   383     2     r-----      17.0\nsd-gpg-dm                                  152   144     1     -b----       4.0\n'
2020-04-01 17:55:08,782 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3974     4     r-----    9528.1\nfpf-vault                                   18   733     2     -b----      81.0\nfpf-infra                                   19  1458     2     -b----     168.0\nsd-dev                                      20  1265     2     -b----     132.4\nfpf-web                                     21  5983     2     -b----    7990.1\nfpf-vpn                                     22   733     2     -b----      74.3\nfpf-vidchat                                 23  2424     2     -b----   10476.1\nsys-firewall-inner                          24   733     2     -b----      70.4\nfpf-email                                   27  1232     2     -b----     133.1\nfpf-signal                                  38  1983     2     -b----    2808.8\nsys-whonix                                  75  1441     2     -b----     273.9\nsd-devices                                  76  1121     2     -b----      63.0\nsd-devices-dm                               77   144     1     -b----     416.3\nanon-whonix                                 80  3112     2     -b----     242.0\nsd-log                                     144  1086     2     -b----      24.0\nsd-log-dm                                  145   144     1     -b----       6.4\nsys-usb                                    146   284     2     -b----      12.8\nsys-usb-dm                                 147   144     1     -b----       8.3\nsys-net                                    148   384     2     -b----      12.2\nsys-net-dm                                 149   144     1     -b----       8.2\nsys-firewall                               150   733     2     -b----       8.6\nsd-gpg                                     151  1039     2     -b----      20.0\nsd-gpg-dm                                  152   144     1     ------       4.7\nsd-app                                     153   383     2     r-----      16.6\nsd-app-dm                                  154   144     1     -b----       4.1\n'
2020-04-01 17:55:19,053 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3972     4     r-----    9539.4\nfpf-vault                                   18   733     2     -b----      81.0\nfpf-infra                                   19  1331     2     -b----     168.1\nsd-dev                                      20  1144     2     -b----     132.5\nfpf-web                                     21  5983     2     -b----    7990.6\nfpf-vpn                                     22   733     2     -b----      74.3\nfpf-vidchat                                 23  2264     2     r-----   10476.8\nsys-firewall-inner                          24   733     2     -b----      70.4\nfpf-email                                   27  1112     2     -b----     133.2\nfpf-signal                                  38  1983     2     -b----    2809.8\nsys-whonix                                  75  1314     2     -b----     274.2\nsd-devices                                  76  1004     2     -b----      63.2\nsd-devices-dm                               77   144     1     -b----     416.6\nanon-whonix                                 80  2930     2     -b----     242.2\nsd-log                                     144  1048     2     -b----      24.8\nsd-log-dm                                  145   144     1     -b----       6.7\nsys-usb                                    146   284     2     r-----      13.2\nsys-usb-dm                                 147   144     1     -b----       8.4\nsys-net                                    148   384     2     -b----      12.3\nsys-net-dm                                 149   144     1     -b----       8.3\nsys-firewall                               150   733     2     -b----       8.8\nsd-gpg                                     151   925     2     -b----      20.2\nsd-gpg-dm                                  152   144     1     -b----       5.1\nsd-app                                     153   942     2     -b----      19.7\nsd-app-dm                                  154   144     1     -b----       4.4\nsd-whonix                                  155   500     2     r-----       7.5\n'
2020-04-01 17:55:47,667 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: xl list before starting VM: b'Name                                        ID   Mem VCPUs\tState\tTime(s)\nDomain-0                                     0  3964     4     r-----    9556.2\nfpf-vault                                   18   733     2     -b----      81.1\nfpf-infra                                   19  1203     2     -b----     168.3\nsd-dev                                      20  1025     2     -b----     132.7\nfpf-web                                     21  5983     2     -b----    7992.4\nfpf-vpn                                     22   733     2     -b----      74.4\nfpf-vidchat                                 23  2097     2     ------   10478.7\nsys-firewall-inner                          24   733     2     -b----      70.5\nfpf-email                                   27   993     2     -b----     133.4\nfpf-signal                                  38  1983     2     -b----    2811.7\nsys-whonix                                  75  1187     2     -b----     274.7\nsd-devices                                  76   891     2     -b----      63.3\nsd-devices-dm                               77   144     1     -b----     417.4\nanon-whonix                                 80  2734     2     -b----     242.5\nsd-log                                     144   932     2     -b----      25.9\nsd-log-dm                                  145   144     1     -b----       7.6\nsys-usb                                    146   284     2     -b----      13.4\nsys-usb-dm                                 147   144     1     -b----       8.8\nsys-net                                    148   384     2     -b----      12.5\nsys-net-dm                                 149   144     1     -b----       8.7\nsys-firewall                               150   733     2     -b----       8.9\nsd-gpg                                     151   815     2     -b----      20.3\nsd-gpg-dm                                  152   144     1     -b----       5.9\nsd-app                                     153   831     2     -b----      19.8\nsd-app-dm                                  154   144     1     -b----       5.2\nsd-whonix                                  155  1209     2     r-----      19.3\nsd-proxy                                   156   383     2     ------      17.3\nsd-proxy-dm                                157   144     1     -b----       4.0\n'
2020-04-01 17:55:47,965 - sdw_updater_gui.Updater:248(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in sd-app
2020-04-01 17:55:48,389 - sdw_updater_gui.Updater:261(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in dom0
2020-04-01 17:55:48,390 - sdw_updater_gui.Updater:216(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-04-01 17:55:48 in sd-app
2020-04-01 17:55:48,622 - sdw_updater_gui.Updater:229(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-04-01 17:55:48 in dom0
2020-04-01 17:55:48,624 - sdw_updater_gui.UpdaterApp:130(upgrade_status) INFO: Signal: upgrade_status {'apply_dom0': '0', 'recommended_action': <UpdateStatus.UPDATES_OK: '0'>, 'fedora': <UpdateStatus.UPDATES_OK: '0'>}
2020-04-01 17:55:48,679 - sdw_updater_gui.UpdaterApp:144(upgrade_status) INFO: VMs have been succesfully updated, OK to start client
2020-04-01 17:57:26,130 - sdw_updater_gui.UpdaterApp:19(launch_securedrop_client) INFO: Launching SecureDrop client

Just right

2020-04-01 18:51:16,796 - sdw_updater_gui.Updater:417(shutdown_and_start_vms) INFO: Shutting down SDW VMs for updates
2020-04-01 18:51:16,964 - sdw_updater_gui.Updater:444(_safely_shutdown_vm) ERROR: Failed to shut down sys-whonix
2020-04-01 18:51:16,965 - sdw_updater_gui.Updater:445(_safely_shutdown_vm) ERROR: Command '['qvm-shutdown', '--wait', 'sys-whonix']' returned non-zero exit status 1
2020-04-01 18:51:16,965 - sdw_updater_gui.Updater:446(_safely_shutdown_vm) ERROR: b'qvm-shutdown: error: Failed to shut down: sys-whonix\n'
2020-04-01 18:51:42,329 - sdw_updater_gui.Updater:422(shutdown_and_start_vms) INFO: Killing system fedora-based VMs for updates
2020-04-01 18:51:53,442 - sdw_updater_gui.Updater:431(shutdown_and_start_vms) INFO: Starting system fedora-based VMs after updates
2020-04-01 18:51:53,730 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sys-usb: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-dev\nsd-devices\nsys-firewall-inner\nsys-whonix\n'
2020-04-01 18:52:08,822 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sys-net: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-dev\nsd-devices\nsys-firewall-inner\nsys-usb\nsys-whonix\n'
2020-04-01 18:52:27,316 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sys-firewall: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-dev\nsd-devices\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:52:37,586 - sdw_updater_gui.Updater:435(shutdown_and_start_vms) INFO: Starting SDW VMs after updates
2020-04-01 18:52:38,072 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sd-log: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-dev\nsd-devices\nsys-firewall\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:53:07,760 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sd-gpg: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-dev\nsd-devices\nsd-log\nsys-firewall\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:53:35,512 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sd-app: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-dev\nsd-devices\nsd-gpg\nsd-log\nsys-firewall\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:54:03,973 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sd-whonix: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-app\nsd-dev\nsd-devices\nsd-gpg\nsd-log\nsys-firewall\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:54:14,158 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sd-proxy: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-app\nsd-dev\nsd-devices\nsd-gpg\nsd-log\nsd-whonix\nsys-firewall\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:54:43,306 - sdw_updater_gui.Updater:455(_safely_start_vm) INFO: VMs running before start of sys-whonix: b'anon-whonix\ndom0\nfpf-email\nfpf-infra\nfpf-signal\nfpf-vault\nfpf-vidchat\nfpf-vpn\nfpf-web\nsd-app\nsd-dev\nsd-devices\nsd-gpg\nsd-log\nsd-proxy\nsd-whonix\nsys-firewall\nsys-firewall-inner\nsys-net\nsys-usb\nsys-whonix\n'
2020-04-01 18:54:43,466 - sdw_updater_gui.Updater:248(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in sd-app
2020-04-01 18:54:43,724 - sdw_updater_gui.Updater:261(_write_updates_status_flag_to_disk) INFO: Setting update flag to 0 in dom0
2020-04-01 18:54:43,725 - sdw_updater_gui.Updater:216(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-04-01 18:54:43 in sd-app
2020-04-01 18:54:43,938 - sdw_updater_gui.Updater:229(_write_last_updated_flags_to_disk) INFO: Setting last updated to 2020-04-01 18:54:43 in dom0
2020-04-01 18:54:43,939 - sdw_updater_gui.UpdaterApp:130(upgrade_status) INFO: Signal: upgrade_status {'recommended_action': <UpdateStatus.UPDATES_OK: '0'>, 'fedora': <UpdateStatus.UPDATES_OK: '0'>, 'apply_dom0': '0'}
2020-04-01 18:54:43,943 - sdw_updater_gui.UpdaterApp:144(upgrade_status) INFO: VMs have been succesfully updated, OK to start client
2020-04-01 18:55:01,043 - sdw_updater_gui.UpdaterApp:19(launch_securedrop_client) INFO: Launching SecureDrop client

We'd need to catch stderr and log that

This is still a good idea, but it turns out our use of the --wait flag makes stderr much less informative:

[user@dom0 ~]$ qvm-check --running anon-whonix sys-whonix
qvm-check: anon-whonix: running
qvm-check: sys-whonix: running
[user@dom0 ~]$ qvm-shutdown sys-whonix
sys-whonix: Shutdown error: There are other VMs connected to this VM: anon-whonix
[user@dom0 ~]$ qvm-shutdown --wait sys-whonix
qvm-shutdown: error: Failed to shut down: sys-whonix
[user@dom0 ~]$ 

Long-term we'll almost certainly switch to using the Python API, rather than the qvm-* CLI tools, so for now it's still worth having the stderr logged rather than not. The running-list seems like it'll be the most help for debugging, though.