pop-os / pop

A project for managing all Pop!_OS sources
https://system76.com/pop
2.36k stars 81 forks source link

Intermittent complete freeze on unsuspend (or suspend?) with Thinkpad x1e gen 2 #794

Open kshepherd opened 4 years ago

kshepherd commented 4 years ago

Distribution (run cat /etc/os-release): NAME="Pop!_OS" VERSION="19.10" ID=ubuntu ID_LIKE=debian PRETTY_NAME="Pop!_OS 19.10" VERSION_ID="19.10" HOME_URL="https://system76.com/pop" SUPPORT_URL="http://support.system76.com" BUG_REPORT_URL="https://github.com/pop-os/pop/issues" PRIVACY_POLICY_URL="https://system76.com/privacy" VERSION_CODENAME=eoan UBUNTU_CODENAME=eoan LOGO=distributor-logo-pop-os

Related Application and/or Package Version (run apt policy $PACKAGE NAME): N/A

Issue/Bug Description: When taking laptop out of suspend (eg. opening lid if it was suspended while closed, or waking up with the power button if I manually suspended), the system will sometimes freeze.

I see the last few messages on the console (usually some wifi adaptor warnings), but other than that it is a full system freeze - capslock keys won't toggle, and the normally-blinking _ cursor is frozen. I have included some syslog clues at the end of the report. I'm not yet sure whether it's a case of freezing while attempting to wake up, or something going wrong when it is suspending. The logs do seem to indicate that in the failures, the suspension never really completes properly (although it's hard to tell with this sort of issue because some log writing is obviously paused, waiting to be written once the system is woken up)

I've seen similar reports for other Thinkpads or Lenovos but I thought I'd try to share some more info and logs here about my specific issue.

Steps to reproduce (if you know): Suspend the Thinkpad with the suspend menu option or by closing the lid and waiting for the configured sleep time. Wake the Thinkpad either by opening the lid if closed, or with a tap on the power button if already open.

Expected behavior: The system wakes up and the gnome session is resumed

Other Notes: I have copied in some snippets from syslog with some inline comments. Apologies if it is an annoyingly long paste. Happy to investigate further logs or look into system-sleep or system-suspend debugging if that will help

This first log snippet shows an example of the freezing / failing suspend. Log begins just as I have clicked the suspend button

Dec 21 12:13:31 pop-os gnome-shell[1848]: JS WARNING: [/usr/share/gnome-shell/extensions/pop-suspend-button@system76.com/extension.js 205]: assignment to undeclared variable gnomeShellVersion Dec 21 12:13:31 pop-os NetworkManager[1035]: [1576883611.8676] manager: sleep: sleep requested (sleeping: no enabled: yes) Dec 21 12:13:31 pop-os NetworkManager[1035]: [1576883611.8678] device (p2p-dev-wlp82s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-ifa ce-state: 'managed') Dec 21 12:13:31 pop-os NetworkManager[1035]: [1576883611.8682] manager: NetworkManager state is now ASLEEP Dec 21 12:13:32 pop-os kernel: [ 5040.887276] pcieport 0000:00:01.0: PME: Spurious native interrupt! Dec 21 12:13:36 pop-os systemd[1]: Reached target Sleep. Dec 21 12:13:36 pop-os systemd[1]: Starting Suspend... Dec 21 12:13:36 pop-os systemd-sleep[8175]: Suspending system... Dec 21 12:13:36 pop-os kernel: [ 5045.140268] PM: suspend entry (deep)

Here, presumably, is the crash. Nothing appears to have been logged when I pressed the button (though I do at least see the display wake up to show a TTY with some wifi log messages). And indeed, the systemd-sleep process doesn't appear to have actually ended? Or at least didn't get logged as such. As below, you can see I've now cold-restarted the system, so the next lines are startup logs from around 2 minutes later

Dec 21 12:15:30 pop-os mtp-probe: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-9" Dec 21 12:15:30 pop-os systemd-modules-load[496]: Inserted module 'lp' Dec 21 12:15:30 pop-os mtp-probe: checking bus 1, device 4: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-11" Dec 21 12:15:30 pop-os systemd-modules-load[496]: Inserted module 'ppdev' Dec 21 12:15:30 pop-os mtp-probe: checking bus 1, device 2: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-8" Dec 21 12:15:30 pop-os systemd-modules-load[496]: Inserted module 'parport_pc' Dec 21 12:15:30 pop-os mtp-probe: bus: 1, device: 2 was not an MTP device

The second log snippets below show a successful suspend and restart, again beginning at button click

