I've configured KDE to show me the multi-option logout screen when I push the power button. Typically, I choose "Sleep" from there, using the keyboard (cursor keys + return). Sometimes - roughly two out of three - this will just return me to my current session, without the machine suspending. Requesting Sleep from KDE's K Menu always works, it's just not the way that's wired into my spine by now. Now, I managed to capture a syslog trace of what's going on, and they do differ significantly between the "does not work" and "does work" cases. Especially, the "does not work" trace shows error messages pertaining to qt.svg from ksmserver-logout-greeter. Visually, there's no difference. Here's the log in the "does not work" case: Oct 13 18:43:12 mercury systemd-logind[2466]: Power key pressed. Oct 13 18:43:12 mercury dbus-daemon[3070]: [session uid=500 pid=3070] Activating service name='org.kde.LogoutPrompt' requested by ':1.16' (uid=500 pid=3183 comm="/usr/bin/ksmserver " label="kernel") Oct 13 18:43:12 mercury dbus-daemon[3070]: [session uid=500 pid=3070] Successfully activated service 'org.kde.LogoutPrompt' Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:34: ReferenceError: model is not defined Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:406:376: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:407:130: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:408:130: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:408:393: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:409:130: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:410:129: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:411:129: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:412:129: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:413:129: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:413:379: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:13 mercury ksmserver-logout-greeter[3434868]: qt.svg: <input>:413:631: Could not add child element to parent element because the types are incorrect. Oct 13 18:43:15 mercury kwin_x11[3154]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 13629, resource id: 79691817, major code: 18 (ChangeProperty), minor code: 0 And here's the log of doing exactly the same thing a few seconds later, when it did work: Oct 13 18:43:28 mercury systemd-logind[2466]: Power key pressed. Oct 13 18:43:29 mercury dbus-daemon[3070]: [session uid=500 pid=3070] Activating service name='org.kde.LogoutPrompt' requested by ':1.16' (uid=500 pid=3183 comm="/usr/bin/ksmserver " label="kernel") Oct 13 18:43:29 mercury dbus-daemon[3070]: [session uid=500 pid=3070] Successfully activated service 'org.kde.LogoutPrompt' Oct 13 18:43:29 mercury ksmserver-logout-greeter[3434925]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:34: ReferenceError: model is not defined Oct 13 18:43:31 mercury kwin_x11[3154]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 19059, resource id: 79691817, major code: 18 (ChangeProperty), minor code: 0 Oct 13 18:43:31 mercury NetworkManager[2465]: <info> [1634143411.0632] manager: sleep: sleep requested (sleeping: no enabled: yes) [... and so on going to suspend.] This has been going on for a while now, anything between 3-6 months at a guess, spanning some number of minor KDE package upgrades. I see that there's an upgrade for qtsvg from 5.15.2 to 5.15.2-r10 coming in for me now; I'll let that build, restart my system and comment on this bug whether I can reproduce the problem still or not. I'll still file this bug for other folks to find, anyway. Here's my emerge --info: Portage 3.0.20 (python 3.9.6-final-0, default/linux/amd64/17.1/desktop/plasma/systemd, gcc-10.3.0, glibc-2.33-r1, 5.10.61-gentoo x86_64) ================================================================= System uname: Linux-5.10.61-gentoo-x86_64-Intel-R-_Core-TM-_i7-6700HQ_CPU_@_2.60GHz-with-glibc2.33 KiB Mem: 16179108 total, 1766160 free KiB Swap: 16777212 total, 15502124 free Timestamp of repository gentoo: Thu, 14 Oct 2021 08:15:01 +0000 Head commit of repository gentoo: ad75696a851b3c7e4edbc03abf9917bb80489b1b sh bash 5.1_p8 ld GNU ld (Gentoo 2.36.1 p5) 2.36.1 distcc 3.4 x86_64-pc-linux-gnu [disabled] ccache version 4.3 [disabled] app-shells/bash: 5.1_p8::gentoo dev-java/java-config: 2.3.1::gentoo dev-lang/perl: 5.34.0::gentoo dev-lang/python: 2.7.18_p11::gentoo, 3.7.11::gentoo, 3.9.6_p2::gentoo dev-lang/rust: 1.53.0::gentoo dev-util/ccache: 4.3-r2::gentoo dev-util/cmake: 3.20.5::gentoo sys-apps/baselayout: 2.7::gentoo sys-apps/sandbox: 2.24::gentoo sys-devel/autoconf: 2.13-r1::gentoo, 2.69-r5::gentoo sys-devel/automake: 1.16.3-r1::gentoo sys-devel/binutils: 2.36.1-r2::gentoo, 2.37_p1::gentoo sys-devel/gcc: 10.3.0-r2::gentoo sys-devel/gcc-config: 2.4::gentoo sys-devel/libtool: 2.4.6-r6::gentoo sys-devel/make: 4.3::gentoo sys-kernel/linux-headers: 5.10::gentoo (virtual/os-headers) sys-libs/glibc: 2.33-r1::gentoo Repositories: gentoo location: /usr/portage sync-type: rsync sync-uri: rsync://rsync.de.gentoo.org/gentoo-portage priority: -1000 sync-rsync-verify-metamanifest: yes sync-rsync-extra-opts: sync-rsync-verify-jobs: 1 sync-rsync-verify-max-age: 24 LOCAL location: /usr/local/portage masters: gentoo priority: 0 gentoo-zh location: /var/lib/layman/gentoo-zh masters: gentoo priority: 50 jmbreuer location: /var/lib/layman/jmbreuer masters: gentoo priority: 50 seden location: /var/lib/layman/seden masters: gentoo priority: 50 steam-overlay location: /var/lib/layman/steam-overlay masters: gentoo priority: 50 tlp location: /var/lib/layman/tlp masters: gentoo priority: 50 torbrowser location: /var/lib/layman/torbrowser masters: gentoo priority: 50 ACCEPT_KEYWORDS="amd64" ACCEPT_LICENSE="* -@EULA" CBUILD="x86_64-pc-linux-gnu" CFLAGS="-march=skylake -mtune=skylake -O2 -pipe -momit-leaf-frame-pointer" CHOST="x86_64-pc-linux-gnu" CONFIG_PROTECT="/etc /usr/lib64/libreoffice/program/sofficerc /usr/share/config /usr/share/easy-rsa /usr/share/gnupg/qualified.txt /usr/share/sddm/scripts" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/php/apache2-php7.4/ext-active/ /etc/php/cgi-php7.4/ext-active/ /etc/php/cli-php7.4/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo /etc/texmf/language.dat.d /etc/texmf/language.def.d /etc/texmf/updmap.d /etc/texmf/web2c /usr/share/X11/xkb" CXXFLAGS="-march=skylake -mtune=skylake -O2 -pipe -momit-leaf-frame-pointer" DISTDIR="/mnt/data/Archive/linux/gentoo/distfiles" EMERGE_DEFAULT_OPTS="--with-bdeps=y --jobs=12 --load-average=6" ENV_UNSET="CARGO_HOME DBUS_SESSION_BUS_ADDRESS DISPLAY GOBIN GOPATH PERL5LIB PERL5OPT PERLPREFIX PERL_CORE PERL_MB_OPT PERL_MM_OPT XAUTHORITY XDG_CACHE_HOME XDG_CONFIG_HOME XDG_DATA_HOME XDG_RUNTIME_DIR" FCFLAGS="-O2 -pipe" FEATURES="assume-digests binpkg-docompress binpkg-dostrip binpkg-logs buildpkg config-protect-if-modified distlocks ebuild-locks fixlafiles ipc-sandbox merge-sync multilib-strict network-sandbox news parallel-fetch pid-sandbox preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr" FFLAGS="-O2 -pipe" GENTOO_MIRRORS="http://mirror.netcologne.de/gentoo/ http://ftp.halifax.rwth-aachen.de/gentoo/ http://ftp.fau.de/gentoo http://mirror.eu.oneandone.net/linux/distributions/gentoo/gentoo/" LANG="en_US.UTF-8" LDFLAGS="-Wl,-O1 -Wl,--as-needed" LINGUAS="en de" MAKEOPTS="-j9 -l6" PKGDIR="/mnt/data/Archive/linux/gentoo/packages/x64cd" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages --exclude=/.git" PORTAGE_TMPDIR="/var/tmp" USE="X Xaw3d a52 aac acl acpi activities alsa amd64 apache2 bluetooth bluray branding bzip2 cairo cdda cdr cjk cli crypt css cups curl cvs dbus declarative dga dri dts dv dvd dvdr emacs emboss encode exif fame fastcgi ffmpeg flac flash fontconfig foomaticdb fortran fuse gcj gd gdbm gif glitz glut gphoto2 gpm gtk gui ibus iconv icu ieee1394 imap imlib innodb ipv6 jack java jce joystick jpeg kde kerberos kipi kpathsea kwallet lame lcms leim libgda libglvnd libnotify libsamplerate libtirpc lzo mad matroska mbox mjpeg mng modplug mono motif mozilla mp3 mp4 mpeg mplayer mtp mule multilib ncurses network network-cron networkmanager nls nptl nsplugin ntfs offensive ogg openal openexr opengl openmp opus pam pango pcap pcmcia pcre pda pdf plasma plotutils png policykit postscript ppds pulseaudio qml qt5 readline real rtsp samba scanner sdl seccomp semantic-desktop sensord slang slp smartcard sound spell split-usr sqlite ssl startup-notification stream subversion svg systemd tcpd theora threads tiff truetype trusted udev udisks unicode upower usb v4l v4l2 vaapi vdpau vhosts vim-syntax vlm vorbis vpx webdav webp widgets wifi wmf wxwidgets x264 xanim xattr xcb xcomposite xinerama xml xscreensaver xv xvid xvmc zeroconf zlib zsh-completion" ABI_X86="64 32" ADA_TARGET="gnat_2019" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" APACHE2_MODULES="authn_core authz_core socache_shmcb unixd actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="karbon sheets words" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" CPU_FLAGS_X86="aes avx avx2 f16c fma3 mmx mmxext pclmul popcnt sse sse2 sse3 sse4_1 sse4_2 ssse3" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock greis isync itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf skytraq superstar2 timing tsip tripmate tnt ublox ubx" INPUT_DEVICES="evdev synaptics" KERNEL="linux" L10N="en de" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" LUA_SINGLE_TARGET="lua5-1" LUA_TARGETS="lua5-1" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php7-3 php7-4" POSTGRES_TARGETS="postgres12 postgres13" PYTHON_SINGLE_TARGET="python3_9" PYTHON_TARGETS="python3_9" RUBY_TARGETS="ruby26 ruby27" SANE_BACKENDS="net" USERLAND="GNU" VIDEO_CARDS="intel i965 nvidia" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq proto steal rawnat logmark ipmark dhcpmac delude chaos account" Unset: CC, CPPFLAGS, CTARGET, CXX, INSTALL_MASK, LC_ALL, PORTAGE_BINHOST, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS, RUSTFLAGS
Very first tests with updated/freshly built qtsvg look promising, I've not had the issue immediately. I've made a reminder in a few days to close this issue if it no longer occurs to me, or update this thread, if it does.
After upgrading to dev-qt/qtsvg-5.15.2-r10 (from 5.15.2); and/or the rebuilds/other upgrades of the world upgrade this was part of, I cannot reproduce this any more.
Thanks for checking back.
OK, bad news - right now, it happened again. I used the power key to bring up the logout greeter, chose 'Sleep' (cursor right to make it wrap around to the leftmost option, return). And the machine returns straight to the desktop. These are the messages when initiating sleep did not work: Oct 20 18:58:57 mercury systemd-logind[2548]: Power key pressed. Oct 20 18:58:58 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Activating service name='org.kde.LogoutPrompt' requested by ':1.132' (uid=500 pid=14523 comm="/usr/bin/ksmserver " label="kernel") Oct 20 18:58:58 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Successfully activated service 'org.kde.LogoutPrompt' Oct 20 18:58:58 mercury ksmserver-logout-greeter[255739]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 20 18:58:58 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 20 18:58:59 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 20 18:58:59 mercury kwin_x11[14490]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 5250, resource id: 144703529, major code: 18 (ChangeProperty), minor code: 0 Ie, the slew of qt.svg error messages that I saw originally is gone. That's what the log looks like now when initiating sleep does work: Oct 20 19:05:00 mercury systemd-logind[2548]: Power key pressed. Oct 20 19:05:00 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Activating service name='org.kde.LogoutPrompt' requested by ':1.132' (uid=500 pid=14523 comm="/usr/bin/ksmserver " label="kernel") Oct 20 19:05:00 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Successfully activated service 'org.kde.LogoutPrompt' Oct 20 19:05:00 mercury ksmserver-logout-greeter[256078]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 20 19:05:02 mercury NetworkManager[2547]: <info> [1634749502.4822] manager: sleep: sleep requested (sleeping: no enabled: yes) [... more NetworkManager stuff ...] Oct 20 19:05:02 mercury kded5[14486]: bluedevil: About to suspend Oct 20 19:05:02 mercury kwin_x11[14490]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 39006, resource id: 146800681, major code: 18 (ChangeProperty), minor code: 0 Oct 20 19:05:02 mercury kded5[14486]: plasma-nm: Unhandled active connection state change: 3 [... more NetworkManager stuff ...] Oct 20 19:05:02 mercury NetworkManager[2547]: <warn> [1634749502.5572] dns-sd-resolved[f2d80c64812c63a4]: send-updates SetLinkDomains@4 failed: GDBus.Error:org.freedesktop.resolve1.LinkBusy: Link dummy0 is managed. Oct 20 19:05:02 mercury kscreenlocker_greet[256108]: Qt: Session management error: networkIdsList argument is NULL Oct 20 19:05:02 mercury kscreenlocker_greet[256108]: libpng warning: iCCP: known incorrect sRGB profile Oct 20 19:05:02 mercury systemd[1]: Reached target Sleep. [... and so on, from here on only daemon and kernel messages related to suspending] ksmserver-logout-greeter belongs to kde-plasma/plasma-workspace-5.22.5-r2, which got built a few days ago along with dev-qt/qtsvg-5.15.2-r10. The qml files that ksmserver-logout-greeter complains about are installed by the very same kde-plasma/plasma-workspace-5.22.5-r2 ebuild. I'm suspicious of the binding loop error that's flagged only in the non-working case. A search turned up these: https://bugs.kde.org/show_bug.cgi?id=443221 https://bugs.kde.org/show_bug.cgi?id=438246 I'm cross-referencing all these reports, maybe Nate of the 'Fixing this has been on my to-do list' comment has an idea ;-)
More bad news - any correlation between 'initiating sleep works' and specific messages that are logged by default seem coincidental. "Better" news (or not, if you want to debug this): It seems to fail much less often than before the recent upgrade. Last case of *not* initiating sleep: Oct 24 09:55:11 mercury systemd-logind[2548]: Power key pressed. Oct 24 09:55:11 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Activating service name='org.kde.LogoutPrompt' requested by ':1.132' (uid=500 pid=14523 comm="/usr/bin/ksmserver " label="kernel") Oct 24 09:55:11 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Successfully activated service 'org.kde.LogoutPrompt' Oct 24 09:55:11 mercury ksmserver-logout-greeter[280655]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 24 09:55:13 mercury kwin_x11[14490]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 30071, resource id: 125829161, major code: 18 (ChangeProperty), minor code: 0 ... and correctly initiating sleep shortly after: Oct 24 09:56:11 mercury systemd-logind[2548]: Power key pressed. Oct 24 09:56:11 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Activating service name='org.kde.LogoutPrompt' requested by ':1.132' (uid=500 pid=14523 comm="/usr/bin/ksmserver " label="kernel") Oct 24 09:56:11 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Successfully activated service 'org.kde.LogoutPrompt' Oct 24 09:56:11 mercury ksmserver-logout-greeter[280738]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 24 09:56:11 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 24 09:56:14 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 24 09:56:14 mercury kwin_x11[14490]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 35444, resource id: 125829161, major code: 18 (ChangeProperty), minor code: 0 Oct 24 09:56:14 mercury kded5[14486]: bluedevil: About to suspend Oct 24 09:56:14 mercury NetworkManager[2547]: <info> [1635062174.3479] manager: sleep: sleep requested (sleeping: no enabled: yes) [...] I've had a brief look at the code on github (for ksmserver-logout-greeter and there around), there's really not a lot going on. As soon as I find the time and energy/motivation, I'll add some logging to the respective code paths and see what that might show.
Created attachment 746802 [details, diff] Add tracing to ksmserver-logout-greeter
First level tracing of ksmserver-logout-greeter shows no difference between the "initiating sleep works" and "initiating sleep doesn't work" cases. Initiating sleep did not work: Oct 26 15:39:44 mercury systemd-logind[2548]: Power key pressed. Oct 26 15:39:44 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Activating service name='org.kde.LogoutPrompt' requested by ':1.132' (uid=500 pid=14523 comm="/usr/bin/ksmserver " label="kernel") Oct 26 15:39:45 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Successfully activated service 'org.kde.LogoutPrompt' Oct 26 15:39:45 mercury ksmserver-logout-greeter[523247]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 26 15:39:45 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 26 15:39:47 mercury ksmserver-logout-greeter[523247]: kde.logout_greeter: start of slotSuspend 2 Oct 26 15:39:47 mercury ksmserver-logout-greeter[523247]: kde.logout_greeter: after m_bootOption.clear() Oct 26 15:39:47 mercury ksmserver-logout-greeter[523247]: kde.logout_greeter: before m_session.suspend() Oct 26 15:39:47 mercury ksmserver-logout-greeter[523247]: kde.logout_greeter: after m_session.suspend() Oct 26 15:39:47 mercury ksmserver-logout-greeter[523247]: kde.logout_greeter: before reject() at end of slotSuspend Oct 26 15:39:47 mercury ksmserver-logout-greeter[523247]: kde.logout_greeter: after reject() at end of slotSuspend Oct 26 15:39:47 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 26 15:39:47 mercury kwin_x11[14490]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 47556, resource id: 125829161, major code: 18 (ChangeProperty), minor code: 0 Initiating sleep works: Oct 26 15:38:30 mercury systemd-logind[2548]: Power key pressed. Oct 26 15:38:31 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Activating service name='org.kde.LogoutPrompt' requested by ':1.132' (uid=500 pid=14523 comm="/usr/bin/ksmserver " label="kernel") Oct 26 15:38:31 mercury dbus-daemon[2969]: [session uid=500 pid=2969] Successfully activated service 'org.kde.LogoutPrompt' Oct 26 15:38:31 mercury ksmserver-logout-greeter[521645]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 26 15:38:31 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 26 15:38:32 mercury ksmserver-logout-greeter[521645]: kde.logout_greeter: start of slotSuspend 2 Oct 26 15:38:32 mercury ksmserver-logout-greeter[521645]: kde.logout_greeter: after m_bootOption.clear() Oct 26 15:38:32 mercury ksmserver-logout-greeter[521645]: kde.logout_greeter: before m_session.suspend() Oct 26 15:38:32 mercury ksmserver-logout-greeter[521645]: kde.logout_greeter: after m_session.suspend() Oct 26 15:38:32 mercury ksmserver-logout-greeter[521645]: kde.logout_greeter: before reject() at end of slotSuspend Oct 26 15:38:32 mercury ksmserver-logout-greeter[521645]: kde.logout_greeter: after reject() at end of slotSuspend Oct 26 15:38:33 mercury plasmashell[14534]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 26 15:38:33 mercury kwin_x11[14490]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 22474, resource id: 125829161, major code: 18 (ChangeProperty), minor code: 0 Oct 26 15:38:33 mercury NetworkManager[2547]: <info> [1635255513.0349] manager: sleep: sleep requested (sleeping: no enabled: yes) Oct 26 15:38:33 mercury kded5[14486]: bluedevil: About to suspend The patch is for reference and debugging purposes only, it should not be applied on production systems. I'll try to follow the m_session.suspend() code path further next.
Just caught another instance of sleep not being initiated: Oct 30 08:46:58 mercury systemd-logind[2563]: Power key pressed. Oct 30 08:46:58 mercury dbus-daemon[2983]: [session uid=500 pid=2983] Activating service name='org.kde.LogoutPrompt' requested by ':1.17' (uid=500 pid=3107 comm="/usr/bin/ksmserver " label="kernel") Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() creating LogindSessionBackend Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: LogindSessionBackend() Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: OrgFreedesktopLogin1ManagerInterface LogindMode: 3 Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:46:58 mercury dbus-daemon[2983]: [session uid=500 pid=2983] Successfully activated service 'org.kde.LogoutPrompt' Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:46:58 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.logout_greeter: start of slotSuspend 2 Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.logout_greeter: after m_bootOption.clear() Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.logout_greeter: before m_session.suspend() Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: SessionManagement::suspend() Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: suspending... Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: LogindSessionBackend::suspend() before m_login1->Suspend(true) Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.libkworkspace: LogindSessionBackend::suspend() after m_login1->Suspend(true) Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.logout_greeter: after m_session.suspend() Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.logout_greeter: before reject() at end of slotSuspend Oct 30 08:47:00 mercury ksmserver-logout-greeter[138489]: kde.logout_greeter: after reject() at end of slotSuspend Oct 30 08:47:00 mercury kwin_x11[3071]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 35266, resource id: 109051945, major code: 18 (ChangeProperty), minor code: 0 So the call gets all the way through to login1_manager_interface.cpp, which supposedly puts it on DBus. Since I started to debug this issue, I've used DBus signalling from the command line about half of the time to see if that makes a difference: $ qdbus --system org.freedesktop.login1 /org/freedesktop/login1 org.freedesktop.login1.Manager.Suspend true So far, this command line method of initiating sleep has ALWAYS worked, just as selecting 'Sleep' from the K Menu. So far, I've only observed the machine not suspending when initiated from ksmserver-logout-greeter... For now, I'll leave DBus monitoring running along, it seems to provide a good trace of what's going on on that level: $ dbus-monitor --system 'path=/org/freedesktop/login1' ... I've yet to catch suspend not working with that, though.
Created attachment 747384 [details, diff] Add tracing to libkworkspace SessionBackend Add debug tracing to allow suspend code path analysis; not ever intended to be applied in a production environment.
Speak of the devil - and here it is: Oct 30 09:10:31 mercury systemd-logind[2563]: Power key pressed. Oct 30 09:10:31 mercury dbus-daemon[2983]: [session uid=500 pid=2983] Activating service name='org.kde.LogoutPrompt' requested by ':1.17' (uid=500 pid=3107 comm="/usr/bin/ksmserver " label="kernel") Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() creating LogindSessionBackend Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: LogindSessionBackend() Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: OrgFreedesktopLogin1ManagerInterface LogindMode: 3 Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:31 mercury dbus-daemon[2983]: [session uid=500 pid=2983] Successfully activated service 'org.kde.LogoutPrompt' Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:31 mercury ksmserver-logout-greeter[141527]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/UserDelegate.qml:35: ReferenceError: model is not defined Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.logout_greeter: start of slotSuspend 2 Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.logout_greeter: after m_bootOption.clear() Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.logout_greeter: before m_session.suspend() Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: SessionManagement::suspend() Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: suspending... Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: LogindSessionBackend::suspend() before m_login1->Suspend(true) Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.libkworkspace: LogindSessionBackend::suspend() after m_login1->Suspend(true) Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.logout_greeter: after m_session.suspend() Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.logout_greeter: before reject() at end of slotSuspend Oct 30 09:10:35 mercury ksmserver-logout-greeter[141527]: kde.logout_greeter: after reject() at end of slotSuspend Oct 30 09:10:35 mercury kwin_x11[3071]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 6549, resource id: 111149097, major code: 18 (ChangeProperty), minor code: 0 DBus trace: $ dbus-monitor --system 'path=/org/freedesktop/login1' signal time=1635577825.600380 sender=org.freedesktop.DBus -> destination=:1.343 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired string ":1.343" signal time=1635577825.600411 sender=org.freedesktop.DBus -> destination=:1.343 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost string ":1.343" method call time=1635577831.608028 sender=:1.344 -> destination=org.freedesktop.login1 serial=5 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=CanPowerOff method call time=1635577831.608124 sender=:1.344 -> destination=org.freedesktop.login1 serial=6 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=CanReboot method call time=1635577831.608175 sender=:1.344 -> destination=org.freedesktop.login1 serial=7 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=CanSuspend method call time=1635577831.608235 sender=:1.344 -> destination=org.freedesktop.login1 serial=8 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=CanHybridSleep method call time=1635577831.608282 sender=:1.344 -> destination=org.freedesktop.login1 serial=9 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=CanHibernate method call time=1635577831.654420 sender=:1.344 -> destination=org.freedesktop.login1 serial=13 path=/org/freedesktop/login1; interface=org.freedesktop.DBus.Properties; member=Get string "org.freedesktop.login1.Manager" string "RebootToFirmwareSetup" method call time=1635577831.760815 sender=:1.344 -> destination=org.freedesktop.login1 serial=19 path=/org/freedesktop/login1; interface=org.freedesktop.DBus.Introspectable; member=Introspect method call time=1635577835.375038 sender=:1.344 -> destination=org.freedesktop.login1 serial=50 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=Suspend boolean true soo... org.freedesktop.login1.Manager.Suspend is called just the same, but nothing's happening after. When initiating sleep works, there's a lot more traffic on that DBus path immediately after the Suspend call, starting with PrepareForSleep: method call time=1635577424.829795 sender=:1.335 -> destination=org.freedesktop.login1 serial=50 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=Suspend boolean true signal time=1635577424.876552 sender=:1.4 -> destination=(null destination) serial=2678 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=PrepareForSleep boolean true signal time=1635577424.884510 sender=:1.4 -> destination=(null destination) serial=2680 path=/org/freedesktop/login1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged string "org.freedesktop.login1.Manager" array [ dict entry( string "DelayInhibited" variant string "sleep" ) ] array [ ] [...] I'll look further into where org.freedesktop.login1.Manager.Suspend causes org.freedesktop.login1.Manager.PrepareForSleep to be issued, since that looks like the key difference between the two cases now.
Started to add tracing and configured systemd-logind for debug logging, now differences between the working and failing case start to show up. Initiating sleep working: Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.logout_greeter: start of slotSuspend 2 Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.logout_greeter: after m_bootOption.clear() Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.logout_greeter: before m_session.suspend() Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.libkworkspace: SessionManagement::suspend() Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.libkworkspace: *SessionBackend::self() returning existing singl eton Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.libkworkspace: suspending... Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.libkworkspace: *SessionBackend::self() returning existing singl eton Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.libkworkspace: LogindSessionBackend::suspend() before m_login1- >Suspend(true) Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.libkworkspace: LogindSessionBackend::suspend() after m_login1- >Suspend(true) Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.logout_greeter: after m_session.suspend() Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.logout_greeter: before reject() at end of slotSuspend Oct 31 06:42:08 mercury ksmserver-logout-greeter[219663]: kde.logout_greeter: after reject() at end of slotSuspend Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_call sender=:1.524 destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=Suspend cookie=74 reply_cookie=0 signature=b er ror-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() enter Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() flags parsed Oct 31 06:42:08 mercury systemd-logind[216478]: Sleep mode "freeze" is supported by the kernel. Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() operation verified Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=831 reply_cookie=0 signature=s error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=181 reply_cookie=831 signature=u error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=832 reply_cookie=0 signature=s error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=182 reply_cookie=832 signature=u error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.PolicyKit1 path=/org/freedesktop/PolicyKit1/Authority interface=org.freedesktop.PolicyKit1.Authority member=CheckAuthorization cookie=833 reply_cookie=0 signature=(sa{sv})sa{ss}us error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() creds verified: 1 Oct 31 06:42:08 mercury plasmashell[216742]: file:///usr/share/plasma/shells/org.kde.plasma.desktop/contents/views/Panel.qml:27:1: QML Panel: Binding loop detected for property "state" Oct 31 06:42:08 mercury kwin_x11[216681]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 54790, resource id: 92274729, major code: 18 (ChangeProperty), minor code: 0 Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_return sender=:1.19 destination=:1.456 path=n/a interface=n/a member=n/a cookie=8590 reply_cookie=833 signature=(bba{ss}) error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_call sender=:1.524 destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=Suspend cookie=74 reply_cookie=0 signature=b error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() enter Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() flags parsed Oct 31 06:42:08 mercury systemd-logind[216478]: Sleep mode "freeze" is supported by the kernel. Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() operation verified Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=834 reply_cookie=0 signature=s error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=183 reply_cookie=834 signature=u error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() creds verified: 0 Oct 31 06:42:08 mercury systemd-logind[216478]: bus_manager_shutdown_or_sleep_now_or_later() enter Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/suspend_2etarget interface=org.freedesktop.DBus.Properties member=Get cookie=835 reply_cookie=0 signature=ss error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=method_return sender=:1.384 destination=:1.456 path=n/a interface=n/a member=n/a cookie=5143 reply_cookie=835 signature=v error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: send_prepare_for() Oct 31 06:42:08 mercury systemd-logind[216478]: send_prepare_for() sending PrepareFor... Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=PrepareForSleep cookie=836 reply_cookie=0 signature=b error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: bus_manager_shutdown_or_sleep_now_or_later() leave Oct 31 06:42:08 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() leave Oct 31 06:42:08 mercury systemd-logind[216478]: Sent message type=method_return sender=n/a destination=:1.524 path=n/a interface=n/a member=n/a cookie=837 reply_cookie=74 signature=n/a error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=signal sender=:1.384 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=5145 reply_cookie=0 signature=so error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=signal sender=:1.384 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=5147 reply_cookie=0 signature=so error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=signal sender=:1.384 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=5149 reply_cookie=0 signature=so error-name=n/a error-message=n/a Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=signal sender=:1.384 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=5151 reply_cookie=0 signature=so error-name=n/a error-message=n/a Oct 31 06:42:08 mercury kded5[216677]: bluedevil: About to suspend Oct 31 06:42:08 mercury systemd-logind[216478]: Got message type=signal sender=:1.384 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=5153 reply_cookie=0 signature=so error-name=n/a error-message=n/a Oct 31 06:42:08 mercury NetworkManager[2562]: <info> [1635658928.4318] manager: sleep: sleep requested (sleeping: no enabled: yes) [...] And the fail case: Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.logout_greeter: start of slotSuspend 2 Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.logout_greeter: after m_bootOption.clear() Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.logout_greeter: before m_session.suspend() Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.libkworkspace: SessionManagement::suspend() Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.libkworkspace: suspending... Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.libkworkspace: *SessionBackend::self() returning existing singleton Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.libkworkspace: LogindSessionBackend::suspend() before m_login1->Suspend(true) Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.libkworkspace: LogindSessionBackend::suspend() after m_login1->Suspend(true) Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.logout_greeter: after m_session.suspend() Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.logout_greeter: before reject() at end of slotSuspend Oct 30 23:23:24 mercury ksmserver-logout-greeter[217684]: kde.logout_greeter: after reject() at end of slotSuspend Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=method_call sender=:1.506 destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=Suspend cookie=74 reply_cookie=0 signature=b error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() enter Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() flags parsed Oct 30 23:23:24 mercury systemd-logind[216478]: Sleep mode "freeze" is supported by the kernel. Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() operation verified Oct 30 23:23:24 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=490 reply_cookie=0 signature=s error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=103 reply_cookie=490 signature=u error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=491 reply_cookie=0 signature=s error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=104 reply_cookie=491 signature=u error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.PolicyKit1 path=/org/freedesktop/PolicyKit1/Authority interface=org.freedesktop.PolicyKit1.Authority member=CheckAuthorization cookie=492 reply_cookie=0 signature=(sa{sv})sa{ss}us error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() creds verified: 1 Oct 30 23:23:24 mercury kwin_x11[216681]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 37692, resource id: 73400361, major code: 18 (ChangeProperty), minor code: 0 Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=method_return sender=:1.19 destination=:1.456 path=n/a interface=n/a member=n/a cookie=8269 reply_cookie=492 signature=(bba{ss}) error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=method_call sender=:1.506 destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=Suspend cookie=74 reply_cookie=0 signature=b error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() enter Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() flags parsed Oct 30 23:23:24 mercury systemd-logind[216478]: Sleep mode "freeze" is supported by the kernel. Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() operation verified Oct 30 23:23:24 mercury systemd-logind[216478]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=493 reply_cookie=0 signature=s error-name=n/a error-message=n/a Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=error sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=105 reply_cookie=493 signature=s error-name=org.freedesktop.DBus.Error.NameHasNoOwner error-message=Could not get UID of name ':1.506': no such name Oct 30 23:23:24 mercury systemd-logind[216478]: method_do_shutdown_or_sleep() creds verified: -6 Oct 30 23:23:24 mercury systemd-logind[216478]: Sent message type=error sender=n/a destination=:1.506 path=n/a interface=n/a member=n/a cookie=494 reply_cookie=74 signature=s error-name=System.Error.ENXIO error-message=No such device or address Oct 30 23:23:24 mercury systemd-logind[216478]: Failed to process message type=method_call sender=:1.506 destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=Suspend cookie=74 reply_cookie=0 signature=b error-name=n/a error-message=n/a: No such device or address Oct 30 23:23:24 mercury systemd-logind[216478]: Got message type=error sender=org.freedesktop.DBus destination=:1.456 path=n/a interface=n/a member=n/a cookie=106 reply_cookie=494 signature=s error-name=org.freedesktop.DBus.Error.ServiceUnknown error-message=The name :1.506 was not provided by any .service files So, in the failing case, verification of the user credentials for the sleep operation fails. If I read the error message right: error-name=org.freedesktop.DBus.Error.NameHasNoOwner error-message=Could not get UID of name ':1.506': no such name This is due to :1.506 already being disconnected from DBus and no longer available for credential queries. :1.506 is ksmserver-logout-greeter, as you can see from where the org.freedesktop.login1.Manager.Suspend method call message is first sent. It would make sense that this happens "sometimes", ksmserver-logout-greeter apparently exits after (asynchronously) calling the Suspend method and either it's still around, or it isn't. Requesting sleep from the K Menu would always work, since in that case the Suspend method is initiated by plasmashell, which sticks around. Since it always works correctly using qdbus on the command line (which also returns immediately, without perceptible delay), I guess it's doing a more sensible thing of performing that call synchronously and thus is always around for the interposed credentials check. I'll have a look and will prepare and test a patch to change ksmserver-logout-greeter to always be available for the credentials check.
Created attachment 747675 [details, diff] Add tracing to systemd-logind Add debug tracing of suspend code path to systemd-logind. This is for debugging purposes only and should never be applied on a production system.
Created attachment 747678 [details, diff] Fix LogindSessionBackend::suspend() to be synchronous This is a working fix for the specific case I was experiencing. With 20/20 hindsight: A few lines higher up there's a comment about .waitForFinished() in the PowerOff case; which describes exactly the "confirm credentials with a caller which might immediately quit" case. (I never saw that comment, because I'd search for 'Suspend' in the editor which would then have it scrolled beyond the top of my view...) Anyway, in the case of ksmserver-logout-greeter specifically, that very same case applies to the suspend etc use cases just the same: They get invoked and the caller immediately exists. On this machine, I don't use hibernate / hybrid suspend; but in my opinion those calls should be made synchronous exactly like Suspend() and for the same reason. I ran and tested this briefly with all the tracing applied as well; now I'm running only this one-liner fix and will confirm that it is stable over the next few days.
Created attachment 747774 [details, diff] Fix LogindSessionBackend::suspend() to be synchronous Proper fix including all related cases (suspend, hibernate, hybrid) and clarification in the code comment.
I've also submitted the fix upstream as: https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/1164
Amazing work, thanks.
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=5c3a65d7d43f8204ab5aa011bd8393d4e242a102 commit 5c3a65d7d43f8204ab5aa011bd8393d4e242a102 Author: Andreas Sturmlechner <asturm@gentoo.org> AuthorDate: 2021-11-09 14:35:21 +0000 Commit: Andreas Sturmlechner <asturm@gentoo.org> CommitDate: 2021-11-09 17:14:20 +0000 kde-plasma/libkworkspace: Fix sleep/suspend race condition See also: https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/1164 Thanks-to: Joe Breuer <kde@jmbreuer.net> Bug: https://bugs.gentoo.org/818124 Package-Manager: Portage-3.0.28, Repoman-3.0.3 Signed-off-by: Andreas Sturmlechner <asturm@gentoo.org> ...bkworkspace-5.23.3-synchronous-dbus-calls.patch | 48 ++++++++++++++++++++++ .../libkworkspace/libkworkspace-5.23.3.ebuild | 5 +++ 2 files changed, 53 insertions(+)
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/proj/kde.git/commit/?id=92c8a38b51613f972cbbdcf6fe3a6a96612f20c1 commit 92c8a38b51613f972cbbdcf6fe3a6a96612f20c1 Author: Andreas Sturmlechner <asturm@gentoo.org> AuthorDate: 2021-11-09 14:35:21 +0000 Commit: Andreas Sturmlechner <asturm@gentoo.org> CommitDate: 2021-12-10 15:09:54 +0000 kde-plasma/libkworkspace: Fix sleep/suspend race condition (not fixed in 5.23 branch yet) See also: https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/1164 Thanks-to: Joe Breuer <kde@jmbreuer.net> Bug: https://bugs.gentoo.org/818124 Package-Manager: Portage-3.0.28, Repoman-3.0.3 Signed-off-by: Andreas Sturmlechner <asturm@gentoo.org> ...bkworkspace-5.23.3-synchronous-dbus-calls.patch | 48 ++++++++++++++++++++++ .../libkworkspace-5.23.49.9999.ebuild | 5 +++ 2 files changed, 53 insertions(+)
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=21ed02f5976d3fedfac8e3d7b894685593103c33 commit 21ed02f5976d3fedfac8e3d7b894685593103c33 Author: Andreas Sturmlechner <asturm@gentoo.org> AuthorDate: 2021-11-09 14:35:21 +0000 Commit: Andreas Sturmlechner <asturm@gentoo.org> CommitDate: 2021-12-10 15:11:03 +0000 kde-plasma/libkworkspace: Fix sleep/suspend race condition (not fixed in 5.23.4 yet) See also: https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/1164 Thanks-to: Joe Breuer <kde@jmbreuer.net> Bug: https://bugs.gentoo.org/818124 Package-Manager: Portage-3.0.28, Repoman-3.0.3 Signed-off-by: Andreas Sturmlechner <asturm@gentoo.org> ...bkworkspace-5.23.3-synchronous-dbus-calls.patch | 48 +++++++++++++++++ .../libkworkspace/libkworkspace-5.23.4-r1.ebuild | 60 ++++++++++++++++++++++ 2 files changed, 108 insertions(+)
