Bug#961124: systemd: suspend for no apparent reasons when using light-locker and the screensaver becomes inactive

Vincent Lefevre vincent at vinc17.net
Wed May 20 12:59:06 BST 2020


Package: systemd
Version: 245.5-2
Severity: important

When I use "light-locker --late-locking" for screen locking and
the screensaver becomes inactive, e.g. because I move the mouse,
systemd-logind suspends the system. The journalctl logs just say
"systemd-logind[xxx]: Suspending...". The system is automatically
resumed a few seconds later, but with indeterminate effects on
the status of the system (the X server may no longer work).

Details:

I have a laptop with 2 external monitors. The laptop screen is off and
the lid is usually closed (not completely, but as seen by the system).
The suspend due to lid closing is inhibited by a systemd-inhibit lock.
I just use the builtin X11 screensaver + "light-locker --late-locking"
for screen locking.

In the morning, while the screensaver was active, moving the mouse had
no visible effect, nor typing some keys on the USB keyboard. The lid of
the laptop was closed. I opened it completely to see whether there was
something, and at this time I heard the fan, which typically happens
when the laptop wakes up after a suspend.

According to the journalctl log excerpt below, the system was not
suspended before I moved to mouse to stop the screensaver.

More tests have shown that the system is suspended each time the
screensaver becomes inactive, and this does not occur if I do not
use light-locker.

