Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Audit and suppress CRITICAL messages in install #559

Open
eloquence opened this issue May 26, 2020 · 5 comments
Open

Audit and suppress CRITICAL messages in install #559

eloquence opened this issue May 26, 2020 · 5 comments
Labels
bug needs reproducing provisioning

Comments

@eloquence
Copy link
Member

eloquence commented May 26, 2020 •
edited
Loading

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 <function disks at 0x763289253b90>, 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 #530 (comment)
@eloquence eloquence changed the title Update to 0.3.0-rc2 stalls at 95% with "Failed to load grains defined in grain file disks.disks" Update to 0.3.0-rc2 shows "Failed to load grains defined in grain file disks.disks" in output May 26, 2020
@eloquence
Copy link
Member Author

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
Copy link
Contributor

Thanks for clarifying that the update process did not fail. I suspect the CRITICAL message is being displayed during the salt purge, see #530 (comment) for a different "CRITICAL" message noted during review.

@eloquence
Copy link
Member Author

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
Copy link
Contributor

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 eloquence mentioned this issue May 27, 2020
Closed
19 tasks
@eloquence eloquence changed the title Update to 0.3.0-rc2 shows "Failed to load grains defined in grain file disks.disks" in output Audit and suppress CRITICAL messages in install Feb 9, 2021
@eloquence
Copy link
Member Author

eloquence commented Feb 9, 2021 •
edited
Loading

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug needs reproducing provisioning
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@eloquence @conorsch @rocodes