[systemd-devel] Why is my docked idle laptop suspended?

[Michal Sojka]

On Fri, Aug 14 2015, Lennart Poettering wrote:
> On Thu, 13.08.15 22:53, Michal Sojka (sojkam1 at fel.cvut.cz) wrote:
>
>> Hi list,
>>
>> I'm trying to figure out why is my laptop automatically suspended after
>> being idle in a docking station. As far as I understand, logind should
>> not suspend when the laptop is docked or external monitor is connected.
>>
>> Below is the (partially filtered) system log of what happens before the
>> suspend. Things start at 17:34:09 when my screensaver sets IdleHint. Few
>> minutes later (17:37) something happens and the logind suspends the
>> system. I don't expect that network manager, active at the same time,
>> can cause this.
>>
>> When looking at function manager_is_docked_or_external_displays(), when
>> my system is docked, I should see "System is docked." message, but
>> instead I see "External (1) displays connected." Can it be that the
>> monitor powers down automatically and logind suspends the system because
>> it is not aware of being docked?
>
> Note that systemd will print "System is docked" only if there's an
> actual "docking" state known, i.e. via some input device that is
> connected to the hinge of your laptop. Most laptops don't expose
> this. In that case we count external displays, and then you only see
> the "External displays connected" message, instead.
>
> Which version of systemd are you running?

The one from Debian unstable
$ systemd --version
systemd 224
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN

> Maybe some other usperspace service is triggering the suspend?

Currently I suspect NetworkManager for triggering suspend. See the logs
below. I have minimalist session with i3 window manager and xss-lock.

>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Got message type=method_call sender=:1.39 destination=:1.224 object=/org/freedesktop/login1/session/_32 interface=org.freedesktop.login1.Session member=SetIdleHint cookie=34 reply_cookie=0 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=3105 reply_cookie=0 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.224 object=n/a interface=n/a member=n/a cookie=2170 reply_cookie=3105 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1/session/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=3106 reply_cookie=0 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=3107 reply_cookie=0 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1/user/_1000 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=3108 reply_cookie=0 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=3109 reply_cookie=0 error=n/a
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: device-enumerator: scan all dirs
>> Aug 13 17:34:09 steelpick systemd-logind[16201]:   device-enumerator: scanning /sys/bus
>> Aug 13 17:34:09 steelpick systemd-logind[16201]:   device-enumerator: scanning /sys/class
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: External (1) displays connected.
>> Aug 13 17:34:09 steelpick systemd-logind[16201]: Refusing operation, as it is turned off.
>> ...
>
> I'd would be nice to see what's going on here...

Only this:

Aug 13 17:37:48 steelpick dhclient[22949]: DHCPREQUEST on wlan0 to 147.32.208.3 port 67
Aug 13 17:37:48 steelpick dhclient[22949]: DHCPACK from 147.32.208.3
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    address 147.32.219.249
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    plen 22 (255.255.252.0)
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    gateway 147.32.216.1
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    server identifier 147.32.208.3
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    lease time 600
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    nameserver '147.32.192.2'
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    nameserver '147.32.192.3'
Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>    domain name 'feld.cvut.cz'

>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>  (wlan0): DHCPv4 state changed bound -> bound
>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <warn>  (wlan0): Lowering IPv6 MTU (1280) to match device MTU (0)
>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <warn>  (wlan0): IPv6 MTU (0) smaller than 1280, adjusting
>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <warn>  (wlan0): Raising device MTU (0) to match IPv6 MTU (1280)
>> Aug 13 17:37:48 steelpick dbus[1307]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
>> Aug 13 17:37:48 steelpick dhclient[22949]: bound to 147.32.219.249 -- renewal in 261 seconds.
>> Aug 13 17:37:48 steelpick systemd[1]: Starting Network Manager Script Dispatcher Service...
>> Aug 13 17:37:48 steelpick systemd-logind[16201]: Got message type=signal sender=:1.0 destination=n/a object=/org/freedesktop/systemd1/unit/NetworkManager_2ddispatcher_2eservice interface=org.freedesktop.DBus.Properties member=P
>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>  sleep requested (sleeping: no  enabled: yes)
>> Aug 13 17:37:48 steelpick systemd-logind[16201]: device-enumerator: scan all dirs
>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>  sleeping...
>> Aug 13 17:37:48 steelpick systemd-logind[16201]:   device-enumerator: scanning /sys/bus
>> Aug 13 17:37:48 steelpick NetworkManager[1420]: <info>  (wlan0): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37]
>> Aug 13 17:37:48 steelpick systemd-logind[16201]:   device-enumerator: scanning /sys/class
>> Aug 13 17:37:48 steelpick systemd-logind[16201]: Failed to open configuration file '/etc/systemd/sleep.conf': No such file or directory
>> Aug 13 17:37:48 steelpick systemd-logind[16201]: Suspending...
>> ...

