update.qubes-vm (and updater) salt not updating nightlies in dev env

[emkll]

After running the update, upgrades were not completely applied to templates, in the development environment.

After running the updater, following command, or using the Qubes Updater GUI, observed not all packages were updated:

sudo qubesctl --skip-dom0 --targets sd-viewer-buster-template state.sls update.qubes-vm

workstation packages are not updated

user@sd-viewer-buster-template:~$ sudo apt list --upgradable 
Listing... Done
securedrop-log/unknown 0.1.0-dev-20200304-060751+buster all [upgradable from: 0.1.0-dev-20200303-060618+buster]
securedrop-workstation-svs-disp/unknown 0.2.1-dev-20200304-061326+buster all [upgradable from: 0.2.1-dev-20200303-061304+buster]
user@sd-viewer-buster-template:~$ 

Upgrading the VMs manually (sudo apt upgrade) correctly updates the VMs

[zenmonkeykstop]

Also confirmed in staging environment:

• ran SD updater, updates applied and system rebooted
• updates still available for sd-{app,log,proxy}-buster-template:
  • securedrop-client and securedrop-log for app
  • securedrop-log for log
  • whonix packages and securedrop-log, securedrop-proxy for proxy
• sudo apt upgrade applies updates in each case, tho on proxy manual input is required because of a formatting change in /etc/apt/sources.list.d/debian.list

[eloquence]

If you see this happening, @conorsch recommends cloning the impacted template(s) for investigation purposes.

[emkll]

apt logs don't seem to provide any clues, no logs from today are present in the logs

user@sd-viewer-buster-template:~$ cat /var/log/apt/history.log

Start-Date: 2020-03-02  09:12:13
Commandline: apt-get -q -y -o DPkg::Options::=--force-confold -o DPkg::Options::=--force-confdef dist-upgrade
Upgrade: securedrop-log:amd64 (0.1.0-dev-20200226-060606+buster, 0.1.0-dev-20200302-060514+buster), securedrop-workstation-svs-disp:amd64 (0.2.0+buster, 0.2.0-dev-20200302-061051+buster)
End-Date: 2020-03-02  09:12:21

Start-Date: 2020-03-03  08:14:17
Commandline: apt-get -q -y -o DPkg::Options::=--force-confold -o DPkg::Options::=--force-confdef dist-upgrade
Upgrade: securedrop-log:amd64 (0.1.0-dev-20200302-060514+buster, 0.1.0-dev-20200303-060618+buster), securedrop-workstation-svs-disp:amd64 (0.2.0-dev-20200302-061051+buster, 0.2.1-dev-20200303-061304+buster)
End-Date: 2020-03-03  08:14:27

[eloquence]

sudo apt upgrade applies updates in each case, tho on proxy manual input is required because of a formatting change in /etc/apt/sources.list.d/debian.list

Under normal operation, is the updater expected to automatically handle those cases (e.g., by using the default option) where manual input is required when sudo apt upgrade is run from the command line?

[emkll]

On VMs that fail to update, I observe a salt error in /var/log/syslog of the template:

Mar  4 13:34:20 localhost qrexec-agent[446]: executed root:QUBESRPC qubes.VMRootShell disp-mgmt-sd-viewer-buster-temp pid 903
Mar  4 13:34:20 localhost systemd[1]: Started Session c8 of user root.
Mar  4 13:34:21 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp: SALT_ARGV: ['/usr/bin/python3', '/var/tmp/.root_62a99a_salt/salt-call', '--retcode-passthrough', '--local', '--metadata', '--out', 'json', '-l', 'quiet', '-c', '/var/tmp/.root_62a99a_salt', '--', 'state.pkg', '/var/tmp/.root_62a99a_salt/salt_state.tgz', 'test=None', 'pkg_sum=49c691c134ffcbd38761065dc7be2c975fac7b2f523ad788698de2dcbc40338b', 'hash_type=sha256'] 
Mar  4 13:34:21 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp: _edbc7885e4f9aac9b83b35999b68d015148caf467b78fa39c05f669c0ff89878 
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp: Traceback (most recent call last): 
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:   File "/var/tmp/.root_62a99a_salt/salt-call", line 27, in <module> 
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:     salt_call() 
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:   File "/var/tmp/.root_62a99a_salt/pyall/salt/scripts.py", line 445, in salt_call 
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:     client.run()
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:   File "/var/tmp/.root_62a99a_salt/pyall/salt/cli/call.py", line 57, in run
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:     caller.run()
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:   File "/var/tmp/.root_62a99a_salt/pyall/salt/cli/caller.py", line 119, in run
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:     ret = self.call()
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:   File "/var/tmp/.root_62a99a_salt/pyall/salt/cli/caller.py", line 232, in call
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp:     func.__module__].__context__.get('retcode', 0)
Mar  4 13:34:27 localhost qubes.VMRootShell-disp-mgmt-sd-viewer-buster-temp: KeyError: 'salt.loaded.int.module.state'
Mar  4 13:34:27 localhost qrexec-agent[446]: send exit code 1
Mar  4 13:34:27 localhost qrexec-agent[446]: pid 903 exited with 1
Mar  4 13:34:27 localhost systemd[1]: session-c8.scope: Succeeded.
Mar  4 13:34:27 localhost qrexec-agent[446]: eintr
Mar  4 13:34:28 localhost qubes-gui[452]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
Mar  4 13:34:28 localhost qubes-gui[452]:       after 134 requests (134 known processed) with 0 events remaining.

[conorsch]

Confirming that the above stack trace appears in TemplateVM syslogs if VMs failed to update. The external output of the salt command in dom0 is deceptively benign:

[user@dom0 ~]$ sudo qubesctl --show-output --skip-dom0 --target debian-10-1 state.sls update.qubes-vm
debian-10-1:

[user@dom0 ~]$ echo $?
0

In the above test, debian-10-1 is a direct clone of debian-10. Other TemplateVMs, however, update just fine, so we still need to identify the root cause of the breakage in any given VM.

[emkll]

Opened ticket upstream QubesOS/qubes-issues#5705

[emkll]

The problem does not appear to be isolated to update.qubes-vm, but seems to rather be a generalized salt issue: A clean Workstation Install on Qubes 4.0.3 no longer works: TemplateVMs are not provisioned, and I observe the same error as above in the logs

[emkll]

A workaround for this issue, which I've tested locally: dnf downgrade salt in fedora-30 template. Unfortunately somewhat impractical given how we enforce auto-updates, but we now understand the root cause. I have updated the upstream ticket.

[emkll]

Temporary workaround (downgrades and freezes upstream salt packages):

Run the following command in Fedora-30 TemplateVM:

sudo dnf downgrade -y salt && echo "exclude=salt salt-ssh" | sudo tee -a /etc/dnf/dnf.conf

To revert the changes, run the following command in the Fedora-30 TemplateVM:

sed -i '/^exclude=/ d' /etc/dnf/dnf.conf