Dec 21 12:23:35 pop-os gnome-shell[2094]: JS WARNING: [/usr/share/gnome-shell/extensions/pop-suspend-button@system76.com/extension.js 205]: assignment to undeclared variable gnomeShellVersion Dec 21 12:23:35 pop-os NetworkManager[1024]: [1576884215.9258] manager: sleep: sleep requested (sleeping: no enabled: yes) Dec 21 12:23:35 pop-os NetworkManager[1024]: [1576884215.9259] device (p2p-dev-wlp82s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-ifa ce-state: 'managed') Dec 21 12:23:35 pop-os NetworkManager[1024]: [1576884215.9263] manager: NetworkManager state is now ASLEEP Dec 21 12:23:36 pop-os systemd[1830]: tracker-extract.service: Succeeded. Dec 21 12:23:36 pop-os kernel: [ 490.667825] pcieport 0000:00:01.0: PME: Spurious native interrupt! Dec 21 12:23:40 pop-os systemd[1]: Reached target Sleep. Dec 21 12:23:40 pop-os systemd[1]: Starting Suspend... Dec 21 12:23:40 pop-os systemd-sleep[4295]: Suspending system... Dec 21 12:23:40 pop-os kernel: [ 494.685723] PM: suspend entry (deep) Dec 21 12:23:40 pop-os kernel: [ 494.689184] Filesystems sync: 0.003 seconds Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "39" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event2 - Power Button: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "42" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event6 - Video Bus: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "43" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event5 - Video Bus: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "44" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event0 - Sleep Button: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "45" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event11 - Integrated Camera: Integrated C: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "46" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event12 - Integrated Camera: Integrated I: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "47" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event3 - AT Translated Set 2 keyboard: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "48" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event4 - SynPS/2 Synaptics TouchPad: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "49" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event7 - TPPS/2 ALPS TrackPoint: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: () Option "fd" "50" Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) event10 - ThinkPad Extra Buttons: device removed Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) AIGLX: Suspending AIGLX clients for VT switch Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:67 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:76 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 226:0 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:71 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:70 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:64 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:66 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:68 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:74 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:69 Dec 21 12:23:41 pop-os /usr/lib/gdm3/gdm-x-session[1864]: (II) systemd-logind: got pause for 13:75

There is no activity in the logs until I wake the system -- this makes sense since the system is suspended! I assume the first set of lines below, referring to stopping devices were just lines queued to be logged.

I tap the power button to wake it up, and apart from the slight confusion around mixed stop/start messages (see above), you can see things do wake up properly