I tried to figure out what's going on here. I was not able to reproduce
this without NetworkManager running. Also it seems that the external
monitor must be switched off (I used "xset dpms 10 10 10"), but I'm not
sure - it never suspended with monitor switched on.

It seems that the system suspends when there is the following line in
the log: "NetworkManager ... DHCPv4 state changed bound -> bound". See
more recent log, which is very similar to the one above.

Aug 17 14:41:17 steelpick systemd-logind[1535]: Got message type=method_call sender=:1.150 destination=:1.7 object=/org/freedesktop/login1/session/_366 interface=org.freedesktop.login1.Session member=SetIdleHint cookie=11 reply_cookie=0 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=457 reply_cookie=0 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.7 object=n/a interface=n/a member=n/a cookie=110 reply_cookie=457 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1/session/_366 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=458 reply_cookie=0 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=459 reply_cookie=0 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1/user/_1000 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=460 reply_cookie=0 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=461 reply_cookie=0 error=n/a
Aug 17 14:41:17 steelpick systemd-logind[1535]: device-enumerator: scan all dirs
Aug 17 14:41:17 steelpick systemd-logind[1535]:   device-enumerator: scanning /sys/bus
Aug 17 14:41:17 steelpick systemd-logind[1535]:   device-enumerator: scanning /sys/class
Aug 17 14:41:17 steelpick systemd-logind[1535]: External (1) displays connected.
Aug 17 14:41:17 steelpick systemd-logind[1535]: Refusing operation, as it is turned off.
Aug 17 14:41:18 steelpick avahi-daemon[1285]: Invalid response packet from host 147.32.86.132.
[...]
Aug 17 14:43:10 steelpick avahi-daemon[1285]: Invalid response packet from host 147.32.86.132.
Aug 17 14:43:11 steelpick dhclient[19735]: DHCPREQUEST on wlan0 to 147.32.208.3 port 67
Aug 17 14:43:11 steelpick dhclient[19735]: DHCPACK from 147.32.208.3
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    address 147.32.219.249
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    plen 22 (255.255.252.0)
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    gateway 147.32.216.1
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    server identifier 147.32.208.3
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    lease time 600
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    nameserver '147.32.192.2'
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    nameserver '147.32.192.3'
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>    domain name 'feld.cvut.cz'
Aug 17 14:43:11 steelpick NetworkManager[1183]: <info>  (wlan0): DHCPv4 state changed bound -> bound
Aug 17 14:43:11 steelpick NetworkManager[1183]: <warn>  (wlan0): Lowering IPv6 MTU (1280) to match device MTU (0)
Aug 17 14:43:11 steelpick NetworkManager[1183]: <warn>  (wlan0): IPv6 MTU (0) smaller than 1280, adjusting
Aug 17 14:43:11 steelpick NetworkManager[1183]: <warn>  (wlan0): Raising device MTU (0) to match IPv6 MTU (1280)
Aug 17 14:43:11 steelpick dhclient[19735]: bound to 147.32.219.249 -- renewal in 226 seconds.
Aug 17 14:43:11 steelpick dbus[1344]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Aug 17 14:43:11 steelpick systemd[1]: Starting Network Manager Script Dispatcher Service...
Aug 17 14:43:11 steelpick systemd-logind[1535]: Got message type=signal sender=:1.0 destination=n/a object=/org/freedesktop/systemd1/unit/NetworkManager_2ddispatcher_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1089 reply_cookie=0 error=n/a
Aug 17 14:43:11 steelpick systemd-logind[1535]: device-enumerator: scan all dirs
Aug 17 14:43:11 steelpick systemd-logind[1535]:   device-enumerator: scanning /sys/bus
Aug 17 14:43:11 steelpick systemd-logind[1535]:   device-enumerator: scanning /sys/class
Aug 17 14:43:11 steelpick systemd-logind[1535]: Failed to open configuration file '/etc/systemd/sleep.conf': No such file or directory
Aug 17 14:43:11 steelpick systemd-logind[1535]: Suspending...

-Michal