DispVM functionality is broken

[conorsch]

When opening files in the SecureDrop Client recently, I observed DispVMs failing to display documents.

Steps to reproduce

1. Run a recent version of the SecureDrop Workstation. Observed on both staging and prod 0.5.4.
2. Open SecureDrop Client, download a submission.
3. Click "open" to view the document.
4. Observe "dispXXX is starting..." notification
5. Observe "dispXXX has halted" notification, with no document ever having been displayed

Expected results

DispVM displays the document requested, and remains open until I close the window

Actual results

DispVM never displays the document, and closes immediately.

More info

Reported earlier in freedomofpress/qubes-template-securedrop-workstation#20 (comment), but warrants its own issue. I suspect that mimetype associations are to blame, will start investigating logs.

[eloquence]

I can repro on prod. If I attempt to open a file like so in sd-app:
qvm-open-in-vm --view-only @dispvm:sd-viewer somefile.png

I observe the following qrexec lines in journalctl:

Jun 08 15:01:45 dom0 qrexec[5963]: qubes.OpenInVM: sd-app -> @dispvm:sd-viewer: allowed to @dispvm:sd-viewer
Jun 08 15:02:13 dom0 qrexec[6471]: qubes.GetDate: disp7607 -> @default: allowed to dom0
Jun 08 15:02:14 dom0 qrexec[6491]: securedrop.Log: disp7607 -> sd-log: allowed to sd-log
Jun 08 15:02:15 dom0 qrexec[6493]: qubes.WindowIconUpdater: disp7607 -> dom0: allowed to dom0
Jun 08 15:02:16 dom0 qrexec[6503]: qubes.OpenInVM: disp7607 -> @dispvm:sd-viewer: denied: denied by policy /etc/qubes-rpc/policy/qubes.OpenInVM:6
Jun 08 15:02:25 dom0 qrexec[6493]: qubes.WindowIconUpdater: disp7607 -> dom0: denied: qrexec-client failed

[eloquence]

If I change the policy line to allow, it keeps opening an endless supply of disposable VMs (one launching another).

[sssoleileraaa]

also dispvm logs (not super useful but including to help us get a complete picture):

user@sd-log:~/QubesIncomingLogs$ tail disp8832/syslog.log 
Jun  8 17:59:54 localhost rtkit-daemon[883]: Failed to look up client: No such file or directory
Jun  8 17:59:54 localhost rtkit-daemon[883]: Failed to look up client: No such file or directory
Jun  8 17:59:54 localhost pulseaudio[882]: vchan module loading
Jun  8 17:59:54 localhost pulseaudio[882]: using domid: 0
Jun  8 17:59:54 localhost pulseaudio[882]: play libvchan_fd_for_select=19, ctrl=0x1e9d469495d0
Jun  8 17:59:54 localhost pulseaudio[882]: rec libvchan_fd_for_select=23, ctrl=0x1e9d46949770
Jun  8 17:59:54 localhost pulseaudio[882]: sink cork req state =1, now state=-2
Jun  8 17:59:54 localhost pulseaudio[882]: source cork req state =1, now state=-2
Jun  8 17:59:55 localhost qubes.OpenInVM-sd-app: Request refused
Jun  8 17:59:55 localhost user: Mailcap is disabled.

[eloquence]

The ~/.local/share/applications/mimeapps.list symlink in my sd-viewer pointed to the wrong target (/opt/sdw/mimeapps.list.sd-default instead of /opt/sdw/mimeapps.list.sd-viewer). After changing the symlink and fully powering off sd-viewer I am able to open files again.

This is handled here in the provisioning logic:
https://github.com/freedomofpress/securedrop-workstation/blob/main/dom0/sd-mime-handling.sls#L25-L33

@creviera @conorsch Do you see the same symlink error on your system?

[sssoleileraaa]

yup, i can confirm i'm seeing the same thing. looks like perhaps we're hitting this else clause:

securedrop-workstation/dom0/sd-mime-handling.sls

Line 23 in 46054d1

{% if grains['id'] in ["sd-viewer", "sd-app", "sd-devices-dvm"] %}

[eloquence]

If I delete the symlink and run sdw-admin --apply, the symlink is again provisioned to point to the wrong file.

[conorsch]

I just performed a clean prod install, and the symlink is correct, and DispVMs are working as intended. Looks like we've found the culprit, although it seems the salt grains logic is failing only intermittently. Was going to ask you to rerun sdw-admin --apply and see if that fixes things. I'll do the same and see if I can get it to break.

When I run sudo qubesctl --skip-dom0 --show-output --target sd-viewer grains.items, i see the "id" field populated with "sd-viewer", as I'd expect. Curious whether you see the same results on your system, and consistently, at that.

[eloquence]

I also see id: sd-viewer. Mysterious.

[eloquence]

I get that consistently if I just keep re-running the command. I wonder if it's a boot race condition? I'll try shutting down sd-viewer as well between runs...

[eloquence]

The grain id seems to be consistently at the correct value. Running state.highstate seems to consistently put the symlink into the correct state, regardless of whether sd-viewer is booted up or not.

I'll do one more sdw-admin --apply run after removing the symlink.

[conorsch]

To clarify, are you seeing that state.highstate restores the proper functionality, whereas sdw-admin --apply does not?

Right now I'm testing this patch locally

diff --git a/dom0/sd-mime-handling.sls b/dom0/sd-mime-handling.sls
index 664ef3a..1bcd903 100644
--- a/dom0/sd-mime-handling.sls
+++ b/dom0/sd-mime-handling.sls
@@ -20,7 +20,8 @@ sd-private-volume-mimeapps-config-dir:
     - makedirs: True
     - mode: "0755"
 
-{% if grains['id'] in ["sd-viewer", "sd-app", "sd-devices-dvm"] %}
+{% set vm_name = salt['cmd.shell']('qubesdb-read /name') %}
+{% if vm_name in ["sd-viewer", "sd-app", "sd-devices-dvm"] %}
 
 sd-private-volume-mimeapps-handling:
   file.symlink:

Which seems to work well. Take it for a spin on your machine if you're still seeing problems.

[eloquence]

To clarify, are you seeing that state.highstate restores the proper functionality,

Yes.

whereas sdw-admin --apply does not?

sdw-admin --apply restored the symlink in the wrong location after one run (happily reporting as much in the output), I am now running it again. This is for a prod setup.

[sssoleileraaa]

sdw-admin --apply restored the symlink in the wrong location after one run (happily reporting as much in the output), I am now running it again. This is for a prod setup.

this is also happening to me on a prod setup multiple times and i confirmed @conorsch's fix works

[eloquence]

I reduced the max_concurrency setting here to 1:

securedrop-workstation/scripts/provision-all

Line 10 in 3096862

max_concurrency="2"

During 4 sdw-admin --apply tests total, that seemed to consistently resolve the issue as well:

• 2 tests with max_concurrency set to 1 resulted in the correct symlink
• 2 tests with max_concurrency set to 2 resulted in the incorrect symlink

If y'all can reproduce that, it may be worth digging further into how concurrency interacts with the grains['id'] lookup (and why it seems to have suddenly gotten worse).

[sssoleileraaa]

we can close this now that #708 is merged