Bug#961146: systemd-logind sometimes ignores a systemd-inhibit lock

[Vincent Lefevre]

On 2020-05-23 16:53:06 +0200, Michael Biebl wrote:
> Am 23.05.20 um 02:59 schrieb Vincent Lefevre:
> > On 2020-05-22 23:53:58 +0200, Michael Biebl wrote:
> >> This is strange. Something is triggering the start of systemd-logind
> > 
> > What do you mean by "start of systemd-logind"?
> > 
> > On my machine, systemd-logind is started early at boot time and
> > never quits.
> 
> You said:
> 
> > The running instance cannot be stopped as it is automatically
> > restarted. 
> 
> when I adviced you to stop the running systemd-logind.service and
> starting logind by hand.

OK, if I do "service systemd-logind stop", it is effectively
stopped. Then I start

  SYSTEMD_LOG_LEVEL=debug /lib/systemd/systemd-logind

from VT 1. I log in on VT 2, start the inhibitor and log out, then
I close the lid. Nothing happens. Then I switch to VT 3, and the
system suspends immediately. So, same issue. In the logs:

May 24 23:12:50 zira dhclient[2527]: DHCPREQUEST for 192.168.1.3 on eth0 to 192.168.1.1 port 67
May 24 23:12:50 zira dhclient[2527]: DHCPACK of 192.168.1.3 from 192.168.1.1
May 24 23:12:50 zira root[568208]: /etc/dhcp/dhclient-enter-hooks.d/google-tcp-dns with reason=RENEW
May 24 23:12:50 zira root[568219]: /etc/dhcp/dhclient-exit-hooks.d/0google-tcp-dns with reason=RENEW
May 24 23:12:50 zira dhclient[2527]: bound to 192.168.1.3 -- renewal in 33912 seconds.
May 24 23:13:09 zira login[158128]: pam_unix(login:auth): Couldn't open /etc/securetty: No such file or directory
May 24 23:13:12 zira login[158128]: pam_unix(login:auth): Couldn't open /etc/securetty: No such file or directory
May 24 23:13:12 zira login[158128]: pam_unix(login:session): session opened for user vinc17 by LOGIN(uid=0)
May 24 23:13:12 zira systemd[1]: Created slice User Slice of UID 1000.
May 24 23:13:12 zira systemd[1]: Starting User Runtime Directory /run/user/1000...
May 24 23:13:12 zira systemd[1]: Finished User Runtime Directory /run/user/1000.
May 24 23:13:12 zira systemd[1]: Starting User Manager for UID 1000...
May 24 23:13:12 zira systemd[568233]: pam_unix(systemd-user:session): session opened for user vinc17 by (uid=0)
May 24 23:13:12 zira systemd[568238]: gpgconf: error running '/usr/lib/gnupg/scdaemon': probably not installed
May 24 23:13:12 zira systemd[568233]: Reached target Paths.
May 24 23:13:12 zira systemd[568233]: Reached target Timers.
May 24 23:13:12 zira systemd[568233]: Starting D-Bus User Message Bus Socket.
May 24 23:13:12 zira systemd[568233]: Listening on GnuPG network certificate management daemon.
May 24 23:13:12 zira systemd[568233]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 24 23:13:12 zira systemd[568233]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
May 24 23:13:12 zira systemd[568233]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
May 24 23:13:12 zira systemd[568233]: Listening on GnuPG cryptographic agent and passphrase cache.
May 24 23:13:12 zira systemd[568233]: Listening on Sound System.
May 24 23:13:12 zira systemd[568233]: Listening on D-Bus User Message Bus Socket.
May 24 23:13:12 zira systemd[568233]: Reached target Sockets.
May 24 23:13:12 zira systemd[568233]: Reached target Basic System.
May 24 23:13:12 zira systemd[1]: Started User Manager for UID 1000.
May 24 23:13:12 zira systemd[568233]: Starting Sound Service...
May 24 23:13:12 zira systemd[1]: Started Session 919 of user vinc17.
May 24 23:13:12 zira rtkit-daemon[793]: Successfully made thread 568253 of process 568253 owned by '1000' high priority at nice level -11.
May 24 23:13:12 zira rtkit-daemon[793]: Supervising 1 threads of 1 processes of 1 users.
May 24 23:13:12 zira systemd[568233]: Started D-Bus User Message Bus.
May 24 23:13:12 zira kernel: snd_hda_codec_hdmi hdaudioC1D0: HDMI: invalid ELD data byte 57
May 24 23:13:12 zira rtkit-daemon[793]: Supervising 1 threads of 1 processes of 1 users.
May 24 23:13:12 zira rtkit-daemon[793]: Successfully made thread 568375 of process 568253 owned by '1000' RT at priority 5.
May 24 23:13:12 zira rtkit-daemon[793]: Supervising 2 threads of 1 processes of 1 users.
May 24 23:13:13 zira rtkit-daemon[793]: Supervising 2 threads of 1 processes of 1 users.
May 24 23:13:13 zira rtkit-daemon[793]: Successfully made thread 568376 of process 568253 owned by '1000' RT at priority 5.
May 24 23:13:13 zira rtkit-daemon[793]: Supervising 3 threads of 1 processes of 1 users.
May 24 23:13:13 zira rtkit-daemon[793]: Supervising 3 threads of 1 processes of 1 users.
May 24 23:13:13 zira rtkit-daemon[793]: Successfully made thread 568377 of process 568253 owned by '1000' RT at priority 5.
May 24 23:13:13 zira rtkit-daemon[793]: Supervising 4 threads of 1 processes of 1 users.
May 24 23:13:13 zira systemd[568233]: Started Sound Service.
May 24 23:13:13 zira systemd[568233]: Reached target Main User Target.
May 24 23:13:13 zira systemd[568233]: Startup finished in 684ms.
May 24 23:13:13 zira bluetoothd[773]: Endpoint registered: sender=:1.230 path=/MediaEndpoint/A2DPSink/sbc
May 24 23:13:13 zira bluetoothd[773]: Endpoint registered: sender=:1.230 path=/MediaEndpoint/A2DPSource/sbc
May 24 23:13:20 zira inhibit-suspend[568398]: (vinc17) on-line: yes
May 24 23:13:20 zira inhibit-suspend[568403]: (vinc17) output: 0
May 24 23:13:29 zira login[158128]: pam_unix(login:session): session closed for user vinc17
May 24 23:13:29 zira systemd[1]: getty at tty2.service: Succeeded.
May 24 23:13:29 zira systemd[1]: getty at tty2.service: Scheduled restart job, restart counter is at 4.
May 24 23:13:29 zira systemd[1]: Stopped Getty on tty2.
May 24 23:13:29 zira systemd[1]: Started Getty on tty2.
May 24 23:13:29 zira bluetoothd[773]: Endpoint unregistered: sender=:1.230 path=/MediaEndpoint/A2DPSink/sbc
May 24 23:13:29 zira bluetoothd[773]: Endpoint unregistered: sender=:1.230 path=/MediaEndpoint/A2DPSource/sbc
May 24 23:13:29 zira systemd[568233]: pulseaudio.service: Succeeded.
May 24 23:13:30 zira inhibit-suspend[568423]: (vinc17) on-line: yes
May 24 23:13:30 zira inhibit-suspend[568428]: (vinc17) output: 0
May 24 23:13:39 zira systemd[1]: Reached target Sleep.
May 24 23:13:39 zira systemd[1]: Starting Suspend...
May 24 23:13:39 zira systemd[1]: Stopping Atop advanced performance monitor...
May 24 23:13:39 zira systemd[1]: atop.service: Succeeded.
May 24 23:13:39 zira systemd[1]: Stopped Atop advanced performance monitor.
May 24 23:13:39 zira systemd-sleep[568431]: Suspending system...
[...]

-- 
Vincent Lefèvre <vincent at vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)