Dec 21 12:24:35 pop-os kernel: [ 498.382716] smpboot: CPU 6 is now offline Dec 21 12:24:35 pop-os kernel: [ 498.386497] IRQ 131: no longer affine to CPU7 Dec 21 12:24:35 pop-os kernel: [ 498.387536] smpboot: CPU 7 is now offline Dec 21 12:24:35 pop-os kernel: [ 498.390526] IRQ 129: no longer affine to CPU8 Dec 21 12:24:35 pop-os kernel: [ 498.390537] IRQ 153: no longer affine to CPU8 Dec 21 12:24:35 pop-os kernel: [ 498.390540] IRQ 167: no longer affine to CPU8 Dec 21 12:24:35 pop-os kernel: [ 498.390544] IRQ 171: no longer affine to CPU8 Dec 21 12:24:35 pop-os kernel: [ 498.390547] IRQ 173: no longer affine to CPU8 Dec 21 12:24:35 pop-os kernel: [ 498.391556] smpboot: CPU 8 is now offline Dec 21 12:24:35 pop-os kernel: [ 498.395266] smpboot: CPU 9 is now offline Dec 21 12:24:35 pop-os kernel: [ 498.398738] smpboot: CPU 10 is now offline Dec 21 12:24:35 pop-os kernel: [ 498.402238] smpboot: CPU 11 is now offline Dec 21 12:24:35 pop-os kernel: [ 498.407269] ACPI: Low-level resume complete Dec 21 12:24:35 pop-os kernel: [ 498.407348] ACPI: EC: EC started Dec 21 12:24:35 pop-os kernel: [ 498.407349] PM: Restoring platform NVS memory Dec 21 12:24:35 pop-os kernel: [ 498.417215] Enabling non-boot CPUs ... Dec 21 12:24:35 pop-os kernel: [ 498.417247] x86: Booting SMP configuration: Dec 21 12:24:35 pop-os kernel: [ 498.417248] smpboot: Booting Node 0 Processor 1 APIC 0x2 Dec 21 12:24:35 pop-os kernel: [ 498.417841] CPU1 is up Dec 21 12:24:35 pop-os kernel: [ 498.417863] smpboot: Booting Node 0 Processor 2 APIC 0x4 Dec 21 12:24:35 pop-os kernel: [ 498.418415] CPU2 is up Dec 21 12:24:35 pop-os kernel: [ 498.418435] smpboot: Booting Node 0 Processor 3 APIC 0x6 Dec 21 12:24:35 pop-os kernel: [ 498.418998] CPU3 is up Dec 21 12:24:35 pop-os kernel: [ 498.419017] smpboot: Booting Node 0 Processor 4 APIC 0x8 Dec 21 12:24:35 pop-os kernel: [ 498.419590] CPU4 is up Dec 21 12:24:35 pop-os kernel: [ 498.419609] smpboot: Booting Node 0 Processor 5 APIC 0xa Dec 21 12:24:35 pop-os kernel: [ 498.420193] CPU5 is up Dec 21 12:24:35 pop-os kernel: [ 498.420213] smpboot: Booting Node 0 Processor 6 APIC 0x1 Dec 21 12:24:35 pop-os kernel: [ 498.420936] CPU6 is up Dec 21 12:24:35 pop-os kernel: [ 498.420962] smpboot: Booting Node 0 Processor 7 APIC 0x3 Dec 21 12:24:35 pop-os kernel: [ 498.421565] CPU7 is up Dec 21 12:24:35 pop-os kernel: [ 498.421585] smpboot: Booting Node 0 Processor 8 APIC 0x5 Dec 21 12:24:35 pop-os kernel: [ 498.422213] CPU8 is up Dec 21 12:24:35 pop-os kernel: [ 498.422241] smpboot: Booting Node 0 Processor 9 APIC 0x7 Dec 21 12:24:35 pop-os kernel: [ 498.422860] CPU9 is up Dec 21 12:24:35 pop-os kernel: [ 498.422883] smpboot: Booting Node 0 Processor 10 APIC 0x9 Dec 21 12:24:35 pop-os kernel: [ 498.423518] CPU10 is up Dec 21 12:24:35 pop-os kernel: [ 498.423540] smpboot: Booting Node 0 Processor 11 APIC 0xb Dec 21 12:24:35 pop-os kernel: [ 498.424183] CPU11 is up Dec 21 12:24:35 pop-os kernel: [ 498.427911] ACPI: Waking up from system sleep state S3 Dec 21 12:24:35 pop-os kernel: [ 498.538155] ACPI: EC: interrupt unblocked Dec 21 12:24:35 pop-os kernel: [ 498.766963] ACPI: EC: event unblocked Dec 21 12:24:35 pop-os kernel: [ 498.802474] iwlwifi 0000:52:00.0: Applying debug destination EXTERNAL_DRAM Dec 21 12:24:35 pop-os kernel: [ 499.005533] nvme nvme0: Shutdown timeout set to 8 seconds Dec 21 12:24:35 pop-os kernel: [ 499.009545] iwlwifi 0000:52:00.0: FW already configured (0) - re-configuring Dec 21 12:24:35 pop-os kernel: [ 499.017275] iwlwifi 0000:52:00.0: BIOS contains WGDS but no WRDS Dec 21 12:24:35 pop-os kernel: [ 499.021054] nvme nvme0: 12/0/0 default/read/poll queues Dec 21 12:24:35 pop-os kernel: [ 499.062283] usb 1-9: reset full-speed USB device number 3 using xhci_hcd Dec 21 12:24:35 pop-os kernel: [ 499.338503] usb 1-11: reset full-speed USB device number 4 using xhci_hcd Dec 21 12:24:35 pop-os kernel: [ 499.475773] psmouse serio1: synaptics: queried max coordinates: x [..5678], y [..4690] Dec 21 12:24:35 pop-os kernel: [ 499.503521] psmouse serio1: synaptics: queried min coordinates: x [1266..], y [1160..] Dec 21 12:24:35 pop-os kernel: [ 499.614682] usb 1-8: reset high-speed USB device number 2 using xhci_hcd Dec 21 12:24:35 pop-os kernel: [ 499.831228] fbcon: Taking over console Dec 21 12:24:35 pop-os kernel: [ 499.831300] acpi LNXPOWER:0b: Turning OFF Dec 21 12:24:35 pop-os kernel: [ 499.831630] acpi LNXPOWER:06: Turning OFF Dec 21 12:24:35 pop-os kernel: [ 499.831928] acpi LNXPOWER:05: Turning OFF Dec 21 12:24:35 pop-os kernel: [ 499.833084] OOM killer enabled. Dec 21 12:24:35 pop-os kernel: [ 499.833086] Restarting tasks ... done. Dec 21 12:24:35 pop-os kernel: [ 499.840679] rfkill: input handler enabled Dec 21 12:24:35 pop-os acpid: client 1866[0:0] has disconnected Dec 21 12:24:35 pop-os NetworkManager[1024]: [1576884275.4325] sup-iface[0x55747a1cb120,wlp82s0]: connection disconnected (reason -3) Dec 21 12:24:35 pop-os wpa_supplicant[1032]: wlp82s0: CTRL-EVENT-DISCONNECTED bssid=c0:25:06:f2:d6:0c reason=3 locally_generated=1 Dec 21 12:24:35 pop-os NetworkManager[1024]: [1576884275.4369] device (wlp82s0): supplicant interface state: completed -> disconnected Dec 21 12:24:35 pop-os wpa_supplicant[1032]: dbus: wpa_dbus_property_changed: no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/0 Dec 21 12:24:35 pop-os wpa_supplicant[1032]: wlp82s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=WORLD Dec 21 12:24:35 pop-os kernel: [ 499.855147] Console: switching to colour frame buffer device 240x67 Dec 21 12:24:35 pop-os kernel: [ 499.922440] pcieport 0000:00:1b.4: PCI bridge to [bus 04-51] Dec 21 12:24:35 pop-os kernel: [ 499.922442] pcieport 0000:00:1b.4: bridge window [io 0x5000-0x7fff] Dec 21 12:24:35 pop-os kernel: [ 499.922447] pcieport 0000:00:1b.4: bridge window [mem 0xb4000000-0xcc1fffff] Dec 21 12:24:35 pop-os kernel: [ 499.922450] pcieport 0000:00:1b.4: bridge window [mem 0x6000000000-0x603fffffff 64bit pref] Dec 21 12:24:35 pop-os kernel: [ 499.922755] pcieport 0000:00:1b.4: PCI bridge to [bus 04-51] Dec 21 12:24:35 pop-os kernel: [ 499.922759] pcieport 0000:00:1b.4: bridge window [io 0x5000-0x7fff] Dec 21 12:24:35 pop-os kernel: [ 499.922766] pcieport 0000:00:1b.4: bridge window [mem 0xb4000000-0xcc1fffff] Dec 21 12:24:35 pop-os kernel: [ 499.922771] pcieport 0000:00:1b.4: bridge window [mem 0x6000000000-0x603fffffff 64bit pref] Dec 21 12:24:35 pop-os kernel: [ 499.922952] pcieport 0000:00:1b.4: PCI bridge to [bus 04-51] Dec 21 12:24:35 pop-os kernel: [ 499.922953] pcieport 0000:00:1b.4: bridge window [io 0x5000-0x7fff] Dec 21 12:24:35 pop-os kernel: [ 499.922961] pcieport 0000:00:1b.4: bridge window [mem 0xb4000000-0xcc1fffff] Dec 21 12:24:35 pop-os kernel: [ 499.922966] pcieport 0000:00:1b.4: bridge window [mem 0x6000000000-0x603fffffff 64bit pref] Dec 21 12:24:35 pop-os NetworkManager[1024]: [1576884275.5346] device (wlp82s0): supplicant interface state: disconnected -> scanning

