Immediate wake-up after suspend

Question

My Debian 9 system wakes up in 2-5 seconds after it enters into the sleep mode (suspend to RAM) manually or automatically. The problem always occurs no matter how the sleep mode is invoked: by lid closing, by power button, or from terminal. What could be the problem?

Here is system info:

$ sudo dmidecode | grep -A3 '^System Information'
System Information
    Manufacturer: LENOVO
    Product Name: 20ET004LGE
    Version: ThinkPad E460
$ uname -a
Linux 4.9.0-3-amd64 #1 SMP Debian 4.9.30-2+deb9u5 (2017-09-19) x86_64 GNU/Linux

To check which devices could cause a problem, I checked /proc/acpi/wakeup and then disabled every device temporarily by issuing echo DeviceName > /proc/acpi/wakeup, but the problem is still persisting. Here it is before I changed:

$ cat /proc/acpi/wakeup 
Device  S-state   Status   Sysfs node
LID   S4    *enabled   platform:PNP0C0D:00
SLPB      S3    *enabled   platform:PNP0C0E:00
IGBE      S4    *enabled   pci:0000:00:1f.6
PXSX      S4    *disabled
PXSX      S4    *disabled  pci:0000:01:00.0
PXSX      S4    *disabled  pci:0000:02:00.0
        *disabled  platform:rtsx_pci_sdmmc.0
        *disabled  platform:rtsx_pci_ms.0
XHCI      S3    *enabled   pci:0000:00:14.0

$ lspci
    00:00.0 Host bridge: Intel Corporation Skylake Host Bridge/DRAM Registers (rev 08)
    00:02.0 VGA compatible controller: Intel Corporation HD Graphics 520 (rev 07)
    00:14.0 USB controller: Intel Corporation Sunrise Point-LP USB 3.0 xHCI Controller (rev 21)
    00:14.2 Signal processing controller: Intel Corporation Sunrise Point-LP Thermal subsystem (rev 21)
    00:16.0 Communication controller: Intel Corporation Sunrise Point-LP CSME HECI #1 (rev 21)
    00:17.0 SATA controller: Intel Corporation Sunrise Point-LP SATA Controller [AHCI mode] (rev 21)
    00:1c.0 PCI bridge: Intel Corporation Device 9d12 (rev f1)
    00:1c.5 PCI bridge: Intel Corporation Sunrise Point-LP PCI Express Root Port #6 (rev f1)
    00:1f.0 ISA bridge: Intel Corporation Sunrise Point-LP LPC Controller (rev 21)
    00:1f.2 Memory controller: Intel Corporation Sunrise Point-LP PMC (rev 21)
    00:1f.3 Audio device: Intel Corporation Sunrise Point-LP HD Audio (rev 21)
    00:1f.4 SMBus: Intel Corporation Sunrise Point-LP SMBus (rev 21)
    00:1f.6 Ethernet controller: Intel Corporation Ethernet Connection I219-V (rev 21)
    01:00.0 Network controller: Intel Corporation Intel Dual Band Wireless-AC 3165 Plus Bluetooth (rev 99)
    02:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. RTS522A PCI Express Card Reader (rev 01)

And lastly here is the relevant part from dmesg, after I put the machine into sleep and it wakes up (without any modification to /proc/acpi/wakeup):

