Spooky: all GUI windows disappeared (but still running)

[bnvk]

Had a strange event happen just now. I was pushing some data between domains via the secure clipboard, and all the sudden every GUI window I had open (in all desktops) disappeared including the Qubes VM Manager.

Upon re-opening things- all the CLI daemons / things I had running (mailpile,jekyll server, etc...) all seem to still be running somewhere but just not accessible in the GUI.

@marmarek anything I can find / offer to help debug like crash log or such?

[marmarek]

Start with GUI daemon logs (/var/log/qubes/guid.VMNAME.log), Xorg log in dom0 (/var/log/Xorg.0.log) and ~/.xsession-errors. If nothing interesting there, check journalctl output in the VMs.

Best Regards, Marek Marczykowski-Górecki Invisible Things Lab A: Because it messes up the order in which people normally read text. Q: Why is top-posting such a bad thing?

[bnvk]

Ok. I emailed you the output of those logs. Is the best thing in this case to just stop the VMs from the Manager and restart things?

[bnvk]

It also, may or may not be worth noting- that I had a PDF opened in a DisposableVM open at the time of this crash

[marmarek]

On Tue, Oct 27, 2015 at 01:57:07PM -0700, Brennan Novak wrote:

Ok. I emailed you the output of those logs. Is the best thing in this case to just stop the VMs from the Manager and restart things?

This would "fix" the problem, but surely will not help finding what was the cause.

In the logs you've sent I don't see anything unusual... Anything in that VMs (especially in journalctl output)? Check also windows list (xwininfo -root -tree) - do you see that disappeared windows?

Best Regards, Marek Marczykowski-Górecki Invisible Things Lab A: Because it messes up the order in which people normally read text. Q: Why is top-posting such a bad thing?

[bnvk]

Here's the journalctl output from the copying VM

-- Reboot --
Oct 27 14:08:37 vault systemd[415]: Starting Paths.
Oct 27 14:08:37 vault systemd[415]: Reached target Paths.
Oct 27 14:08:37 vault systemd[415]: Starting Timers.
Oct 27 14:08:37 vault systemd[415]: Reached target Timers.
Oct 27 14:08:37 vault systemd[415]: Starting Sockets.
Oct 27 14:08:37 vault systemd[415]: Reached target Sockets.
Oct 27 14:08:37 vault systemd[415]: Starting Basic System.
Oct 27 14:08:37 vault systemd[415]: Reached target Basic System.
Oct 27 14:08:37 vault systemd[415]: Starting Default.
Oct 27 14:08:37 vault systemd[415]: Reached target Default.
Oct 27 14:08:37 vault systemd[415]: Startup finished in 79ms.
Oct 27 14:08:38 vault gnome-keyring-daemon[601]: couldn't access control socket: /run/user/1000/keyring/control: No such 
Oct 27 14:08:38 vault gnome-keyring-daemon[603]: The SSH agent was already initialized
Oct 27 14:08:38 vault gnome-keyring-daemon[603]: The PKCS#11 component was already initialized
Oct 27 14:08:38 vault gnome-keyring-daemon[603]: The Secret Service was already initialized
Oct 27 14:08:38 vault gnome-keyring-daemon[603]: The GPG agent was already initialized
Oct 27 14:08:39 vault org.a11y.Bus[565]: Activating service name='org.a11y.atspi.Registry'
Oct 27 14:08:39 vault org.a11y.Bus[565]: Successfully activated service 'org.a11y.atspi.Registry'
Oct 27 14:08:39 vault org.a11y.atspi.Registry[668]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.R
Oct 27 14:08:39 vault org.a11y.atspi.Registry[668]: Xlib:  extension "XEVIE" missing on display ":0".
Oct 27 14:08:39 vault pulseaudio[640]: vchan module loading
Oct 27 14:08:39 vault pulseaudio[640]: play libvchan_fd_for_select=19, ctrl=0x7fbbea94fbb0
Oct 27 14:08:39 vault pulseaudio[640]: rec libvchan_fd_for_select=22, ctrl=0x7fbbea950640
Oct 27 14:08:39 vault pulseaudio[640]: sink cork req state =1, now state=-2
Oct 27 14:08:39 vault pulseaudio[640]: source cork req state =1, now state=-2
Oct 27 14:08:44 vault pulseaudio[640]: source cork req state =2, now state=1
Oct 27 14:08:44 vault pulseaudio[640]: sink cork req state =2, now state=1

And journalctl from the pasting VM says No journal files were found.

[marmarek]

Try sudo journalctl -b to get also system messages. But I guess there isn't anything useful either...

Best Regards, Marek Marczykowski-Górecki Invisible Things Lab A: Because it messes up the order in which people normally read text. Q: Why is top-posting such a bad thing?