-- Logs begin at Mon 2019-06-03 11:58:51 CEST, end at Wed 2020-05-20 09:50:47 CEST. --
May 20 02:36:23 zira kernel: microcode: microcode updated early to revision 0x27, date = 2019-02-26
May 20 02:36:23 zira kernel: Linux version 5.6.0-1-amd64 (debian-kernel at lists.debian.org) (gcc version 9.3.0 (Debian 9.3.0-11)) #1 SMP Debian 5.6.7-1 (2020-04-29)
May 20 02:36:23 zira kernel: Command line: BOOT_IMAGE=/vmlinuz-5.6.0-1-amd64 root=/dev/mapper/zira--vg-root ro quiet
[...]
May 20 09:13:09 zira inhibit-suspend[200484]: (vinc17) on-line: yes
May 20 09:13:09 zira inhibit-suspend[200489]: (vinc17) output: 3
May 20 09:13:19 zira inhibit-suspend[200497]: (vinc17) on-line: yes
May 20 09:13:19 zira inhibit-suspend[200502]: (vinc17) output: 3
May 20 09:13:29 zira inhibit-suspend[200511]: (vinc17) on-line: yes
May 20 09:13:29 zira inhibit-suspend[200516]: (vinc17) output: 3
May 20 09:13:39 zira inhibit-suspend[200527]: (vinc17) on-line: yes
May 20 09:13:39 zira inhibit-suspend[200532]: (vinc17) output: 3
May 20 09:13:49 zira inhibit-suspend[200541]: (vinc17) on-line: yes
May 20 09:13:49 zira inhibit-suspend[200546]: (vinc17) output: 3
May 20 09:13:59 zira inhibit-suspend[200554]: (vinc17) on-line: yes
May 20 09:13:59 zira inhibit-suspend[200559]: (vinc17) output: 3
May 20 09:14:09 zira inhibit-suspend[200567]: (vinc17) on-line: yes
May 20 09:14:09 zira inhibit-suspend[200572]: (vinc17) output: 3
May 20 09:14:19 zira inhibit-suspend[200580]: (vinc17) on-line: yes
May 20 09:14:19 zira inhibit-suspend[200585]: (vinc17) output: 3
May 20 09:14:29 zira inhibit-suspend[200593]: (vinc17) on-line: yes
May 20 09:14:29 zira inhibit-suspend[200598]: (vinc17) output: 3
May 20 09:14:39 zira inhibit-suspend[200606]: (vinc17) on-line: yes
May 20 09:14:39 zira inhibit-suspend[200611]: (vinc17) output: 3
May 20 09:14:49 zira inhibit-suspend[200620]: (vinc17) on-line: yes
May 20 09:14:49 zira inhibit-suspend[200625]: (vinc17) output: 3
May 20 09:14:59 zira inhibit-suspend[200634]: (vinc17) on-line: yes
May 20 09:14:59 zira inhibit-suspend[200639]: (vinc17) output: 3
May 20 09:15:01 zira CRON[200642]: pam_unix(cron:session): session opened for user root by (uid=0)
May 20 09:15:01 zira CRON[200643]: pam_unix(cron:session): session opened for user root by (uid=0)
May 20 09:15:01 zira CRON[200644]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 09:15:01 zira CRON[200645]: (root) CMD (/sbin/hwclock --systohc)
May 20 09:15:01 zira CRON[200643]: pam_unix(cron:session): session closed for user root
May 20 09:15:02 zira CRON[200642]: pam_unix(cron:session): session closed for user root
May 20 09:15:09 zira inhibit-suspend[200653]: (vinc17) on-line: yes
May 20 09:15:09 zira inhibit-suspend[200658]: (vinc17) output: 3
May 20 09:15:19 zira inhibit-suspend[200666]: (vinc17) on-line: yes
May 20 09:15:20 zira inhibit-suspend[200671]: (vinc17) output: 3
May 20 09:15:30 zira inhibit-suspend[200679]: (vinc17) on-line: yes
May 20 09:15:30 zira inhibit-suspend[200684]: (vinc17) output: 3
May 20 09:15:40 zira inhibit-suspend[200693]: (vinc17) on-line: yes
May 20 09:15:40 zira inhibit-suspend[200698]: (vinc17) output: 3
May 20 09:15:50 zira inhibit-suspend[200706]: (vinc17) on-line: yes
May 20 09:15:50 zira inhibit-suspend[200711]: (vinc17) output: 3
May 20 09:16:00 zira inhibit-suspend[200719]: (vinc17) on-line: yes
May 20 09:16:00 zira inhibit-suspend[200724]: (vinc17) output: 3
May 20 09:16:10 zira inhibit-suspend[200732]: (vinc17) on-line: yes
May 20 09:16:10 zira inhibit-suspend[200737]: (vinc17) output: 3
May 20 09:16:20 zira inhibit-suspend[200745]: (vinc17) on-line: yes
May 20 09:16:20 zira inhibit-suspend[200750]: (vinc17) output: 3
May 20 09:16:30 zira inhibit-suspend[200765]: (vinc17) on-line: yes
May 20 09:16:43 zira systemd-logind[785]: Suspending...
May 20 09:16:43 zira systemd[1]: Reached target Sleep.
May 20 09:16:43 zira systemd[1]: Starting Suspend...
May 20 09:16:43 zira systemd[1]: Stopping Atop advanced performance monitor...
May 20 09:16:43 zira inhibit-suspend[200779]: (vinc17) output: 3
May 20 09:16:43 zira systemd[1]: atop.service: Succeeded.
May 20 09:16:43 zira systemd[1]: Stopped Atop advanced performance monitor.
May 20 09:16:43 zira systemd-sleep[200774]: Suspending system...
May 20 09:16:43 zira kernel: PM: suspend entry (deep)
May 20 09:16:43 zira kernel: Filesystems sync: 0.017 seconds
May 20 09:17:02 zira kernel: (NULL device *): firmware: direct-loading firmware regulatory.db.p7s
May 20 09:17:02 zira kernel: (NULL device *): firmware: direct-loading firmware regulatory.db
May 20 09:17:02 zira kernel: (NULL device *): firmware: direct-loading firmware intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
May 20 09:17:02 zira kernel: (NULL device *): firmware: direct-loading firmware iwlwifi-7260-17.ucode
May 20 09:17:02 zira kernel: Freezing user space processes ... (elapsed 0.001 seconds) done.
May 20 09:17:02 zira kernel: OOM killer disabled.
May 20 09:17:02 zira kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
May 20 09:17:02 zira kernel: printk: Suspending console(s) (use no_console_suspend to debug)
May 20 09:17:02 zira kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
May 20 09:17:02 zira kernel: sd 0:0:0:0: [sda] Stopping disk
May 20 09:17:02 zira kernel: parport_pc 00:04: disabled
May 20 09:17:02 zira kernel: e1000e: EEE TX LPI TIMER: 00000011
May 20 09:17:02 zira kernel: ACPI: EC: interrupt blocked
May 20 09:17:02 zira kernel: ACPI: Preparing to enter system sleep state S3
May 20 09:17:02 zira kernel: ACPI: EC: event blocked
May 20 09:17:02 zira kernel: ACPI: EC: EC stopped
May 20 09:17:02 zira kernel: PM: Saving platform NVS memory
May 20 09:17:02 zira kernel: Disabling non-boot CPUs ...
May 20 09:17:02 zira kernel: smpboot: CPU 1 is now offline
May 20 09:17:02 zira kernel: smpboot: CPU 2 is now offline
May 20 09:17:02 zira kernel: smpboot: CPU 3 is now offline
May 20 09:17:02 zira kernel: smpboot: CPU 4 is now offline
May 20 09:17:02 zira kernel: smpboot: CPU 5 is now offline
May 20 09:17:02 zira kernel: smpboot: CPU 6 is now offline
May 20 09:17:02 zira kernel: smpboot: CPU 7 is now offline
May 20 09:17:02 zira kernel: ACPI: Low-level resume complete
May 20 09:17:02 zira kernel: ACPI: EC: EC started
May 20 09:17:02 zira kernel: PM: Restoring platform NVS memory
May 20 09:17:02 zira kernel: Enabling non-boot CPUs ...
May 20 09:17:02 zira kernel: x86: Booting SMP configuration:
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
May 20 09:17:02 zira kernel: CPU1 is up
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 2 APIC 0x2
May 20 09:17:02 zira kernel: CPU2 is up
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
May 20 09:17:02 zira kernel: CPU3 is up
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 4 APIC 0x4
May 20 09:17:02 zira kernel: CPU4 is up
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 5 APIC 0x5
May 20 09:17:02 zira kernel: CPU5 is up
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 6 APIC 0x6
May 20 09:17:02 zira kernel: CPU6 is up
May 20 09:17:02 zira kernel: smpboot: Booting Node 0 Processor 7 APIC 0x7
May 20 09:17:02 zira kernel: CPU7 is up
May 20 09:17:02 zira kernel: ACPI: Waking up from system sleep state S3
May 20 09:17:02 zira kernel: ACPI: EC: interrupt unblocked
May 20 09:17:02 zira kernel: iwlwifi 0000:3d:00.0: can't change power state from D3hot to D0 (config space inaccessible)
May 20 09:17:02 zira kernel: ACPI: EC: event unblocked
May 20 09:17:02 zira kernel: sd 0:0:0:0: [sda] Starting disk
May 20 09:17:02 zira kernel: snd_hda_intel 0000:01:00.1: azx_get_response timeout, switching to polling mode: last cmd=0x004f0900
May 20 09:17:02 zira kernel: usb 2-7: reset high-speed USB device number 4 using xhci_hcd
May 20 09:17:02 zira kernel: ata3: SATA link down (SStatus 0 SControl 300)
May 20 09:17:02 zira kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
May 20 09:17:02 zira kernel: ata4: SATA link down (SStatus 0 SControl 300)
May 20 09:17:02 zira kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
May 20 09:17:02 zira kernel: ata2.00: configured for UDMA/100
May 20 09:17:02 zira kernel: ata1.00: configured for UDMA/133
May 20 09:17:02 zira kernel: usb 2-12: reset full-speed USB device number 6 using xhci_hcd
May 20 09:17:02 zira kernel: usb 2-5: reset full-speed USB device number 2 using xhci_hcd
May 20 09:17:02 zira kernel: parport_pc 00:04: activated
May 20 09:17:02 zira kernel: tpm tpm0: tpm_try_transmit: send(): error -5
May 20 09:17:02 zira kernel: acpi LNXPOWER:01: Turning OFF
May 20 09:17:02 zira kernel: OOM killer enabled.
May 20 09:17:02 zira kernel: Restarting tasks ... 
May 20 09:17:02 zira kernel: acpi PNP0501:00: Still not present
May 20 09:17:02 zira kernel: pci_bus 0000:02: Allocating resources
May 20 09:17:02 zira kernel: pci_bus 0000:3b: Allocating resources
May 20 09:17:02 zira kernel: done.
May 20 09:17:02 zira kernel: pcieport 0000:3c:03.0: bridge window [io  0x1000-0x0fff] to [bus 5f] add_size 1000
May 20 09:17:02 zira kernel: pcieport 0000:3c:03.0: BAR 13: no space for [io  size 0x1000]
May 20 09:17:02 zira kernel: pcieport 0000:3c:03.0: BAR 13: failed to assign [io  size 0x1000]
May 20 09:17:02 zira kernel: pcieport 0000:3c:03.0: BAR 13: no space for [io  size 0x1000]
May 20 09:17:02 zira kernel: pcieport 0000:3c:03.0: BAR 13: failed to assign [io  size 0x1000]
May 20 09:17:02 zira acpid[757]: client 1319[0:0] has disconnected
May 20 09:17:02 zira systemd-logind[785]: Lid opened.
May 20 09:17:02 zira bluetoothd[808]: Endpoint unregistered: sender=:1.40 path=/MediaEndpoint/A2DPSink/sbc
May 20 09:17:02 zira systemd[1]: Starting Load/Save RF Kill Switch Status...
May 20 09:17:02 zira bluetoothd[808]: Endpoint unregistered: sender=:1.40 path=/MediaEndpoint/A2DPSource/sbc
May 20 09:17:02 zira systemd[1]: Stopped target Bluetooth.
May 20 09:17:02 zira systemd[1]: Started Load/Save RF Kill Switch Status.
May 20 09:17:02 zira kernel: video LNXVIDEO:00: Restoring backlight state
May 20 09:17:02 zira systemd-sleep[200774]: System resumed.
May 20 09:17:02 zira kernel: PM: suspend exit
May 20 09:17:02 zira systemd[1]: Started Atop advanced performance monitor.
May 20 09:17:02 zira systemd[1]: systemd-suspend.service: Succeeded.
May 20 09:17:02 zira systemd[1]: Finished Suspend.
May 20 09:17:02 zira systemd[1]: Stopped target Sleep.
May 20 09:17:02 zira systemd[1]: Reached target Suspend.
May 20 09:17:02 zira systemd[1]: Stopped target Suspend.
May 20 09:17:02 zira systemd-logind[785]: Operation 'sleep' finished.
May 20 09:17:02 zira rtkit-daemon[780]: Supervising 3 threads of 1 processes of 1 users.
May 20 09:17:02 zira rtkit-daemon[780]: Successfully made thread 200906 of process 7921 owned by '1000' RT at priority 5.
May 20 09:17:02 zira rtkit-daemon[780]: Supervising 4 threads of 1 processes of 1 users.
May 20 09:17:02 zira acpid[757]: client connected from 200781[0:0]
May 20 09:17:02 zira acpid[757]: 1 client rule loaded
May 20 09:17:03 zira kernel: psmouse serio3: synaptics: queried max coordinates: x [..5660], y [..4730]
May 20 09:17:03 zira kernel: psmouse serio3: synaptics: queried min coordinates: x [1324..], y [1248..]
May 20 09:17:03 zira systemd[7815]: Reached target Bluetooth.
May 20 09:17:03 zira systemd[1]: Reached target Bluetooth.
May 20 09:17:03 zira kernel: Bluetooth: hci0: read Intel version: 370710018002030d00
May 20 09:17:03 zira kernel: Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
May 20 09:17:03 zira kernel: Bluetooth: hci0: unexpected event for opcode 0xfc2f
May 20 09:17:03 zira kernel: Bluetooth: hci0: Intel firmware patch completed and activated
May 20 09:17:03 zira bluetoothd[808]: Sap driver initialization failed.
May 20 09:17:03 zira bluetoothd[808]: sap-server: Operation not permitted (1)
May 20 09:17:03 zira bluetoothd[808]: Endpoint registered: sender=:1.40 path=/MediaEndpoint/A2DPSink/sbc
May 20 09:17:03 zira bluetoothd[808]: Endpoint registered: sender=:1.40 path=/MediaEndpoint/A2DPSource/sbc
May 20 09:17:04 zira lightdm[200915]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
May 20 09:17:04 zira lightdm[200915]: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0)
May 20 09:17:04 zira systemd[1]: Created slice User Slice of UID 116.
May 20 09:17:04 zira systemd[1]: Starting User Runtime Directory /run/user/116...
May 20 09:17:04 zira systemd-logind[785]: New session c2 of user lightdm.
May 20 09:17:04 zira systemd[1]: Finished User Runtime Directory /run/user/116.
May 20 09:17:04 zira systemd[1]: Starting User Manager for UID 116...
May 20 09:17:04 zira systemd[200919]: pam_unix(systemd-user:session): session opened for user lightdm by (uid=0)
May 20 09:17:05 zira systemd[200924]: gpgconf: error running '/usr/lib/gnupg/scdaemon': probably not installed
May 20 09:17:05 zira systemd[200919]: Reached target Paths.
May 20 09:17:05 zira systemd[200919]: Reached target Timers.
May 20 09:17:05 zira systemd[200919]: Starting D-Bus User Message Bus Socket.
May 20 09:17:05 zira systemd[200919]: Listening on GnuPG network certificate management daemon.
May 20 09:17:05 zira systemd[200919]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 20 09:17:05 zira systemd[200919]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
May 20 09:17:05 zira systemd[200919]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
May 20 09:17:05 zira systemd[200919]: Listening on GnuPG cryptographic agent and passphrase cache.
May 20 09:17:05 zira systemd[200919]: Listening on Sound System.
May 20 09:17:05 zira systemd[200919]: Listening on D-Bus User Message Bus Socket.
May 20 09:17:05 zira systemd[200919]: Reached target Sockets.
May 20 09:17:05 zira systemd[200919]: Reached target Basic System.
May 20 09:17:05 zira systemd[1]: Started User Manager for UID 116.
May 20 09:17:05 zira systemd[200919]: Starting Sound Service...
May 20 09:17:05 zira systemd[1]: Started Session c2 of user lightdm.
May 20 09:17:05 zira systemd[200919]: Started D-Bus User Message Bus.
May 20 09:17:05 zira dbus-daemon[200944]: [session uid=116 pid=200944] Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service' requested by ':1.1' (uid=116 pid=200941 comm="/usr/sbin/lightdm-gtk-greeter ")
May 20 09:17:05 zira systemd[200919]: Starting Accessibility services bus...
May 20 09:17:05 zira dbus-daemon[200944]: [session uid=116 pid=200944] Successfully activated service 'org.a11y.Bus'
May 20 09:17:05 zira systemd[200919]: Started Accessibility services bus.
May 20 09:17:05 zira dbus-daemon[200944]: [session uid=116 pid=200944] Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service' requested by ':1.3' (uid=116 pid=200941 comm="/usr/sbin/lightdm-gtk-greeter ")
May 20 09:17:05 zira systemd[200919]: Starting Virtual filesystem service...
May 20 09:17:05 zira dbus-daemon[200944]: [session uid=116 pid=200944] Successfully activated service 'org.gtk.vfs.Daemon'
May 20 09:17:05 zira systemd[200919]: Started Virtual filesystem service.
May 20 09:17:05 zira rtkit-daemon[780]: Successfully made thread 200939 of process 200939 owned by '116' high priority at nice level -11.
May 20 09:17:05 zira rtkit-daemon[780]: Supervising 4 threads of 2 processes of 2 users.
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira kernel: snd_hda_intel 0000:01:00.1: spurious response 0x80000000:0x0, last cmd=0x7f0900
May 20 09:17:05 zira at-spi-bus-launcher[200950]: dbus-daemon[200950]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=116 pid=200941 comm="/usr/sbin/lightdm-gtk-greeter ")
May 20 09:17:05 zira lightdm[200963]: pam_unix(lightdm:auth): Couldn't open /etc/securetty: No such file or directory
May 20 09:17:05 zira at-spi-bus-launcher[200950]: dbus-daemon[200950]: Successfully activated service 'org.a11y.atspi.Registry'
May 20 09:17:05 zira at-spi-bus-launcher[200966]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
May 20 09:17:06 zira netplugd[1026]: eth0: state ACTIVE flags 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000 -> 0x00001003 UP,BROADCAST,MULTICAST
May 20 09:17:06 zira netplugd[200970]: /etc/netplug/netplug eth0 out -> pid 200970
May 20 09:17:06 zira logger[200971]: netplug out: /sbin/ifdown -v eth0
May 20 09:17:06 zira ifupdown[200975]: IFACE=eth0 ADDRFAM=inet METHOD=dhcp PHASE=pre-down
May 20 09:17:06 zira systemd[1]: Reloading Postfix Mail Transport Agent (instance -).
May 20 09:17:06 zira postfix[200992]: Postfix is running with backwards-compatible default settings
May 20 09:17:06 zira postfix[200992]: See http://www.postfix.org/COMPATIBILITY_README.html for details
May 20 09:17:06 zira postfix[200992]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
May 20 09:17:06 zira postfix/postfix-script[200998]: refreshing the Postfix mail system
May 20 09:17:06 zira postfix/master[1320]: reload -- version 3.5.1, configuration /etc/postfix
May 20 09:17:06 zira systemd[1]: Reloaded Postfix Mail Transport Agent (instance -).
May 20 09:17:06 zira systemd[1]: Reloading Postfix Mail Transport Agent.
May 20 09:17:06 zira systemd[1]: Reloaded Postfix Mail Transport Agent.
May 20 09:17:06 zira dhclient[201007]: Killed old client process
May 20 09:17:06 zira netplugd[1026]: eth0: state OUTING flags 0x00001003 UP,BROADCAST,MULTICAST -> 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000
May 20 09:17:06 zira kernel: e1000e 0000:00:19.0 eth0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
May 20 09:17:07 zira rtkit-daemon[780]: Supervising 4 threads of 2 processes of 2 users.
May 20 09:17:07 zira rtkit-daemon[780]: Successfully made thread 201012 of process 7921 owned by '1000' RT at priority 5.
May 20 09:17:07 zira rtkit-daemon[780]: Supervising 5 threads of 2 processes of 2 users.
May 20 09:17:07 zira dhclient[201007]: Internet Systems Consortium DHCP Client 4.4.1
May 20 09:17:07 zira dhclient[201007]: Copyright 2004-2018 Internet Systems Consortium.
May 20 09:17:07 zira dhclient[201007]: All rights reserved.
May 20 09:17:07 zira dhclient[201007]: For info, please visit https://www.isc.org/software/dhcp/
May 20 09:17:07 zira dhclient[201007]: 
May 20 09:17:07 zira dhclient[201007]: Listening on LPF/eth0/30:8d:99:25:ad:3f
May 20 09:17:07 zira dhclient[201007]: Sending on   LPF/eth0/30:8d:99:25:ad:3f
May 20 09:17:07 zira dhclient[201007]: Sending on   Socket/fallback
May 20 09:17:07 zira dhclient[201007]: DHCPRELEASE of 192.168.1.3 on eth0 to 192.168.1.1 port 67
May 20 09:17:07 zira root[201020]: /etc/dhcp/dhclient-enter-hooks.d/google-tcp-dns with reason=RELEASE
May 20 09:17:07 zira avahi-daemon[762]: Withdrawing address record for 192.168.1.3 on eth0.
May 20 09:17:07 zira avahi-daemon[762]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.3.
May 20 09:17:07 zira avahi-daemon[762]: Interface eth0.IPv4 no longer relevant for mDNS.
May 20 09:17:07 zira root[201023]: /etc/dhcp/dhclient-exit-hooks.d/0google-tcp-dns with reason=RELEASE
May 20 09:17:07 zira systemd[1]: Stopping Network Time Synchronization...
May 20 09:17:07 zira systemd[1]: systemd-timesyncd.service: Succeeded.
May 20 09:17:07 zira systemd[1]: Stopped Network Time Synchronization.
May 20 09:17:07 zira systemd[1]: Starting Network Time Synchronization...
May 20 09:17:07 zira systemd[1]: Started Network Time Synchronization.
May 20 09:17:07 zira rtkit-daemon[780]: Supervising 5 threads of 2 processes of 2 users.
May 20 09:17:07 zira rtkit-daemon[780]: Successfully made thread 201037 of process 200939 owned by '116' RT at priority 5.
May 20 09:17:07 zira rtkit-daemon[780]: Supervising 6 threads of 2 processes of 2 users.
May 20 09:17:07 zira rtkit-daemon[780]: Supervising 6 threads of 2 processes of 2 users.
May 20 09:17:07 zira rtkit-daemon[780]: Successfully made thread 201038 of process 200939 owned by '116' RT at priority 5.
May 20 09:17:07 zira rtkit-daemon[780]: Supervising 7 threads of 2 processes of 2 users.
May 20 09:17:07 zira systemd[200919]: Started Sound Service.
May 20 09:17:07 zira systemd[200919]: Reached target Main User Target.
May 20 09:17:07 zira systemd[200919]: Startup finished in 2.573s.
May 20 09:17:07 zira bluetoothd[808]: Endpoint registered: sender=:1.67 path=/MediaEndpoint/A2DPSink/sbc
May 20 09:17:07 zira bluetoothd[808]: Endpoint registered: sender=:1.67 path=/MediaEndpoint/A2DPSource/sbc
May 20 09:17:07 zira bluetoothd[808]: RFCOMM server failed for Headset Voice gateway: rfcomm_bind: Address already in use (98)
May 20 09:17:07 zira bluetoothd[808]: RFCOMM server failed for :1.67/Profile/HSPHSProfile/00001108-0000-1000-8000-00805f9b34fb: rfcomm_bind: Address already in use (98)
May 20 09:17:07 zira netplugd[1026]: eth0: state OUTING flags 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000 -> 0x00001002 BROADCAST,MULTICAST
May 20 09:17:07 zira avahi-daemon[762]: Interface eth0.IPv6 no longer relevant for mDNS.
May 20 09:17:07 zira avahi-daemon[762]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::328d:99ff:fe25:ad3f.
May 20 09:17:07 zira avahi-daemon[762]: Withdrawing address record for fe80::328d:99ff:fe25:ad3f on eth0.
May 20 09:17:07 zira kernel: e1000e 0000:00:19.0 eth0: NIC Link is Down
May 20 09:17:07 zira ifupdown[201042]: IFACE=eth0 ADDRFAM=inet METHOD=dhcp PHASE=post-down
May 20 09:17:08 zira systemd[1]: systemd-rfkill.service: Succeeded.
May 20 09:17:09 zira inhibit-suspend[201061]: (vinc17) on-line: yes
May 20 09:17:09 zira inhibit-suspend[201066]: (vinc17) output: 3
May 20 09:17:11 zira lightdm[200963]: pam_unix(lightdm:auth): Couldn't open /etc/securetty: No such file or directory
May 20 09:17:11 zira lightdm[200963]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
May 20 09:17:12 zira netplugd[1026]: eth0: state DOWNANDOUT pid 200970 exited status 0
May 20 09:17:12 zira netplugd[201076]: /etc/netplug/netplug eth0 probe -> pid 201076
May 20 09:17:12 zira logger[201077]: netplug probe: /sbin/ip link set eth0 up
May 20 09:17:12 zira netplugd[1026]: eth0: state PROBING flags 0x00001002 BROADCAST,MULTICAST -> 0x00001003 UP,BROADCAST,MULTICAST
May 20 09:17:12 zira netplugd[1026]: eth0: state PROBING_UP pid 201076 exited status 0
May 20 09:17:13 zira systemd[1]: Stopping Session c2 of user lightdm.
May 20 09:17:13 zira lightdm[200915]: pam_unix(lightdm-greeter:session): session closed for user lightdm
May 20 09:17:13 zira systemd[1]: session-c2.scope: Succeeded.
May 20 09:17:13 zira systemd[1]: Stopped Session c2 of user lightdm.
May 20 09:17:13 zira systemd-logind[785]: Removed session c2.
May 20 09:17:13 zira bluetoothd[808]: Endpoint unregistered: sender=:1.67 path=/MediaEndpoint/A2DPSink/sbc
May 20 09:17:13 zira bluetoothd[808]: Endpoint unregistered: sender=:1.67 path=/MediaEndpoint/A2DPSource/sbc
May 20 09:17:13 zira systemd[200919]: pulseaudio.service: Succeeded.
May 20 09:17:13 zira acpid[757]: client 200781[0:0] has disconnected
May 20 09:17:13 zira acpid[757]: client connected from 1319[0:0]
May 20 09:17:13 zira acpid[757]: 1 client rule loaded
May 20 09:17:16 zira netplugd[1026]: eth0: state INACTIVE flags 0x00001003 UP,BROADCAST,MULTICAST -> 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000
May 20 09:17:16 zira netplugd[201080]: /etc/netplug/netplug eth0 in -> pid 201080
May 20 09:17:16 zira kernel: e1000e 0000:00:19.0 eth0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
May 20 09:17:16 zira kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
May 20 09:17:16 zira logger[201081]: netplug in: /sbin/ifup -v eth0
May 20 09:17:16 zira ifupdown[201086]: IFACE=eth0 ADDRFAM=inet METHOD=dhcp PHASE=pre-up
May 20 09:17:16 zira dhclient[201096]: Internet Systems Consortium DHCP Client 4.4.1
May 20 09:17:16 zira dhclient[201096]: Copyright 2004-2018 Internet Systems Consortium.
May 20 09:17:16 zira dhclient[201096]: All rights reserved.
May 20 09:17:16 zira dhclient[201096]: For info, please visit https://www.isc.org/software/dhcp/
May 20 09:17:16 zira dhclient[201096]: 
May 20 09:17:16 zira root[201107]: /etc/dhcp/dhclient-enter-hooks.d/google-tcp-dns with reason=PREINIT
May 20 09:17:16 zira root[201110]: /etc/dhcp/dhclient-exit-hooks.d/0google-tcp-dns with reason=PREINIT
May 20 09:17:16 zira dhclient[201096]: Listening on LPF/eth0/30:8d:99:25:ad:3f
May 20 09:17:16 zira dhclient[201096]: Sending on   LPF/eth0/30:8d:99:25:ad:3f
May 20 09:17:16 zira dhclient[201096]: Sending on   Socket/fallback
May 20 09:17:16 zira dhclient[201096]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 6
May 20 09:17:16 zira dhclient[201096]: DHCPOFFER of 192.168.1.3 from 192.168.1.1
May 20 09:17:16 zira dhclient[201096]: DHCPREQUEST for 192.168.1.3 on eth0 to 255.255.255.255 port 67
May 20 09:17:16 zira dhclient[201096]: DHCPACK of 192.168.1.3 from 192.168.1.1
May 20 09:17:16 zira root[201122]: /etc/dhcp/dhclient-enter-hooks.d/google-tcp-dns with reason=BOUND
May 20 09:17:16 zira CRON[201124]: pam_unix(cron:session): session opened for user root by (uid=0)
May 20 09:17:16 zira CRON[201125]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
May 20 09:17:16 zira CRON[201124]: pam_unix(cron:session): session closed for user root
May 20 09:17:17 zira avahi-daemon[762]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::328d:99ff:fe25:ad3f.
May 20 09:17:17 zira avahi-daemon[762]: New relevant interface eth0.IPv6 for mDNS.
May 20 09:17:17 zira avahi-daemon[762]: Registering new address record for fe80::328d:99ff:fe25:ad3f on eth0.*.
May 20 09:17:19 zira inhibit-suspend[201133]: (vinc17) on-line: yes
May 20 09:17:19 zira inhibit-suspend[201138]: (vinc17) output: 2
May 20 09:17:23 zira systemd[1]: Stopping User Manager for UID 116...
May 20 09:17:23 zira systemd[200919]: Stopped target Main User Target.
May 20 09:17:23 zira systemd[200919]: Stopping Accessibility services bus...
May 20 09:17:23 zira gvfsd[200952]: A connection to the bus can't be made
May 20 09:17:23 zira systemd[200919]: Stopping D-Bus User Message Bus...
May 20 09:17:23 zira systemd[200919]: Stopping Virtual filesystem service...
May 20 09:17:23 zira systemd[200919]: gvfs-daemon.service: Succeeded.
May 20 09:17:23 zira systemd[200919]: Stopped Virtual filesystem service.
May 20 09:17:23 zira systemd[200919]: dbus.service: Succeeded.
May 20 09:17:23 zira systemd[200919]: Stopped D-Bus User Message Bus.
May 20 09:17:23 zira systemd[200919]: at-spi-dbus-bus.service: Succeeded.
May 20 09:17:23 zira systemd[200919]: Stopped Accessibility services bus.
May 20 09:17:23 zira systemd[200919]: Stopped target Basic System.
May 20 09:17:23 zira systemd[200919]: Stopped target Paths.
May 20 09:17:23 zira systemd[200919]: Stopped target Sockets.
May 20 09:17:23 zira systemd[200919]: Stopped target Timers.
May 20 09:17:23 zira systemd[200919]: dbus.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed D-Bus User Message Bus Socket.
May 20 09:17:23 zira systemd[200919]: dirmngr.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed GnuPG network certificate management daemon.
May 20 09:17:23 zira systemd[200919]: gpg-agent-browser.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 20 09:17:23 zira systemd[200919]: gpg-agent-extra.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
May 20 09:17:23 zira systemd[200919]: gpg-agent-ssh.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed GnuPG cryptographic agent (ssh-agent emulation).
May 20 09:17:23 zira systemd[200919]: gpg-agent.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed GnuPG cryptographic agent and passphrase cache.
May 20 09:17:23 zira systemd[200919]: pulseaudio.socket: Succeeded.
May 20 09:17:23 zira systemd[200919]: Closed Sound System.
May 20 09:17:23 zira systemd[200919]: Reached target Shutdown.
May 20 09:17:23 zira systemd[200919]: systemd-exit.service: Succeeded.
May 20 09:17:23 zira systemd[200919]: Finished Exit the Session.
May 20 09:17:23 zira systemd[200919]: Reached target Exit the Session.
May 20 09:17:23 zira systemd[1]: user at 116.service: Succeeded.
May 20 09:17:23 zira systemd[1]: Stopped User Manager for UID 116.
May 20 09:17:23 zira systemd[1]: Stopping User Runtime Directory /run/user/116...
May 20 09:17:23 zira systemd[7815]: run-user-116.mount: Succeeded.
May 20 09:17:23 zira systemd[1]: run-user-116.mount: Succeeded.
May 20 09:17:23 zira systemd[1]: user-runtime-dir at 116.service: Succeeded.
May 20 09:17:23 zira systemd[1]: Stopped User Runtime Directory /run/user/116.
May 20 09:17:23 zira systemd[1]: Removed slice User Slice of UID 116.
May 20 09:17:26 zira avahi-daemon[762]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.3.
May 20 09:17:26 zira avahi-daemon[762]: New relevant interface eth0.IPv4 for mDNS.
May 20 09:17:26 zira avahi-daemon[762]: Registering new address record for 192.168.1.3 on eth0.IPv4.
May 20 09:17:26 zira root[201158]: /etc/dhcp/dhclient-exit-hooks.d/0google-tcp-dns with reason=BOUND
May 20 09:17:26 zira systemd[1]: Stopping Network Time Synchronization...
May 20 09:17:26 zira systemd[1]: systemd-timesyncd.service: Succeeded.
May 20 09:17:26 zira systemd[1]: Stopped Network Time Synchronization.
May 20 09:17:26 zira systemd[1]: Starting Network Time Synchronization...
May 20 09:17:26 zira systemd[1]: Started Network Time Synchronization.
May 20 09:17:27 zira systemd-timesyncd[201177]: Initial synchronization to time server 192.168.1.1:123 (192.168.1.1).
May 20 09:17:27 zira dhclient[201096]: bound to 192.168.1.3 -- renewal in 33916 seconds.
May 20 09:17:27 zira ifupdown[201184]: IFACE=eth0 ADDRFAM=inet METHOD=dhcp PHASE=post-up
May 20 09:17:27 zira systemd[1]: Reloading Postfix Mail Transport Agent (instance -).
May 20 09:17:27 zira postfix[201236]: Postfix is running with backwards-compatible default settings
May 20 09:17:27 zira postfix[201236]: See http://www.postfix.org/COMPATIBILITY_README.html for details
May 20 09:17:27 zira postfix[201236]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
May 20 09:17:27 zira postfix/postfix-script[201242]: refreshing the Postfix mail system
May 20 09:17:27 zira postfix/master[1320]: reload -- version 3.5.1, configuration /etc/postfix
May 20 09:17:27 zira systemd[1]: Reloaded Postfix Mail Transport Agent (instance -).
May 20 09:17:27 zira systemd[1]: Reloading Postfix Mail Transport Agent.
May 20 09:17:27 zira systemd[1]: Reloaded Postfix Mail Transport Agent.
May 20 09:17:27 zira home_net[201254]: (root) homenet = yes
May 20 09:17:27 zira home_net[201254]: (root) eth0 speed: 1000Mb/s
May 20 09:17:27 zira netplugd[1026]: eth0: state INNING pid 201080 exited status 0
May 20 09:17:30 zira inhibit-suspend[201261]: (vinc17) on-line: yes
May 20 09:17:30 zira inhibit-suspend[201266]: (vinc17) output: 2
May 20 09:17:40 zira inhibit-suspend[201274]: (vinc17) on-line: yes
May 20 09:17:40 zira inhibit-suspend[201279]: (vinc17) output: 2
May 20 09:17:50 zira inhibit-suspend[201287]: (vinc17) on-line: yes
May 20 09:17:50 zira inhibit-suspend[201292]: (vinc17) output: 2
[...]