$ sudo dmesg
[ 2591.034943] wlp1s0: deauthenticating from a4:2b:b0:ab:e2:99 by local choice (Reason: 3=DEAUTH_LEAVING)
[ 2591.044024] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2593.048689] PM: Syncing filesystems ... done.
[ 2593.071217] PM: Preparing system for sleep (mem)
[ 2593.071490] (NULL device *): firmware: direct-loading firmware i915/skl_dmc_ver1_26.bin
[ 2593.071864] (NULL device *): firmware: direct-loading firmware iwlwifi-7265D-22.ucode
[ 2593.071880] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 2593.074134] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 2593.075457] PM: Suspending system (mem)
[ 2593.075519] Suspending console(s) (use no_console_suspend to debug)
[ 2593.075955] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 2593.077328] sd 0:0:0:0: [sda] Stopping disk
[ 2593.264951] ACPI : EC: event blocked
[ 2593.313967] PM: suspend of devices complete after 238.174 msecs
[ 2593.336883] PM: late suspend of devices complete after 22.910 msecs
[ 2593.337306] ACPI : EC: interrupt blocked
[ 2593.338237] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
[ 2593.378029] PM: noirq suspend of devices complete after 41.142 msecs
[ 2593.378652] ACPI: Preparing to enter system sleep state S3
[ 2593.399563] ACPI : EC: EC stopped
[ 2593.399564] PM: Saving platform NVS memory
[ 2593.399570] Disabling non-boot CPUs ...
[ 2593.400953] smpboot: CPU 1 is now offline
[ 2593.403402] smpboot: CPU 2 is now offline
[ 2593.405121] smpboot: CPU 3 is now offline
[ 2593.408016] ACPI: Low-level resume complete
[ 2593.408131] ACPI : EC: EC started
[ 2593.408131] PM: Restoring platform NVS memory
[ 2593.408865] Suspended for 3.452 seconds
[ 2593.410052] Enabling non-boot CPUs ...
[ 2593.410111] x86: Booting SMP configuration:
[ 2593.410111] smpboot: Booting Node 0 Processor 1 APIC 0x2
[ 2593.413738]  cache: parent cpu1 should not be sleeping
[ 2593.418428] CPU1 is up
[ 2593.418467] smpboot: Booting Node 0 Processor 2 APIC 0x1
[ 2593.421003]  cache: parent cpu2 should not be sleeping
[ 2593.425788] CPU2 is up
[ 2593.425826] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 2593.428373]  cache: parent cpu3 should not be sleeping
[ 2593.433092] CPU3 is up
[ 2593.436236] ACPI: Waking up from system sleep state S3
[ 2593.480811] ACPI : EC: interrupt unblocked
[ 2593.536245] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
[ 2593.536310] PM: noirq resume of devices complete after 55.607 msecs
[ 2593.541114] PM: early resume of devices complete after 4.771 msecs
[ 2593.541223] ACPI : EC: event unblocked
[ 2593.541548] iwlwifi 0000:01:00.0: RF_KILL bit toggled to enable radio.
[ 2593.542111] sd 0:0:0:0: [sda] Starting disk
[ 2593.542645] rtc_cmos 00:02: System wakeup disabled by ACPI
[ 2593.548069] [drm] GuC firmware load skipped
[ 2593.768567] usb 1-7: reset high-speed USB device number 2 using xhci_hcd
[ 2593.856890] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 2593.857497] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 2593.857500] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 2593.857545] ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
[ 2593.857767] ata1.00: supports DRM functions and may not be fully accessible
[ 2593.859546] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 2593.859548] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 2593.859591] ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
[ 2593.859806] ata1.00: supports DRM functions and may not be fully accessible
[ 2593.860711] ata1.00: configured for UDMA/133
[ 2594.130430] PM: resume of devices complete after 589.312 msecs
[ 2594.130711] PM: Finishing wakeup.
[ 2594.130712] Restarting tasks ... 
[ 2594.132323] [drm] RC6 on
[ 2594.133646] done.
[ 2594.754297] e1000e: enp0s31f6 NIC Link is Down
[ 2594.756068] IPv6: ADDRCONF(NETDEV_UP): enp0s31f6: link is not ready
[ 2594.969138] IPv6: ADDRCONF(NETDEV_UP): enp0s31f6: link is not ready
[ 2594.972566] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2594.974923] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2594.975229] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.043353] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.043657] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.064475] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2595.074769] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.075066] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.140447] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.140753] iwlwifi 0000:01:00.0: L1 Enabled - LTR Enabled
[ 2595.156361] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2595.237719] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2598.905323] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2598.986638] wlp1s0: authenticate with a4:2b:b0:ab:e2:99
[ 2598.990338] wlp1s0: send auth to a4:2b:b0:ab:e2:99 (try 1/3)
[ 2598.992121] wlp1s0: authenticated
[ 2598.996133] wlp1s0: associate with a4:2b:b0:ab:e2:99 (try 1/3)
[ 2598.999926] wlp1s0: RX AssocResp from a4:2b:b0:ab:e2:99 (capab=0x431 status=0 aid=1)
[ 2599.003864] wlp1s0: associated
[ 2599.003986] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready

Solution 1

I don't know if you ever got this problem resolved, but I had the same thing happening on Debian buster/sid on a ThinkPad T460. The output of my dmesg wasn't identical to yours, but importantly, it had the same

ACPI: EC: event blocked

line. Per this thread on AskUbuntu, I disabled XHCI as a wakeup trigger in /proc/acpi/wakeup:

$ grep enabled /proc/acpi/wakeup | cut -f 1
LID
SLPB
XHCI
$ sudo su
# echo XHCI > /proc/acpi/wakeup

and that fixed it for me. Oddly, this was only supposed to matter if you had USB devices plugged into the machine, but I most certainly did not.

---

EDIT: Never mind, I forgot about the part where you tried disabling every line in /proc/acpi/wakeup.

Solution 2

Problem solved. It was somehow the keyboard. One of my F keys was broken and I decided to test if this key was constantly sending input. Then I tested keyboard inputs in the terminal - no input was shown when I don't touch the keyboard. Although that was the case, when I replaced the keyboard with a new one, I could put the PC into sleep. It might be something related to Thinkpad BIOS I guess, because no matter what I tried in the OS, I could not see any keyboard input that might wake it up from sleep.

Comments

[Admin]

check your power settings in the settings menu, if your power manager service is stopped then this could be the default behavior built in to the driver.

[Admin]

Try booting with the break kernel parameter, and when you're dropped at the (initramfs) prompt, do echo mem >/sys/power/state to suspend your machine. If that works right, try finding the point which breaks it: for example acpid interacting with systemd-logind (boot with systemd.unit=rescue.target), with your display manager (boot with systemd.unit=multi-user.target) or with your desktop power manager (close your desktop environment).

[MakisH]

Because I was wondering: no restart is required after applying this change. For me, XHC was causing the problem (ThinkPad T470s, Ubuntu 16.04, kernel 4.15).