search

freedomofpress / securedrop-workstation

Qubes-based SecureDrop Journalist Workstation environment for submission handling
GNU Affero General Public License v3.0
140 stars 43 forks source link

Audit and suppress CRITICAL messages in install #559

Open eloquence opened 4 years ago

eloquence commented 4 years ago

During sdw-admin --apply runs, we sometimes observe "CRITICAL" messages by Qubes. As part of making the system production-ready, we should audit the current installation process, identify the root cause of each message, and suppress them if they are indeed safe to ignore.

Example 1

Observed during attempt to update SecureDrop Workstation running 0.3.0-rc1 to 0.3.0-rc2, using the graphical updater. Update completes successfully, no user-facing errors, but see output on terminal below, which occurred while the updater reported 95% progress.

Click to expand ``` [erik@dom0 ~]$ /opt/securedrop/launcher/sdw-launcher.py --skip-delta 0Running 'sudo apt update' on sd-log-buster-template Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on sd-log-buster-template Using sys-firewall as UpdateVM to download updates for Dom0; this may take some time... Checking for dom0 updates... Available updates: Fedora 25 - x86_64 - Updates 7.3 MB/s | 24 MB 00:03 Fedora 25 - x86_64 7.8 MB/s | 50 MB 00:06 Qubes Dom0 Repository (updates) 1.5 MB/s | 17 MB 00:11 determining the fastest mirror (15 hosts).. done. Qubes Templates repository 2.2 kB/s | 16 kB 00:07 SecureDrop Workstation Qubes dom0 repo 3.5 kB/s | 3.3 kB 00:00 securedrop-workstation-dom0-config.noarch 0.3.0-0.rc2.1.fc25 securedrop-workstation-dom0 Running 'sudo apt update' on whonix-gw-15 Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on whonix-gw-15 Running 'sudo apt update' on sd-app-buster-template Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on sd-app-buster-template Running 'sudo apt update' on sd-proxy-buster-template Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on sd-proxy-buster-template Running 'sudo apt update' on sd-devices-buster-template Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on sd-devices-buster-template Running 'sudo apt update' on securedrop-workstation-buster Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on securedrop-workstation-buster Running 'sudo apt update' on sd-viewer-buster-template Running '[[ $(apt list --upgradable | wc -l) -eq 1 ]]' on sd-viewer-buster-template Running 'echo '1' > /home/user/.securedrop_client/sdw-update-status' on sd-app Using sys-firewall as UpdateVM to download updates for Dom0; this may take some time... Last metadata expiration check: 0:06:11 ago on Tue May 26 16:14:04 2020. Dependencies resolved. =================================================================================================== Package Arch Version Repository Size =================================================================================================== Upgrading: securedrop-workstation-dom0-config noarch 0.3.0-0.rc2.1.fc25 securedrop-workstation-dom0 105 k Transaction Summary =================================================================================================== Upgrade 1 Package Total download size: 105 k DNF will only download packages for the transaction. Downloading Packages: securedrop-workstation-dom0-config-0.3.0-0.rc2. 144 kB/s | 105 kB 00:00 -------------------------------------------------------------------------------- Total 136 kB/s | 105 kB 00:00 Complete! The downloaded packages were saved in cache until the next successful transaction. You can remove cached packages by executing 'dnf clean packages'. Qubes OS Repository for Dom0 26 MB/s | 27 kB 00:00 securedrop-workstation-dom0-config.noarch 0.3.0-0.rc2.1.fc25 qubes-dom0-cached Qubes OS Repository for Dom0 26 MB/s | 27 kB 00:00 Dependencies resolved. ================================================================================ Package Arch Version Repository Size ================================================================================ Upgrading: securedrop-workstation-dom0-config noarch 0.3.0-0.rc2.1.fc25 qubes-dom0-cached 105 k Transaction Summary ================================================================================ Upgrade 1 Package Total size: 105 k Downloading Packages: Running transaction check Transaction check succeeded. Running transaction test Transaction test succeeded. Running transaction Upgrading : securedrop-workstation-dom0-config-0.3.0-0.rc2.1.fc25.noa 1/2 Cleanup : securedrop-workstation-dom0-config-0.3.0-0.rc1.1.fc25.noa 2/2 Verifying : securedrop-workstation-dom0-config-0.3.0-0.rc2.1.fc25.noa 1/2 Verifying : securedrop-workstation-dom0-config-0.3.0-0.rc1.1.fc25.noa 2/2 Upgraded: securedrop-workstation-dom0-config.noarch 0.3.0-0.rc2.1.fc25 Complete! fedora-30: OK [CRITICAL] Failed to load grains defined in grain file disks.disks in function , error: Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/salt/loader.py", line 740, in grains ret = funcs[key]() File "/usr/lib/python2.7/site-packages/salt/grains/disks.py", line 33, in disks return _linux_disks() File "/usr/lib/python2.7/site-packages/salt/grains/disks.py", line 132, in _linux_disks flag = entry_fp.read(1) IOError: [Errno 2] No such file or directory ```