The "output: 2" instead of "output: 3" is due to the fact that after
the suspend/resume, the screen connected via the Thunderbolt port is
no longer connected. I need to switch it off and on again.

Concerning the systemd-inhibit locks:

$ systemd-inhibit --list --no-pager
WHO           UID  USER   PID   COMM            WHAT              WHY                               MODE
Screen Locker 1000 vinc17 8681  light-locker    sleep             Lock the screen on suspend/resume delay
vinc17        1000 vinc17 13956 systemd-inhibit handle-lid-switch power supply or external output   block

2 inhibitors listed.

$ ps -fwwC systemd-inhibit
UID          PID    PPID  C STIME TTY          TIME CMD
vinc17     13956    8856  0 02:36 pts/3    00:00:00 systemd-inhibit --what=handle-lid-switch --who=vinc17 --why=power supply or external output --mode=block /home/vinc17/wd/src/scripts/inhibit-suspend 10 log +

-- Package-specific info:

-- System Information:
Debian Release: bullseye/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'stable-updates'), (500, 'unstable'), (500, 'testing'), (500, 'stable'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 5.6.0-1-amd64 (SMP w/8 CPU cores)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=POSIX, LC_CTYPE=C.UTF-8 (charmap=UTF-8), LANGUAGE=POSIX (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages systemd depends on:
ii  adduser                          3.118
ii  libacl1                          2.2.53-8
ii  libapparmor1                     2.13.4-1+b1
ii  libaudit1                        1:2.8.5-3+b1
ii  libblkid1                        2.35.1-5
ii  libc6                            2.30-8
ii  libcap2                          1:2.34-2
ii  libcrypt1                        1:4.4.16-1
ii  libcryptsetup12                  2:2.3.2-1
ii  libgcrypt20                      1.8.5-5
ii  libgnutls30                      3.6.13-2
ii  libgpg-error0                    1.37-1
ii  libidn2-0                        2.3.0-1
ii  libip4tc2                        1.8.4-3
ii  libkmod2                         27+20200310-2
ii  liblz4-1                         1.9.2-2
ii  liblzma5                         5.2.4-1+b1
ii  libmount1                        2.35.1-5
ii  libpam0g                         1.3.1-5
ii  libpcre2-8-0                     10.34-7
ii  libseccomp2                      2.4.3-1+b1
ii  libselinux1                      3.0-1+b3
ii  libsystemd0                      245.5-2
ii  mount                            2.35.1-5
ii  systemd-timesyncd [time-daemon]  245.5-2
ii  util-linux                       2.35.1-5

Versions of packages systemd recommends:
ii  dbus  1.12.16-2

Versions of packages systemd suggests:
ii  policykit-1        0.105-26
pn  systemd-container  <none>

Versions of packages systemd is related to:
pn  dracut           <none>
ii  initramfs-tools  0.137
ii  libnss-systemd   245.5-2
ii  libpam-systemd   245.5-2
ii  udev             245.5-2

-- Configuration Files:
/etc/systemd/journald.conf changed:
[Journal]
Storage=persistent

/etc/systemd/logind.conf changed:
[Login]
HandlePowerKey=ignore

/etc/systemd/system.conf changed:
[Manager]
DefaultTimeoutStopSec=20s


-- no debconf information

-- 
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)



More information about the Pkg-systemd-maintainers mailing list