[bnvk]

Ok, here's a bunch of different stuff from that command

Oct 27 10:54:48 chatty systemd[786]: Time has been changed
Oct 27 10:54:48 chatty systemd[2698]: Time has been changed
Oct 27 10:54:48 chatty systemd[1]: Time has been changed
Oct 27 10:54:48 chatty su[2697]: pam_unix(su:session): session closed for user root
Oct 27 10:54:48 chatty systemd-logind[413]: Removed session c10.
Oct 27 10:54:48 chatty systemd[1]: Stopping User Manager for UID 0...
Oct 27 10:54:48 chatty systemd[2698]: Stopping Default.
Oct 27 10:54:48 chatty systemd[2698]: Stopped target Default.
Oct 27 10:54:48 chatty systemd[2698]: Stopping Basic System.
Oct 27 10:54:48 chatty systemd[2698]: Stopped target Basic System.
Oct 27 10:54:48 chatty systemd[2698]: Stopping Paths.
Oct 27 10:54:48 chatty systemd[2698]: Stopped target Paths.
Oct 27 10:54:48 chatty systemd[2698]: Stopping Timers.
Oct 27 10:54:48 chatty systemd[2698]: Stopped target Timers.
Oct 27 10:54:48 chatty systemd[2698]: Stopping Sockets.
Oct 27 10:54:48 chatty systemd[2698]: Stopped target Sockets.
Oct 27 10:54:48 chatty systemd[2698]: Starting Shutdown.
Oct 27 10:54:48 chatty systemd[2698]: Reached target Shutdown.
Oct 27 10:54:48 chatty systemd[2698]: Starting Exit the Session...
Oct 27 10:54:48 chatty systemd[2698]: Received SIGRTMIN+24 from PID 2705 (kill).
Oct 27 10:54:48 chatty systemd[1]: Stopped User Manager for UID 0.
Oct 27 10:54:48 chatty systemd[1]: Stopping user-0.slice.
Oct 27 10:54:48 chatty systemd[1]: Removed slice user-0.slice.
Oct 27 10:58:07 chatty chronyd[458]: Forward time jump detected!
Oct 27 11:27:15 chatty kernel: hrtimer: interrupt took 4988150 ns
Oct 27 11:32:39 chatty dbus[419]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.s
Oct 27 11:32:39 chatty systemd[1]: Starting Daemon for power management...
Oct 27 11:32:39 chatty dbus[419]: [system] Successfully activated service 'org.freedesktop.UPower'
Oct 27 11:32:39 chatty systemd[1]: Started Daemon for power management.
Oct 27 11:36:06 chatty pulseaudio[937]: sink cork req state =1, now state=2
Oct 27 11:36:06 chatty pulseaudio[937]: sink cork req state =0, now state=1
Oct 27 11:36:16 chatty pulseaudio[937]: sink cork req state =1, now state=0
Oct 27 11:36:21 chatty pulseaudio[937]: sink cork req state =2, now state=1
Oct 27 11:36:42 chatty pulseaudio[937]: sink cork req state =1, now state=2
Oct 27 11:36:42 chatty pulseaudio[937]: sink cork req state =0, now state=1
Oct 27 11:36:52 chatty pulseaudio[937]: sink cork req state =1, now state=0
Oct 27 11:36:57 chatty pulseaudio[937]: sink cork req state =2, now state=1
Oct 27 11:42:11 chatty qrexec-agent[717]: executed (nowait) root:date -s "Tue Oct 27 11:46:05 PDT 2015" pid 3591
Oct 27 11:42:12 chatty qrexec-agent[717]: send exit code 0
Oct 27 11:42:12 chatty qrexec-agent[717]: eintr
Oct 27 11:42:12 chatty su[3591]: Successful su for root by root
Oct 27 11:42:12 chatty su[3591]: + ??? root:root
Oct 27 11:42:12 chatty su[3591]: pam_unix(su:session): session opened for user root by (uid=0)
Oct 27 11:42:12 chatty systemd[1]: Starting user-0.slice.
Oct 27 11:42:12 chatty systemd[1]: Created slice user-0.slice.
Oct 27 11:42:12 chatty systemd[1]: Starting User Manager for UID 0...
Oct 27 11:42:12 chatty systemd[1]: Starting Session c11 of user root.
Oct 27 11:42:12 chatty systemd[1]: Started Session c11 of user root.
Oct 27 11:42:12 chatty systemd-logind[413]: New session c11 of user root.
Oct 27 11:42:12 chatty systemd[3592]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Oct 27 11:42:12 chatty systemd[3592]: Starting Paths.
Oct 27 11:42:12 chatty systemd[3592]: Reached target Paths.
Oct 27 11:42:12 chatty systemd[3592]: Starting Timers.
Oct 27 11:42:12 chatty systemd[3592]: Reached target Timers.
Oct 27 11:42:12 chatty systemd[3592]: Starting Sockets.
Oct 27 11:42:12 chatty systemd[3592]: Reached target Sockets.
Oct 27 11:42:12 chatty systemd[3592]: Starting Basic System.
Oct 27 11:42:12 chatty systemd[3592]: Reached target Basic System.
Oct 27 11:42:12 chatty systemd[3592]: Starting Default.
Oct 27 11:42:12 chatty systemd[3592]: Reached target Default.
Oct 27 11:42:12 chatty systemd[3592]: Startup finished in 49ms.
Oct 27 11:42:12 chatty systemd[1]: Started User Manager for UID 0.
Oct 27 11:46:05 chatty systemd[3592]: Time has been changed
Oct 27 11:46:05 chatty systemd[1]: Time has been changed
Oct 27 11:46:05 chatty systemd[786]: Time has been changed
Oct 27 11:46:05 chatty su[3591]: pam_unix(su:session): session closed for user root
Oct 27 11:46:05 chatty systemd-logind[413]: Removed session c11.
Oct 27 11:46:05 chatty systemd[1]: Stopping User Manager for UID 0...
Oct 27 11:46:05 chatty systemd[3592]: Stopping Default.
Oct 27 11:46:05 chatty systemd[3592]: Stopped target Default.
Oct 27 11:46:05 chatty systemd[3592]: Stopping Basic System.
Oct 27 11:46:05 chatty systemd[3592]: Stopped target Basic System.
Oct 27 11:46:05 chatty systemd[3592]: Stopping Paths.
Oct 27 11:46:05 chatty systemd[3592]: Stopped target Paths.
Oct 27 11:46:05 chatty systemd[3592]: Stopping Timers.
Oct 27 11:46:05 chatty systemd[3592]: Stopped target Timers.
Oct 27 11:46:05 chatty systemd[3592]: Stopping Sockets.
Oct 27 11:46:05 chatty systemd[3592]: Stopped target Sockets.
Oct 27 11:46:05 chatty systemd[3592]: Starting Shutdown.
Oct 27 11:46:05 chatty systemd[3592]: Reached target Shutdown.
Oct 27 11:46:05 chatty systemd[3592]: Starting Exit the Session...
Oct 27 11:46:05 chatty systemd[3592]: Received SIGRTMIN+24 from PID 3600 (kill).
Oct 27 11:46:05 chatty systemd[3593]: pam_unix(systemd-user:session): session closed for user root
Oct 27 11:46:05 chatty systemd[1]: Stopped User Manager for UID 0.
Oct 27 11:46:05 chatty systemd[1]: Stopping user-0.slice.
Oct 27 11:46:05 chatty systemd[1]: Removed slice user-0.slice.
Oct 27 11:53:44 chatty chronyd[458]: Forward time jump detected!
Oct 27 12:25:31 chatty qrexec-agent[717]: executed (nowait) root:date -s "Tue Oct 27 13:14:52 PDT 2015" pid 3649
Oct 27 12:25:31 chatty qrexec-agent[717]: send exit code 0
Oct 27 12:25:31 chatty qrexec-agent[717]: eintr
Oct 27 12:25:31 chatty su[3649]: Successful su for root by root
Oct 27 12:25:31 chatty su[3649]: + ??? root:root
Oct 27 12:25:31 chatty su[3649]: pam_unix(su:session): session opened for user root by (uid=0)
Oct 27 12:25:31 chatty systemd[3650]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Oct 27 12:25:31 chatty systemd[1]: Starting user-0.slice.
Oct 27 12:25:31 chatty systemd[1]: Created slice user-0.slice.
Oct 27 12:25:31 chatty systemd[1]: Starting User Manager for UID 0...
Oct 27 12:25:31 chatty systemd[1]: Starting Session c12 of user root.

[qubesuser]

Accidentally pressing Win+Tab instead of Alt+Tab can result in this by switching to a different empty KDE activity, which will look exactly like all windows instantly disappearing but the KDE panel still working (fixable by pressing Win+Tab again until fixed).

Otherwise, running "sudo systemctl restart lightdm" in dom0 will restart the whole GUI and session and restart all guids and thus restore VM windows, which should fix any other strange GUI issue.

[marmarek]

@bnvk, did @qubesuser hint helped?

[bnvk]

I'm closing this issue as it has not happened since that one time. But to answer the question, no it was not caused by Accidentally pressing Win+Tab instead of Alt+Tab so it was probably a fluke given some random condition