Example 2

See https://github.com/freedomofpress/securedrop-workstation/pull/530#issuecomment-612256842

eloquence commented 4 years ago

In spite of the error on the terminal (which a user ordinarily wouldn't see, if they launch the updater through the desktop icon), the update seems to be continuing.

conorsch commented 4 years ago

Thanks for clarifying that the update process did not fail. I suspect the CRITICAL message is being displayed during the salt purge, see https://github.com/freedomofpress/securedrop-workstation/pull/530#issuecomment-612256842 for a different "CRITICAL" message noted during review.

eloquence commented 4 years ago

It looks like it ultimately completed successfully. Here's the remainder of the output:

Click to expand ``` local: ---------- ID: template-whonix-ws-15 Function: pkg.installed Name: qubes-template-whonix-ws-15 Result: True Comment: Package qubes-template-whonix-ws-15 is already installed Started: 16:21:43.418378 Duration: 842.881 ms Changes: ---------- ID: whonix-ws-tag Function: qvm.vm Name: whonix-ws-15 Result: True Comment: ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'whonix-ws' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-workstation-updates,whonix-updatevm Started: 16:21:44.265948 Duration: 328.293 ms Changes: ---------- ID: whonix-ws-update-policy Function: file.prepend Name: /etc/qubes-rpc/policy/qubes.UpdatesProxy Result: True Comment: File /etc/qubes-rpc/policy/qubes.UpdatesProxy is in correct state Started: 16:21:44.596364 Duration: 3.306 ms Changes: ---------- ID: whonix-get-date-policy Function: file.prepend Name: /etc/qubes-rpc/policy/qubes.GetDate Result: True Comment: File /etc/qubes-rpc/policy/qubes.GetDate is in correct state Started: 16:21:44.599772 Duration: 1.175 ms Changes: ---------- ID: template-whonix-gw-15 Function: pkg.installed Name: qubes-template-whonix-gw-15 Result: True Comment: Package qubes-template-whonix-gw-15 is already installed Started: 16:21:44.601032 Duration: 0.354 ms Changes: ---------- ID: whonix-gw-tag Function: qvm.vm Name: whonix-gw-15 Result: True Comment: ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'whonix-gw' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-workstation-updates,whonix-updatevm Started: 16:21:44.601463 Duration: 325.28 ms Changes: ---------- ID: whonix-gw-update-policy Function: file.prepend Name: /etc/qubes-rpc/policy/qubes.UpdatesProxy Result: True Comment: File /etc/qubes-rpc/policy/qubes.UpdatesProxy is in correct state Started: 16:21:44.926876 Duration: 1.633 ms Changes: ---------- ID: sys-net Function: qvm.exists Result: True Comment: /usr/bin/qvm-check sys-net None Started: 16:21:44.928612 Duration: 222.928 ms Changes: ---------- ID: sys-firewall Function: qvm.exists Result: True Comment: /usr/bin/qvm-check sys-firewall None Started: 16:21:45.151955 Duration: 220.847 ms Changes: ---------- ID: sys-whonix Function: qvm.exists Result: True Comment: /usr/bin/qvm-check sys-whonix None Started: 16:21:45.373208 Duration: 222.618 ms Changes: ---------- ID: whonix-ws-15-dvm Function: qvm.exists Result: True Comment: /usr/bin/qvm-check whonix-ws-15-dvm None Started: 16:21:45.600627 Duration: 221.568 ms Changes: ---------- ID: qvm-appmenus --update whonix-ws-15-dvm Function: cmd.run Result: True Comment: State was not run because none of the onchanges reqs changed Changes: ---------- ID: anon-whonix Function: qvm.exists Result: True Comment: /usr/bin/qvm-check anon-whonix None Started: 16:21:45.823632 Duration: 220.58 ms Changes: ---------- ID: dom0-rpm-test-key Function: file.managed Name: /etc/pki/rpm-gpg/RPM-GPG-KEY-securedrop-workstation Result: True Comment: File /etc/pki/rpm-gpg/RPM-GPG-KEY-securedrop-workstation is in the correct state Started: 16:21:46.044643 Duration: 61.865 ms Changes: ---------- ID: dom0-rpm-test-key-import Function: cmd.run Name: sudo rpm --import /etc/pki/rpm-gpg/RPM-GPG-KEY-securedrop-workstation Result: True Comment: Command "sudo rpm --import /etc/pki/rpm-gpg/RPM-GPG-KEY-securedrop-workstation" run Started: 16:21:46.107576 Duration: 56.987 ms Changes: ---------- pid: 12829 retcode: 0 stderr: stdout: ---------- ID: dom0-workstation-rpm-repo Function: file.managed Name: /etc/yum.repos.d/securedrop-workstation-dom0.repo Result: True Comment: File /etc/yum.repos.d/securedrop-workstation-dom0.repo is in the correct state Started: 16:21:46.165969 Duration: 2.718 ms Changes: ---------- ID: dom0-remove-securedrop-workstation-stretch-template Function: pkg.removed Result: True Comment: All specified packages are already absent Started: 16:21:46.169470 Duration: 0.581 ms Changes: ---------- ID: dom0-install-securedrop-workstation-template Function: pkg.installed Result: True Comment: All specified packages are already installed Started: 16:21:46.171038 Duration: 0.382 ms Changes: ---------- ID: dom0-remove-legacy-updater Function: file.absent Name: /usr/bin/securedrop-update Result: True Comment: File /usr/bin/securedrop-update is not present Started: 16:21:46.171491 Duration: 0.345 ms Changes: ---------- ID: dom0-remove-legacy-updater Function: file.absent Name: /etc/cron.daily/securedrop-update-cron Result: True Comment: File /etc/cron.daily/securedrop-update-cron is not present Started: 16:21:46.171904 Duration: 0.219 ms Changes: ---------- ID: dom0-securedrop-icons-directory Function: file.directory Name: /usr/share/securedrop/icons Result: True Comment: Directory /usr/share/securedrop/icons is in the correct state Directory /usr/share/securedrop/icons updated Started: 16:21:46.172191 Duration: 0.679 ms Changes: ---------- ID: dom0-securedrop-icon Function: file.managed Name: /usr/share/securedrop/icons/sd-logo.png Result: True Comment: File /usr/share/securedrop/icons/sd-logo.png is in the correct state Started: 16:21:46.173459 Duration: 2.656 ms Changes: ---------- ID: dom0-enabled-apparmor-on-whonix-gw-template Function: qvm.vm Name: whonix-gw-15 Result: True Comment: ====== ['prefs'] ====== [SKIP] kernelopts : nopat apparmor=1 security=apparmor Started: 16:21:46.176470 Duration: 31.514 ms Changes: ---------- ID: dom0-enabled-apparmor-on-whonix-ws-template Function: qvm.vm Name: whonix-ws-15 Result: True Comment: ====== ['prefs'] ====== [SKIP] kernelopts : nopat apparmor=1 security=apparmor Started: 16:21:46.208345 Duration: 31.703 ms Changes: ---------- ID: dom0-create-opt-securedrop-directory Function: file.directory Name: /opt/securedrop Result: True Comment: Directory /opt/securedrop is in the correct state Directory /opt/securedrop updated Started: 16:21:46.240160 Duration: 0.506 ms Changes: ---------- ID: dom0-adjust-desktop-icon-size-xfce Function: cmd.script Name: salt://update-xfce-settings Result: True Comment: Command 'salt://update-xfce-settings' run Started: 16:21:46.240739 Duration: 131.811 ms Changes: ---------- pid: 12851 retcode: 0 stderr: stdout: update-xfce-settings: Adjusting icon size for user erik to 64 px ---------- ID: dom0-login-autostart-directory Function: file.directory Name: /home/erik/.config/autostart Result: True Comment: Directory /home/erik/.config/autostart is in the correct state Directory /home/erik/.config/autostart updated Started: 16:21:46.372887 Duration: 1.466 ms Changes: ---------- ID: dom0-login-autostart-desktop-file Function: file.managed Name: /home/erik/.config/autostart/SDWLogin.desktop Result: True Comment: File /home/erik/.config/autostart/SDWLogin.desktop is in the correct state Started: 16:21:46.375791 Duration: 6.821 ms Changes: ---------- ID: dom0-login-autostart-script Function: file.managed Name: /usr/bin/securedrop-login Result: True Comment: File /usr/bin/securedrop-login is in the correct state Started: 16:21:46.382704 Duration: 1.924 ms Changes: ---------- ID: dom0-tag-whonix-ws-15 Function: qvm.vm Name: whonix-ws-15 Result: True Comment: ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-workstation-updates,whonix-updatevm Started: 16:21:46.384722 Duration: 289.098 ms Changes: ---------- ID: dom0-tag-whonix-gw-15 Function: qvm.vm Name: whonix-gw-15 Result: True Comment: ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-workstation-updates,whonix-updatevm Started: 16:21:46.673934 Duration: 292.051 ms Changes: ---------- ID: dom0-securedrop-launcher-directory Function: file.recurse Name: /opt/securedrop/launcher Result: True Comment: Recursively updated /opt/securedrop/launcher Started: 16:21:46.966096 Duration: 64.806 ms Changes: ---------- /opt/securedrop/launcher/sdw-launcher.py: ---------- mode: 0644 /opt/securedrop/launcher/sdw-notify.py: ---------- mode: 0644 ---------- ID: dom0-securedrop-launcher-executables Function: file.managed Name: /opt/securedrop/launcher/sdw-launcher.py Result: True Comment: Started: 16:21:47.033836 Duration: 41.339 ms Changes: ---------- mode: 0755 ---------- ID: dom0-securedrop-launcher-executables Function: file.managed Name: /opt/securedrop/launcher/sdw-notify.py Result: True Comment: Started: 16:21:47.077471 Duration: 38.248 ms Changes: ---------- mode: 0755 ---------- ID: dom0-securedrop-launcher-desktop-shortcut Function: file.managed Name: /home/erik/Desktop/securedrop-launcher.desktop Result: True Comment: File /home/erik/Desktop/securedrop-launcher.desktop is in the correct state Started: 16:21:47.118215 Duration: 6.122 ms Changes: ---------- ID: dom0-install-securedrop-workstation-dom0-config Function: pkg.installed Result: True Comment: All specified packages are already installed Started: 16:21:47.141002 Duration: 0.402 ms Changes: ---------- ID: dom0-disable-unsafe-power-management-xfce Function: cmd.script Name: salt://update-xfce-settings Result: True Comment: Command 'salt://update-xfce-settings' run Started: 16:21:47.141854 Duration: 154.696 ms Changes: ---------- pid: 12875 retcode: 0 stderr: stdout: update-xfce-settings: Disabling unsafe power management options for user erik ---------- ID: sd-workstation-template Function: qvm.vm Name: securedrop-workstation-buster Result: True Comment: ====== ['prefs'] ====== [SKIP] virt_mode : hvm [SKIP] kernel : ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'service.paxctld' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation,sd-workstation-updates Started: 16:21:47.300118 Duration: 873.871 ms Changes: ---------- ID: run-prep-upgrade-scripts Function: cmd.script Name: salt://securedrop-handle-upgrade Result: True Comment: Command 'salt://securedrop-handle-upgrade' run Started: 16:21:48.174120 Duration: 1220.261 ms Changes: ---------- pid: 12881 retcode: 0 stderr: stdout: ---------- ID: sd-gpg Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-gpg' already exists. ====== ['prefs'] ====== [SKIP] autostart : True [SKIP] netvm : None [SKIP] template : securedrop-workstation-buster ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-workstation Started: 16:21:49.395671 Duration: 551.297 ms Changes: ---------- ID: dom0-crontab-update-notify Function: file.blockreplace Name: /etc/crontab Result: True Comment: No changes needed to be made Started: 16:21:49.947289 Duration: 1.448 ms Changes: ---------- ID: sd-viewer-template Function: qvm.vm Name: sd-viewer-buster-template Result: True Comment: ====== ['clone'] ====== [SKIP] A VM with the name 'sd-viewer-buster-template' already exists. ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation,sd-workstation-updates Started: 16:21:49.949652 Duration: 769.235 ms Changes: ---------- ID: sd-viewer Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-viewer' already exists. ====== ['prefs'] ====== [SKIP] template_for_dispvms: True [SKIP] netvm : None [SKIP] template : sd-viewer-buster-template ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'service.paxctld' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-viewer-vm,sd-workstation Started: 16:21:50.720224 Duration: 1077.34 ms Changes: ---------- ID: sd-viewer-default-dispvm Function: cmd.run Name: qubes-prefs default_dispvm sd-viewer Result: True Comment: Command "qubes-prefs default_dispvm sd-viewer" run Started: 16:21:51.798798 Duration: 336.084 ms Changes: ---------- pid: 12963 retcode: 0 stderr: stdout: ---------- ID: sd-whonix Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-whonix' already exists. ====== ['prefs'] ====== [SKIP] autostart : True [SKIP] kernelopts : nopat apparmor=1 security=apparmor [SKIP] netvm : sys-firewall [SKIP] provides_network : True [SKIP] template : whonix-gw-15 ====== ['tags'] ====== [SKIP] All requested tags already set: anon-gateway,created-by-dom0,sd-buster,sd-workstation Started: 16:21:52.136212 Duration: 873.914 ms Changes: ---------- ID: sd-proxy-template Function: qvm.vm Name: sd-proxy-buster-template Result: True Comment: ====== ['clone'] ====== [SKIP] A VM with the name 'sd-proxy-buster-template' already exists. ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation,sd-workstation-updates Started: 16:21:53.010434 Duration: 1013.036 ms Changes: ---------- ID: sd-proxy Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-proxy' already exists. ====== ['prefs'] ====== [SKIP] autostart : True [SKIP] netvm : sd-whonix [SKIP] template : sd-proxy-buster-template ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation Started: 16:21:54.025411 Duration: 797.693 ms Changes: ---------- ID: sd-proxy-dom0-securedrop.Proxy Function: file.prepend Name: /etc/qubes-rpc/policy/securedrop.Proxy Result: True Comment: File /etc/qubes-rpc/policy/securedrop.Proxy is in correct state Started: 16:21:54.823395 Duration: 2.587 ms Changes: ---------- ID: sd-app-template Function: qvm.vm Name: sd-app-buster-template Result: True Comment: ====== ['clone'] ====== [SKIP] A VM with the name 'sd-app-buster-template' already exists. ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation,sd-workstation-updates Started: 16:21:54.826940 Duration: 1022.031 ms Changes: ---------- ID: sd-app Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-app' already exists. ====== ['prefs'] ====== [SKIP] netvm : None [SKIP] template : sd-app-buster-template ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'service.paxctld' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-client,sd-workstation Started: 16:21:55.850293 Duration: 821.906 ms Changes: ---------- ID: sd-app-private-volume-size Function: cmd.run Name: qvm-volume resize sd-app:private 10GiB Result: True Comment: Command "qvm-volume resize sd-app:private 10GiB " run Started: 16:21:56.673436 Duration: 571.241 ms Changes: ---------- pid: 13069 retcode: 0 stderr: stdout: ---------- ID: sd-app-template-sync-appmenus Function: cmd.run Name: qvm-start --skip-if-running sd-app-buster-template && qvm-sync-appmenus sd-app-buster-template Result: True Comment: State was not run because none of the onchanges reqs changed Changes: ---------- ID: sys-whonix-template-config Function: qvm.vm Name: sys-whonix Result: True Comment: ====== ['prefs'] ====== [SKIP] template : whonix-gw-15 Started: 16:21:57.247020 Duration: 32.645 ms Changes: ---------- ID: anon-whonix-template-config Function: qvm.vm Name: anon-whonix Result: True Comment: ====== ['prefs'] ====== [SKIP] template : whonix-ws-15 Started: 16:21:57.280060 Duration: 29.882 ms Changes: ---------- ID: run-remove-upgrade-scripts Function: cmd.script Name: salt://securedrop-handle-upgrade Result: True Comment: Command 'salt://securedrop-handle-upgrade' run Started: 16:21:57.310061 Duration: 368.045 ms Changes: ---------- pid: 13071 retcode: 0 stderr: usage: qvm-check [--verbose] [--quiet] [--help] [--all] [--exclude EXCLUDE] [--running] [--paused] [--template] [--networked] [VMNAME [VMNAME ...]] qvm-check: error: no such domain: 'sd-app-template' usage: qvm-check [--verbose] [--quiet] [--help] [--all] [--exclude EXCLUDE] [--running] [--paused] [--template] [--networked] [VMNAME [VMNAME ...]] qvm-check: error: no such domain: 'sd-viewer-template' usage: qvm-check [--verbose] [--quiet] [--help] [--all] [--exclude EXCLUDE] [--running] [--paused] [--template] [--networked] [VMNAME [VMNAME ...]] qvm-check: error: no such domain: 'sd-devices-template' usage: qvm-check [--verbose] [--quiet] [--help] [--all] [--exclude EXCLUDE] [--running] [--paused] [--template] [--networked] [VMNAME [VMNAME ...]] qvm-check: error: no such domain: 'sd-proxy-template' stdout: ---------- ID: dom0-poweroff Function: file.blockreplace Name: /etc/systemd/logind.conf Result: True Comment: No changes needed to be made Started: 16:21:57.678456 Duration: 1.703 ms Changes: ---------- ID: apply-systemd-changes Function: cmd.run Name: sudo systemctl restart systemd-logind Result: True Comment: Command "sudo systemctl restart systemd-logind" run Started: 16:21:57.680256 Duration: 111.495 ms Changes: ---------- pid: 13076 retcode: 0 stderr: stdout: ---------- ID: dom0-rpc-qubes.ClipboardPaste Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.ClipboardPaste Result: True Comment: No changes needed to be made Started: 16:21:57.792531 Duration: 2.879 ms Changes: ---------- ID: dom0-rpc-qubes.FeaturesRequest Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.FeaturesRequest Result: True Comment: No changes needed to be made Started: 16:21:57.795519 Duration: 0.516 ms Changes: ---------- ID: dom0-rpc-qubes.Filecopy Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.Filecopy Result: True Comment: No changes needed to be made Started: 16:21:57.796130 Duration: 0.515 ms Changes: ---------- ID: dom0-rpc-qubes.OpenInVM Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.OpenInVM Result: True Comment: No changes needed to be made Started: 16:21:57.796733 Duration: 0.47 ms Changes: ---------- ID: dom0-rpc-qubes.OpenURL Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.OpenURL Result: True Comment: No changes needed to be made Started: 16:21:57.797283 Duration: 0.481 ms Changes: ---------- ID: dom0-rpc-qubes.PdfConvert Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.PdfConvert Result: True Comment: No changes needed to be made Started: 16:21:57.797843 Duration: 0.464 ms Changes: ---------- ID: dom0-rpc-qubes.StartApp Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.StartApp Result: True Comment: No changes needed to be made Started: 16:21:57.798392 Duration: 0.448 ms Changes: ---------- ID: dom0-rpc-qubes.USB Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.USB Result: True Comment: No changes needed to be made Started: 16:21:57.798922 Duration: 0.448 ms Changes: ---------- ID: dom0-rpc-qubes.ensure.USBAttach Function: file.managed Name: /etc/qubes-rpc/policy/qubes.USBAttach Result: True Comment: File /etc/qubes-rpc/policy/qubes.USBAttach exists with proper permissions. No changes made. Started: 16:21:57.799449 Duration: 0.672 ms Changes: ---------- ID: dom0-rpc-qubes.USBAttach Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.USBAttach Result: True Comment: No changes needed to be made Started: 16:21:57.801634 Duration: 0.455 ms Changes: ---------- ID: dom0-rpc-qubes.VMRootShell Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.VMRootShell Result: True Comment: No changes needed to be made Started: 16:21:57.802165 Duration: 0.486 ms Changes: ---------- ID: dom0-rpc-qubes.VMshell Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.VMShell Result: True Comment: No changes needed to be made Started: 16:21:57.802727 Duration: 0.486 ms Changes: ---------- ID: dom0-rpc-qubes.Gpg Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.Gpg Result: True Comment: No changes needed to be made Started: 16:21:57.803287 Duration: 0.434 ms Changes: ---------- ID: dom0-rpc-qubes.GpgImportKey Function: file.blockreplace Name: /etc/qubes-rpc/policy/qubes.GpgImportKey Result: True Comment: No changes needed to be made Started: 16:21:57.803794 Duration: 0.422 ms Changes: ---------- ID: sd-devices-template Function: qvm.vm Name: sd-devices-buster-template Result: True Comment: ====== ['clone'] ====== [SKIP] A VM with the name 'sd-devices-buster-template' already exists. ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation,sd-workstation-updates Started: 16:21:57.804779 Duration: 761.763 ms Changes: ---------- ID: sd-devices-dvm Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-devices-dvm' already exists. ====== ['prefs'] ====== [SKIP] template_for_dispvms: True [SKIP] netvm : None [SKIP] template : sd-devices-buster-template ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'service.paxctld' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation Started: 16:21:58.567922 Duration: 828.354 ms Changes: ---------- ID: sd-devices-template-sync-appmenus Function: cmd.run Name: qvm-start --skip-if-running sd-devices-buster-template && qvm-sync-appmenus sd-devices-buster-template Result: True Comment: State was not run because none of the onchanges reqs changed Changes: ---------- ID: sd-devices-create-named-dispvm Function: qvm.vm Name: sd-devices Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-devices' already exists. ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation Started: 16:21:59.398489 Duration: 507.197 ms Changes: ---------- ID: fedora-30-dvm Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'fedora-30-dvm' already exists. ====== ['prefs'] ====== [SKIP] template_for_dispvms: True [SKIP] label : red ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'appmenus-dispvm' = Enabled Started: 16:21:59.906011 Duration: 290.241 ms Changes: ---------- ID: echo -e 'firefox.desktop\nxterm.desktop' | qvm-appmenus --set-whitelist=- --update fedora-30-dvm Function: cmd.run Result: True Comment: Command "echo -e 'firefox.desktop\nxterm.desktop' | qvm-appmenus --set-whitelist=- --update fedora-30-dvm" run Started: 16:22:00.196536 Duration: 444.235 ms Changes: ---------- pid: 13185 retcode: 0 stderr: fedora-30-dvm: Creating appmenus stdout: ---------- ID: dom0-install-fedora-template Function: pkg.installed Result: True Comment: 1 targeted package was installed/updated. Started: 16:22:00.641154 Duration: 812133.639 ms Changes: ---------- qubes-template-fedora-31: ---------- new: 4.0.1-202002142323 old: ---------- ID: update-fedora-template-if-new Function: cmd.wait Name: sudo qubesctl --skip-dom0 --targets fedora-31 state.sls update.qubes-vm Result: True Comment: Command "sudo qubesctl --skip-dom0 --targets fedora-31 state.sls update.qubes-vm" run Started: 16:35:32.779481 Duration: 528135.374 ms Changes: ---------- pid: 14974 retcode: 0 stderr: stdout: fedora-31: OK ---------- ID: set-fedora-default-template-version Function: cmd.run Name: qubes-prefs default_template fedora-31 Result: True Comment: Command "qubes-prefs default_template fedora-31" run Started: 16:44:20.917012 Duration: 653.905 ms Changes: ---------- pid: 16601 retcode: 0 stderr: stdout: ---------- ID: sd-sys-usb-fedora-version-halt Function: qvm.kill Name: sys-usb Result: True Comment: qvm.state halted Halted None Started: 16:44:21.579010 Duration: 5101.815 ms Changes: ---------- ID: sd-sys-usb-fedora-version-halt-wait Function: cmd.run Name: sleep 5 Result: True Comment: Command "sleep 5" run Started: 16:44:26.682816 Duration: 5027.833 ms Changes: ---------- pid: 17223 retcode: 0 stderr: stdout: ---------- ID: sd-sys-usb-fedora-version-update Function: qvm.vm Name: sys-usb Result: True Comment: ====== ['prefs'] ====== Started: 16:44:31.712874 Duration: 260.73 ms Changes: ---------- qvm.prefs: ---------- qvm.create: ---------- template: ---------- new: fedora-31 old: fedora-30 ---------- ID: sd-sys-usb-fedora-version-start Function: qvm.start Name: sys-usb Result: True Comment: qvm.state running Running None Started: 16:44:31.974401 Duration: 15484.514 ms Changes: ---------- ID: sd-sys-net-fedora-version-halt Function: qvm.kill Name: sys-net Result: True Comment: qvm.state halted Halted None Started: 16:44:47.460720 Duration: 6714.489 ms Changes: ---------- ID: sd-sys-net-fedora-version-halt-wait Function: cmd.run Name: sleep 5 Result: True Comment: Command "sleep 5" run Started: 16:44:54.177429 Duration: 5034.784 ms Changes: ---------- pid: 18037 retcode: 0 stderr: stdout: ---------- ID: sd-sys-net-fedora-version-update Function: qvm.vm Name: sys-net Result: True Comment: ====== ['prefs'] ====== Started: 16:44:59.215771 Duration: 273.178 ms Changes: ---------- qvm.prefs: ---------- qvm.create: ---------- template: ---------- new: fedora-31 old: fedora-30 ---------- ID: sd-sys-net-fedora-version-start Function: qvm.start Name: sys-net Result: True Comment: qvm.state running Running None Started: 16:44:59.489758 Duration: 15880.625 ms Changes: ---------- ID: sd-sys-firewall-fedora-version-halt Function: qvm.kill Name: sys-firewall Result: True Comment: qvm.state halted Halted None Started: 16:45:15.372241 Duration: 6496.88 ms Changes: ---------- ID: sd-sys-firewall-fedora-version-halt-wait Function: cmd.run Name: sleep 5 Result: True Comment: Command "sleep 5" run Started: 16:45:21.871750 Duration: 5036.109 ms Changes: ---------- pid: 18807 retcode: 0 stderr: stdout: ---------- ID: sd-sys-firewall-fedora-version-update Function: qvm.vm Name: sys-firewall Result: True Comment: ====== ['prefs'] ====== Started: 16:45:26.913266 Duration: 272.094 ms Changes: ---------- qvm.prefs: ---------- qvm.create: ---------- template: ---------- new: fedora-31 old: fedora-30 ---------- ID: sd-sys-firewall-fedora-version-start Function: qvm.start Name: sys-firewall Result: True Comment: qvm.state running Running None Started: 16:45:27.186132 Duration: 12001.407 ms Changes: ---------- ID: sd-default-mgmt-dvm-fedora-version-halt Function: qvm.kill Name: default-mgmt-dvm Result: True Comment: [SKIP] Halted None Started: 16:45:39.188955 Duration: 50.253 ms Changes: ---------- ID: sd-default-mgmt-dvm-fedora-version-halt-wait Function: cmd.run Name: sleep 5 Result: True Comment: Command "sleep 5" run Started: 16:45:39.240221 Duration: 5033.901 ms Changes: ---------- pid: 19096 retcode: 0 stderr: stdout: ---------- ID: sd-default-mgmt-dvm-fedora-version-update Function: qvm.vm Name: default-mgmt-dvm Result: True Comment: ====== ['prefs'] ====== Started: 16:45:44.276676 Duration: 303.793 ms Changes: ---------- qvm.prefs: ---------- qvm.create: ---------- template: ---------- new: fedora-31 old: fedora-30 ---------- ID: sd-default-mgmt-dvm-fedora-version-start Function: qvm.start Name: default-mgmt-dvm Result: True Comment: qvm.state running Running None Started: 16:45:44.581280 Duration: 12035.983 ms Changes: ---------- ID: topd-always-passes Function: test.succeed_without_changes Name: foo Result: True Comment: Success! Started: 16:45:56.622244 Duration: 0.694 ms Changes: ---------- ID: sd-log-template Function: qvm.vm Name: sd-log-buster-template Result: True Comment: ====== ['clone'] ====== [SKIP] A VM with the name 'sd-log-buster-template' already exists. ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-buster,sd-workstation,sd-workstation-updates Started: 16:45:56.624396 Duration: 692.745 ms Changes: ---------- ID: sd-log Function: qvm.vm Result: True Comment: ====== ['present'] ====== [SKIP] A VM with the name 'sd-log' already exists. ====== ['prefs'] ====== [SKIP] autostart : True [SKIP] netvm : None ====== ['features'] ====== [SKIP] Feature already in desired state: ENABLE 'service.paxctld' = Enabled [SKIP] Feature already in desired state: ENABLE 'service.redis' = Enabled [SKIP] Feature already in desired state: ENABLE 'service.securedrop-log' = Enabled ====== ['tags'] ====== [SKIP] All requested tags already set: created-by-dom0,sd-workstation Started: 16:45:57.318720 Duration: 790.359 ms Changes: ---------- ID: sd-log-dom0-securedrop.Log Function: file.prepend Name: /etc/qubes-rpc/policy/securedrop.Log Result: True Comment: File /etc/qubes-rpc/policy/securedrop.Log is in correct state Started: 16:45:58.396034 Duration: 7.933 ms Changes: ---------- ID: sd-log-private-volume-size Function: cmd.run Name: qvm-volume resize sd-log:private 5GiB Result: True Comment: Command "qvm-volume resize sd-log:private 5GiB " run Started: 16:45:58.405096 Duration: 1218.287 ms Changes: ---------- pid: 19465 retcode: 0 stderr: stdout: Summary for local -------------- Succeeded: 101 (changed=24) Failed: 0 -------------- Total states run: 101 Total run time: 1455.788 s Running 'echo '2' > /home/user/.securedrop_client/sdw-update-status' on sd-app Running 'echo '2020-05-26 16:49:26' > /home/user/.securedrop_client/sdw-last-updated' on sd-app ```
conorsch commented 4 years ago

Ran a graphical updater on "staging" environment. Completed without error. Inspecting ~/.securedrop_launcher/logs/launcher.log in dom0 shows everything happy, but the stderr output @eloquence shared above is not logged, so those messages could have been emitted on my run, too. Client logs in successfully.

Currently experiencing a sync problem on the client, version 0.1.6-dev-20200526-060119+buster, but it might be the server I'm connecting too...

eloquence commented 3 years ago

Retitled and rescoped -- we should IMO still understand the cause of any CRITICAL messages during the installation, and suppress if possible and appropriate, as part of getting the workstation ready for wider production use.