spontaneous wake-up from suspend

titaniumbones · 2016-09-07 18:08:38

I run Arch/GNOME on a Thi8nkpad T440s. Among other issues, I'm pretty sure the lid sensor is over-sensitive, perhaps crimped in the laptop hinge; changing the screen angle used to trigger a suspend event until I turned off suspend-on-lid-close in both GNOME and /etc/systemd/logind.conf. I've also now removed the small magnet from the case (proximity to the magnet is what triggers the sensor).

I now trigger suspend manually by pressing the suspend key (fn + 4 on my laptop). I'm finding now that the laptop almost always resumes spontaneously after a few minutes. I suspect, but can't prove, that this is caused by a lid-open event, something which occurs even though I've removed the magnet. So, I guess my questions are:

1 -- am I reading the logs right? (see the long-ish journalctl snipped pasted in, with some commentary, below)
2 -- if I've diagnosed the problem right, can anyone think of a workaround?

Thanks a bunch!

Journalctl output from the suspend-key event into the early stages of resuming:

First, the successful suspend event:

-- Logs begin at Mon 2014-07-07 16:45:03 EDT, end at Wed 2016-09-07 13:47:35 EDT. --
Sep 07 12:10:58 osskil systemd-logind[643]: Suspend key pressed.
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.3232] manager: sleep requested (sleeping: no  enabled: yes)
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.3232] manager: sleeping...
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.3233] manager: NetworkManager state is now ASLEEP
Sep 07 12:10:58 osskil dbus[645]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.3265] device (wlp3s0): state change: activated -> deactivating (reason 'sleeping') [100 110 37]
Sep 07 12:10:58 osskil systemd[1]: Starting Network Manager Script Dispatcher Service...
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.3460] device (wlp3s0): state change: deactivating -> disconnected (reason 'sleeping') [110 30 37]
Sep 07 12:10:58 osskil avahi-daemon[644]: Withdrawing address record for fe80::8a71:9a10:2fce:86a3 on wlp3s0.
Sep 07 12:10:58 osskil avahi-daemon[644]: Leaving mDNS multicast group on interface wlp3s0.IPv6 with address fe80::8a71:9a10:2fce:86a3.
Sep 07 12:10:58 osskil avahi-daemon[644]: Interface wlp3s0.IPv6 no longer relevant for mDNS.
Sep 07 12:10:58 osskil gvfsd[1175]: ** (process:15132): WARNING **: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Sep 07 12:10:58 osskil dbus[645]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Sep 07 12:10:58 osskil systemd[1]: Started Network Manager Script Dispatcher Service.
Sep 07 12:10:58 osskil nm-dispatcher[18048]: req:1 'connectivity-change': new request (0 scripts)
Sep 07 12:10:58 osskil nm-dispatcher[18048]: req:1 'connectivity-change': completed: no scripts
Sep 07 12:10:58 osskil org.gnome.Shell.desktop[725]: Window manager warning: Failed to set power save mode for output eDP37: Permission denied
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4108] dhcp4 (wlp3s0): canceled DHCP transaction, DHCP client pid 17687
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4108] dhcp4 (wlp3s0): state changed bound -> done
Sep 07 12:10:58 osskil kernel: wlp3s0: deauthenticating from e8:40:f2:4c:0a:d5 by local choice (Reason: 3=DEAUTH_LEAVING)
Sep 07 12:10:58 osskil wpa_supplicant[753]: wlp3s0: CTRL-EVENT-DISCONNECTED bssid=e8:40:f2:4c:0a:d5 reason=3 locally_generated=1
Sep 07 12:10:58 osskil avahi-daemon[644]: Withdrawing address record for 192.168.0.69 on wlp3s0.
Sep 07 12:10:58 osskil avahi-daemon[644]: Leaving mDNS multicast group on interface wlp3s0.IPv4 with address 192.168.0.69.
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4237] device (wlp3s0): set-hw-addr: set MAC address to AA:AE:EC:FE:C5:0E (scanning)
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4280] dns-mgr: Removing DNS information from /usr/bin/resolvconf
Sep 07 12:10:58 osskil kernel: IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready
Sep 07 12:10:58 osskil avahi-daemon[644]: Interface wlp3s0.IPv4 no longer relevant for mDNS.
Sep 07 12:10:58 osskil nm-dispatcher[18048]: req:2 'down' [wlp3s0]: new request (0 scripts)
Sep 07 12:10:58 osskil nm-dispatcher[18048]: req:2 'down' [wlp3s0]: completed: no scripts
Sep 07 12:10:58 osskil NetworkManager[14341]: <warn>  [1473264658.4686] sup-iface[0x239ee30,wlp3s0]: connection disconnected (reason -3)
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4694] device (wlp3s0): supplicant interface state: completed -> disconnected
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4704] device (wlp3s0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Sep 07 12:10:58 osskil NetworkManager[14341]: <info>  [1473264658.4808] device (wlp3s0): set-hw-addr: reset MAC address to 5C:51:4F:4E:17:95 (unmanage)
Sep 07 12:10:58 osskil wpa_supplicant[753]: nl80211: deinit ifname=p2p-dev-wlp3s0 disabled_11b_rates=0
Sep 07 12:10:58 osskil wpa_supplicant[753]: nl80211: deinit ifname=wlp3s0 disabled_11b_rates=0
Sep 07 12:10:59 osskil gvfsd[1175]: ** (process:15132): WARNING **: Couldn't create directory monitor on smb://x-gnome-default-workgroup/. Error: Operation not supported by backend
Sep 07 12:11:00 osskil systemd[1]: Reached target Sleep.
Sep 07 12:11:00 osskil systemd[1]: Starting Suspend...
Sep 07 12:11:00 osskil systemd-sleep[18102]: Suspending system...
Sep 07 12:11:00 osskil kernel: PM: Syncing filesystems ... done.
Sep 07 12:11:00 osskil kernel: PM: Preparing system for sleep (mem)

6 minutes later the logs start again, despite the fact that the laptop is being carried in my backpack, inside a laptop sleeve. Low-level resume first:

Sep 07 12:17:44 osskil kernel: Freezing user space processes ... (elapsed 0.002 seconds) done.
Sep 07 12:17:44 osskil kernel: Double checking all user space processes after OOM killer disable... (elapsed 0.000 seconds) 
Sep 07 12:17:44 osskil kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Sep 07 12:17:44 osskil kernel: PM: Suspending system (mem)
Sep 07 12:17:44 osskil kernel: Suspending console(s) (use no_console_suspend to debug)
Sep 07 12:17:44 osskil kernel: sd 1:0:0:0: [sdb] Synchronizing SCSI cache
Sep 07 12:17:44 osskil kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Sep 07 12:17:44 osskil kernel: sd 1:0:0:0: [sdb] Stopping disk
Sep 07 12:17:44 osskil kernel: sd 0:0:0:0: [sda] Stopping disk
Sep 07 12:17:44 osskil kernel: PM: suspend of devices complete after 1440.865 msecs
Sep 07 12:17:44 osskil kernel: PM: late suspend of devices complete after 21.462 msecs
Sep 07 12:17:44 osskil kernel: ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
Sep 07 12:17:44 osskil kernel: xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
Sep 07 12:17:44 osskil kernel: PM: noirq suspend of devices complete after 16.806 msecs
Sep 07 12:17:44 osskil kernel: ACPI: Preparing to enter system sleep state S3
Sep 07 12:17:44 osskil kernel: ACPI : EC: EC stopped
Sep 07 12:17:44 osskil kernel: PM: Saving platform NVS memory
Sep 07 12:17:44 osskil kernel: Disabling non-boot CPUs ...
Sep 07 12:17:44 osskil kernel: smpboot: CPU 1 is now offline
Sep 07 12:17:44 osskil kernel: smpboot: CPU 2 is now offline
Sep 07 12:17:44 osskil kernel: smpboot: CPU 3 is now offline
Sep 07 12:17:44 osskil kernel: ACPI: Low-level resume complete

Then a successful high-level resume:

Sep 07 12:17:44 osskil kernel: ACPI : EC: EC started
Sep 07 12:17:44 osskil kernel: PM: Restoring platform NVS memory
Sep 07 12:17:44 osskil kernel: Enabling non-boot CPUs ...
Sep 07 12:17:44 osskil kernel: x86: Booting SMP configuration:
Sep 07 12:17:44 osskil kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Sep 07 12:17:44 osskil kernel:  cache: parent cpu1 should not be sleeping
Sep 07 12:17:44 osskil kernel: CPU1 is up
Sep 07 12:17:44 osskil kernel: smpboot: Booting Node 0 Processor 2 APIC 0x2
Sep 07 12:17:44 osskil kernel:  cache: parent cpu2 should not be sleeping
Sep 07 12:17:44 osskil kernel: CPU2 is up
Sep 07 12:17:44 osskil kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
Sep 07 12:17:44 osskil kernel:  cache: parent cpu3 should not be sleeping
Sep 07 12:17:44 osskil kernel: CPU3 is up
Sep 07 12:17:44 osskil kernel: ACPI: Waking up from system sleep state S3
Sep 07 12:17:44 osskil kernel: acpi LNXPOWER:02: Turning OFF
Sep 07 12:17:44 osskil kernel: ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI
Sep 07 12:17:44 osskil kernel: xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
Sep 07 12:17:44 osskil kernel: PM: noirq resume of devices complete after 17.271 msecs
Sep 07 12:17:44 osskil kernel: PM: early resume of devices complete after 6.127 msecs
Sep 07 12:17:44 osskil kernel: usb usb1: root hub lost power or was reset
Sep 07 12:17:44 osskil kernel: usb usb2: root hub lost power or was reset
Sep 07 12:17:44 osskil kernel: rtc_cmos 00:02: System wakeup disabled by ACPI
Sep 07 12:17:44 osskil kernel: sd 1:0:0:0: [sdb] Starting disk
Sep 07 12:17:44 osskil kernel: sd 0:0:0:0: [sda] Starting disk
Sep 07 12:17:44 osskil kernel: usb 3-1: reset high-speed USB device number 2 using ehci-pci
Sep 07 12:17:44 osskil kernel: ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Sep 07 12:17:44 osskil kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Sep 07 12:17:44 osskil kernel: ata2.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata2.00: configured for UDMA/133
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata1.00: supports DRM functions and may not be fully accessible
Sep 07 12:17:44 osskil kernel: ata1.00: NCQ Send/Recv Log not supported
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Sep 07 12:17:44 osskil kernel: ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Sep 07 12:17:44 osskil kernel: ata1.00: supports DRM functions and may not be fully accessible
Sep 07 12:17:44 osskil kernel: ata1.00: NCQ Send/Recv Log not supported
Sep 07 12:17:44 osskil kernel: ata1.00: configured for UDMA/133
Sep 07 12:17:44 osskil kernel: psmouse serio1: synaptics: queried max coordinates: x [..5112], y [..3834]
Sep 07 12:17:44 osskil kernel: usb 1-7: reset full-speed USB device number 3 using xhci_hcd
Sep 07 12:17:44 osskil kernel: psmouse serio1: synaptics: queried min coordinates: x [1024..], y [1024..]
Sep 07 12:17:44 osskil kernel: psmouse serio1: synaptics: quirked min/max coordinates: x [1024..5112], y [2024..4832]
Sep 07 12:17:44 osskil kernel: usb 1-8: reset high-speed USB device number 4 using xhci_hcd
Sep 07 12:17:44 osskil kernel: usb 1-6: reset full-speed USB device number 2 using xhci_hcd
Sep 07 12:17:44 osskil kernel: PM: resume of devices complete after 1208.559 msecs
Sep 07 12:17:44 osskil kernel: usb 1-7:1.0: rebind failed: -517
Sep 07 12:17:44 osskil kernel: usb 1-7:1.1: rebind failed: -517
Sep 07 12:17:44 osskil kernel: PM: Finishing wakeup.
Sep 07 12:17:44 osskil kernel: Restarting tasks ... done.
Sep 07 12:17:44 osskil systemd[1]: Time has been changed

Then, post-resume, the system registers TONS of lid open/close events, followed by some messages about supend that dont look right to me:

Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd[695]: Time has been changed
Sep 07 12:17:44 osskil systemd[941]: Time has been changed
Sep 07 12:17:44 osskil systemd[1]: Starting Load/Save RF Kill Switch Status...
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid opened.
Sep 07 12:17:44 osskil kernel: Bluetooth: hci0: read Intel version: 370710018002030d00
Sep 07 12:17:44 osskil kernel: Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
Sep 07 12:17:44 osskil systemd-sleep[18102]: System resumed.
Sep 07 12:17:44 osskil systemd[1]: bluetooth.target: Unit not needed anymore. Stopping.
Sep 07 12:17:44 osskil systemd[1]: Stopped target Bluetooth.
Sep 07 12:17:44 osskil systemd[1]: Reached target Bluetooth.
Sep 07 12:17:44 osskil systemd[1]: Started Load/Save RF Kill Switch Status.
Sep 07 12:17:44 osskil systemd-logind[643]: Lid closed.
Sep 07 12:17:44 osskil systemd[1]: Started Atop advanced performance monitor.
Sep 07 12:17:44 osskil org.gnome.Shell.desktop[725]: Window manager warning: Failed to read EDID of output eDP37: No such file or directory
Sep 07 12:17:44 osskil systemd[1]: Started Suspend.
Sep 07 12:17:44 osskil systemd[1]: sleep.target: Unit not needed anymore. Stopping.
Sep 07 12:17:44 osskil systemd[1]: Stopped target Sleep.
Sep 07 12:17:44 osskil systemd[1]: Reached target Suspend.
Sep 07 12:17:44 osskil systemd[1]: suspend.target: Unit is bound to inactive unit systemd-suspend.service. Stopping, too.
Sep 07 12:17:44 osskil systemd[1]: Stopped target Suspend.
Sep 07 12:17:44 osskil systemd-logind[643]: Operation 'sleep' finished.
Sep 07 12:17:44 osskil NetworkManager[14341]: <info>  [1473265064.6354] manager: wake requested (sleeping: yes  enabled: yes)
Sep 07 12:17:44 osskil NetworkManager[14341]: <info>  [1473265064.6354] manager: waking up...
Sep 07 12:17:44 osskil NetworkManager[14341]: <info>  [1473265064.6355] device (enp0s25): state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
Sep 07 12:17:44 osskil org.gnome.Shell.desktop[725]: Window manager warning: Failed to set power save mode for output eDP37: Permission denied
Sep 07 12:17:44 osskil kernel: Process accounting resumed

----------------------

After this, the seqence:

Sep 07 12:44:34 osskil org.gnome.Shell.desktop[725]: Window manager warning: Failed to read EDID of output eDP37: No such file or directory
Sep 07 12:44:34 osskil systemd-logind[643]: Lid opened.
Sep 07 12:44:35 osskil systemd-logind[643]: Lid closed.

repeates itself over and over again, several hundred times, for about 30 minutes until I come back to the laptop and notice that it's on.

--------------------------------------------------------------------------------------------------
Thank you for your help! Much apreciated!

Last edited by titaniumbones (2016-09-07 18:27:26)

Trilby · 2016-09-07 18:18:13

You linked to the wrong thread. And you spammed a link to this issue in some other poor member's thread when it clearly has nothing to do with their thread.

I've deleted your spam post on their thread, and I've closed and binned your other post.

Do not post multiple threads for the same issue. Use the edit button.

You can practice now: edit your post and used code tags.

Then read our code of conduct from start to finish before posting again:
https://wiki.archlinux.org/index.php/Code_of_conduct

You've been around long enough to know better. And checking through your previous posts to see if you've been given such advice (or warnings) before, I don't see any - but I do see a history of abandoning threads. So please read twice over the "life is a 2-way street" section of the code of conduct.

titaniumbones · 2016-09-07 18:25:00

Thanks Trilby, and sorry for the errors. Will do as you suggest. I think part of the non-response issue was that I didn't have "Automatically subscribe to every topic you post in" checked and often missed responses; in any case, I appreciate the slap on the wrist and will endeavour to do better.

Last edited by titaniumbones (2016-09-07 18:39:52)

Arch Linux

#1 2016-09-07 18:08:38

spontaneous wake-up from suspend

#2 2016-09-07 18:18:13

Re: spontaneous wake-up from suspend

#3 2016-09-07 18:25:00

Re: spontaneous wake-up from suspend

Board footer