Finally, the system sleep / suspend services report a successful resumption

Dec 21 12:24:35 pop-os systemd-sleep[4295]: System resumed. Dec 21 12:24:35 pop-os kernel: [ 499.979638] PM: suspend exit Dec 21 12:24:35 pop-os systemd[1]: systemd-suspend.service: Succeeded. Dec 21 12:24:35 pop-os systemd[1]: Started Suspend. Dec 21 12:24:35 pop-os systemd[1]: Stopped target Sleep. Dec 21 12:24:35 pop-os systemd[1]: Reached target Suspend. Dec 21 12:24:35 pop-os systemd[1]: Stopped target Suspend.

kshepherd commented 4 years ago

Further to this, my systemd sleep.conf is just all the defaults, as shipped, but I may play around with it to see if I get any different behaviour or clues:

[Sleep]

AllowSuspend=yes

AllowHibernation=yes

AllowSuspendThenHibernate=yes

AllowHybridSleep=yes

SuspendMode=

SuspendState=mem standby freeze

HibernateMode=platform shutdown

HibernateState=disk

HybridSleepMode=suspend platform shutdown

HybridSleepState=disk

HibernateDelaySec=180min

Serkan80 commented 4 years ago

I have the same issue with the same laptop running on PopOs 20.04 and with external monitors connected. I think the problem mostly happens when the laptop is on battery and/not when plugged in.

I get the following error:

PCI post-resume error -19 HC died: cleaning up thunderbolt 000.x.x.x.x failed to send driver ready to ICM iwlwifi 000.x.x.x.x BIOS contains WGDS but no WRDS hub 4-1:1.0: set hub depth failed

madisonpeople commented 2 years ago

I find a sure way to recreate this problem is leaving your device in Suspend or Hibernate mode +2 or more hours System76 Thelio Just installed Pop Os 22.04