search

QubesOS / qubes-issues

The Qubes OS Project issue tracker
https://www.qubes-os.org/doc/issue-tracking/
532 stars 46 forks source link

Opener VM shutdown no longer kills DisposableVM (until it tries to write on the stale qrexec connection) #7693

Open rustybird opened 2 years ago

rustybird commented 2 years ago

Qubes OS release

R4.1, maybe late R4.0 too

Brief summary

In R4.0, when a VM that had opened a @dispvm was shut down this would kill the DisposableVM right away. But in R4.1 the DisposableVM will linger, until it is finally killed when it attempts to write data to the opener VM on the stale qrexec connection. This can be confusing from a user's perspective.

(* I don't remember for sure if this change came with R4.1, or already sometime during R4.0)

Steps to reproduce

qrexec-client-vm @dispvm qubes.VMShell <<<'echo now shut down the opener VM; sleep 60; echo this write will finally kill the DisposableVM'

Expected behavior

The disp1234 DisposableVM is killed soon after shutting down the opener VM.

Actual behavior

It's only killed later after attempting to write on the stale qrexec connection: https://github.com/QubesOS/qubes-core-qrexec/blob/v4.1.18/libqrexec/process_io.c#L173-L192

Two relevant lines are logged in dom0, the first one just after shutting down the opener VM, the second one just before the DisposableVM is killed:

Aug 13 13:04:44 dom0 qrexec-policy-daemon[77147]: 2022-08-13 13:04:44.200 qrexec-client[77147]: process_io.c:187:process_io: vchan connection closed early (fds: 4 11 -1, status: -1 -1)
Aug 13 13:05:42 dom0 qrexec-policy-daemon[77514]: 2022-08-13 13:05:42.690 qrexec-client[77514]: process_io.c:187:process_io: vchan connection closed early (fds: 4 11 -1, status: -1 -1)
SvenSemmler commented 1 year ago

This might be related to the freezes I see when running updates...

Oct 04 18:06:33 dom0 kernel: Linux version 5.15.64-1.fc32.qubes.x86_64 (mockbuild@4b435ee24c154289bb215bd37e0e5c21) (gcc (GCC) 10.3.1 20210422 (Red Hat 10.3.1-1), GNU ld version 2.34-6.fc32) #1 SMP Mon Sep 5 04:26:01 CEST 2022
-- Reboot --
Oct 04 12:31:03 dom0 root[48245]: /etc/xen/scripts/block: remove XENBUS_PATH=backend/vbd/62/51712
Oct 04 12:31:01 dom0 qrexec-policy-daemon[48143]: 2022-10-04 12:31:01.299 qrexec-client[48143]: process_io.c:187:process_io: vchan connection closed early (fds: 4 11 -1, status: -1 -1)
Oct 04 12:30:59 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.NotifyUpdates+: debian-11-signal -> @adminvm: allowed to dom0
Oct 04 12:30:56 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.UpdatesProxy+: debian-11-signal -> @default: allowed to sys-pi-hole
Oct 04 12:30:53 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.UpdatesProxy+: debian-11-signal -> @default: allowed to sys-pi-hole
Oct 04 12:30:49 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.VMRootShell+: disp-mgmt-debian-11-signal -> debian-11-signal: allowed to debian-11-signal
Oct 04 12:30:48 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.VMRootShell+: disp-mgmt-debian-11-signal -> debian-11-signal: allowed to debian-11-signal
Oct 04 12:30:47 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.GetDate+: debian-11-signal -> @default: allowed to dom0
Oct 04 12:30:44 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.WindowIconUpdater+: debian-11-signal -> @adminvm: allowed to dom0
Oct 04 12:30:43 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.VMRootShell+: disp-mgmt-debian-11-signal -> debian-11-signal: allowed to debian-11-signal
Oct 04 12:30:43 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.VMRootShell+: disp-mgmt-debian-11-signal -> debian-11-signal: allowed to debian-11-signal
Oct 04 12:30:43 dom0 qrexec-policy-daemon[1495]: qrexec: qubes.VMRootShell+: disp-mgmt-debian-11-signal -> debian-11-signal: allowed to debian-11-signal
Oct 04 12:30:41 dom0 audit[48104]: CRED_DISP pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:41 dom0 audit[48104]: USER_END pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:41 dom0 kernel: audit: type=1104 audit(1664904641.884:971): pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:41 dom0 kernel: audit: type=1106 audit(1664904641.884:970): pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:41 dom0 runuser[48104]: pam_unix(runuser:session): session closed for user user
Oct 04 12:30:37 dom0 kernel: xen-blkback: backend/vbd/62/51760: using 2 queues, protocol 1 (x86_64-abi) 
Oct 04 12:30:37 dom0 kernel: xen-blkback: backend/vbd/62/51744: using 2 queues, protocol 1 (x86_64-abi) 
Oct 04 12:30:36 dom0 kernel: xen-blkback: backend/vbd/62/51728: using 2 queues, protocol 1 (x86_64-abi) 
Oct 04 12:30:36 dom0 kernel: xen-blkback: backend/vbd/62/51712: using 2 queues, protocol 1 (x86_64-abi) 
Oct 04 12:30:35 dom0 audit[48104]: USER_START pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 kernel: audit: type=1105 audit(1664904635.407:969): pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 runuser[48104]: pam_unix(runuser:session): session opened for user user by (uid=0)
Oct 04 12:30:35 dom0 kernel: audit: type=1103 audit(1664904635.406:968): pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 audit[48104]: CRED_ACQ pid=48104 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 qubesd[1402]: vm.debian-11-signal: Activating the debian-11-signal VM
Oct 04 12:30:35 dom0 kernel: audit: type=1104 audit(1664904635.353:967): pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 kernel: audit: type=1106 audit(1664904635.353:966): pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 audit[48100]: CRED_DISP pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 audit[48100]: USER_END pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 runuser[48100]: pam_unix(runuser:session): session closed for user user
Oct 04 12:30:35 dom0 audit[48100]: USER_START pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 kernel: audit: type=1105 audit(1664904635.314:965): pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 runuser[48100]: pam_unix(runuser:session): session opened for user user by (uid=0)
Oct 04 12:30:35 dom0 kernel: audit: type=1103 audit(1664904635.313:964): pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 audit[48100]: CRED_ACQ pid=48100 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Oct 04 12:30:35 dom0 qubesd[1402]: vm.debian-11-signal: Starting Qubes DB
Oct 04 12:30:35 dom0 qubesd[1402]: vm.debian-11-signal: Setting Qubes DB info for the VM