Waking up from suspend, no idea why

Samuelfaure · 2024-04-19 03:03:09

My system often wakes up right after suspend, but I have no idea why.

I have studied the journalctl log but I don't manage to find what's waking it up and what to do.

Here's the output of `sudo journalctl -b` after executing suspend and the system waking up:

Apr 19 11:41:44 mycomputer rtkit-daemon[728]: Supervising 11 threads of 7 processes of 1 users.
Apr 19 11:41:44 mycomputer systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
Apr 19 11:41:43 mycomputer NetworkManager[726]: <info>  [1713494503.2944] dhcp6 (wlp1s0): state changed new lease
Apr 19 11:41:43 mycomputer NetworkManager[726]: <info>  [1713494503.2894] policy: set 'Buffalo-G-51B0' (wlp1s0) as default for IPv6 routing and DNS
Apr 19 11:41:43 mycomputer NetworkManager[726]: <info>  [1713494503.2886] dhcp6 (wlp1s0): activation: beginning transaction (timeout in 45 seconds)
Apr 19 11:41:42 mycomputer NetworkManager[726]: <info>  [1713494502.4967] manager: NetworkManager state is now CONNECTED_GLOBAL
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-26 noise=-96 txrate=1000
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.5386] device (wlp1s0): Activation: successful, device activated.
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.5382] manager: NetworkManager state is now CONNECTED_SITE
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.5379] device (wlp1s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.5378] device (wlp1s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.5357] device (wlp1s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.4845] policy: set 'Buffalo-G-51B0' (wlp1s0) as default for IPv4 routing and DNS
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.4838] dhcp4 (wlp1s0): state changed new lease, address=192.168.11.10
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.3134] dhcp4 (wlp1s0): state changed new lease, address=192.168.11.10, acd pending
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.2486] dhcp4 (wlp1s0): activation: beginning transaction (timeout in 45 seconds)
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.2482] device (wlp1s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.2458] device (wlp1s0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wirel>
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.2458] device (wlp1s0): supplicant interface state: 4way_handshake -> completed
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-CONNECTED - Connection to <confidential> completed [id=0 id_str=]
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: WPA: Key negotiation completed with <confidential> [PTK=CCMP GTK=CCMP]
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.1778] device (wlp1s0): supplicant interface state: associating -> 4way_handshake
Apr 19 11:41:41 mycomputer kernel: wlp1s0: associated
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: Associated with <confidential>
Apr 19 11:41:41 mycomputer kernel: wlp1s0: RX AssocResp from <confidential> (capab=0x411 status=0 aid=4)
Apr 19 11:41:41 mycomputer kernel: wlp1s0: associate with <confidential> (try 1/3)
Apr 19 11:41:41 mycomputer kernel: wlp1s0: authenticated
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.1459] device (wlp1s0): supplicant interface state: authenticating -> associating
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: Trying to associate with <confidential> (SSID='Buffalo-G-51B0' freq=2437 MHz)
Apr 19 11:41:41 mycomputer kernel: wlp1s0: send auth to <confidential> (try 1/3)
Apr 19 11:41:41 mycomputer kernel: wlp1s0: authenticate with <confidential> (local address=04:7b:cb:29:7d:0a)
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.1426] device (wlp1s0): supplicant interface state: scanning -> authenticating
Apr 19 11:41:41 mycomputer kernel: wlp1s0: 80 MHz not supported, disabling VHT
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: SME: Trying to authenticate with <confidential> (SSID='Buffalo-G-51B0' freq=2437 MHz)
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0290] device (wlp1s0): supplicant interface state: disconnected -> scanning
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0285] Config: added 'psk' value '<hidden>'
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0285] Config: added 'auth_alg' value 'OPEN'
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0285] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK SAE FT-SAE'
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0285] Config: added 'bgscan' value 'simple:30:-70:86400'
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0285] Config: added 'scan_ssid' value '1'
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0284] Config: added 'ssid' value 'Buffalo-G-51B0'
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0284] device (wlp1s0): Activation: (wifi) connection 'Buffalo-G-51B0' has security, and secrets exist.  >
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: WPS-CANCEL
Apr 19 11:41:41 mycomputer wpa_supplicant[1366]: wlp1s0: WPS-PBC-ACTIVE
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0282] device (wlp1s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0280] device (wlp1s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0271] sup-iface[0c24ba1b2dca0b28,7,wlp1s0]: wps: type pbc start...
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0270] device (wlp1s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0270] device (wlp1s0): Activation: (wifi) access point 'Buffalo-G-51B0' has security, but secrets are re>
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0266] device (wlp1s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0265] manager: NetworkManager state is now CONNECTING
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0263] device (wlp1s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0262] device (wlp1s0): Activation: starting connection 'Buffalo-G-51B0' (f6bc9953-d497-4b10-a893-f99859b>
Apr 19 11:41:41 mycomputer NetworkManager[726]: <info>  [1713494501.0257] policy: auto-activating connection 'Buffalo-G-51B0' (f6bc9953-d497-4b10-a893-f99859b9e61c)
Apr 19 11:41:38 mycomputer rtkit-daemon[728]: Supervising 11 threads of 7 processes of 1 users.
Apr 19 11:41:38 mycomputer rtkit-daemon[728]: Supervising 11 threads of 7 processes of 1 users.
Apr 19 11:41:37 mycomputer NetworkManager[726]: <info>  [1713494497.5246] device (wlp1s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-ifa>
Apr 19 11:41:37 mycomputer NetworkManager[726]: <info>  [1713494497.5246] device (wlp1s0): supplicant interface state: internal-starting -> disconnected
Apr 19 11:41:37 mycomputer wpa_supplicant[1366]: dbus: fill_dict_with_properties dbus_interface=fi.w1.wpa_supplicant1.Interface.P2PDevice dbus_property=P2PDeviceConfig gett>
Apr 19 11:41:37 mycomputer NetworkManager[726]: <info>  [1713494497.4805] manager: NetworkManager state is now CONNECTED_LOCAL
Apr 19 11:41:37 mycomputer NetworkManager[726]: <info>  [1713494497.4756] device (wlp1s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'exter>
Apr 19 11:41:37 mycomputer NetworkManager[726]: <info>  [1713494497.4753] manager: sleep: wake requested (sleeping: yes  enabled: yes)
Apr 19 11:41:37 mycomputer systemd-logind[734]: Operation 'suspend' finished.
Apr 19 11:41:37 mycomputer systemd[1]: Stopped target Suspend.
Apr 19 11:41:37 mycomputer systemd[1]: Reached target Suspend.
Apr 19 11:41:37 mycomputer systemd[1]: Stopped target Sleep.
Apr 19 11:41:37 mycomputer systemd[1]: Finished System Suspend.
Apr 19 11:41:37 mycomputer systemd[1]: systemd-suspend.service: Deactivated successfully.
Apr 19 11:41:36 mycomputer kernel: PM: suspend exit
Apr 19 11:41:36 mycomputer bluetoothd[1403]: Controller resume with wake event 0x0
Apr 19 11:41:36 mycomputer systemd-sleep[268112]: System returned from sleep operation 'suspend'.
Apr 19 11:41:36 mycomputer systemd-logind[734]: Lid closed.
Apr 19 11:41:36 mycomputer kernel: random: crng reseeded on system resumption
Apr 19 11:41:36 mycomputer kernel: Restarting tasks ... done.
Apr 19 11:41:36 mycomputer kernel: OOM killer enabled.
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring jpeg_dec uses VM inv eng 5 on hub 8
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring vcn_enc_0.1 uses VM inv eng 4 on hub 8
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring vcn_enc_0.0 uses VM inv eng 1 on hub 8
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring vcn_dec_0 uses VM inv eng 0 on hub 8
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring sdma0 uses VM inv eng 12 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring kiq_0.2.1.0 uses VM inv eng 11 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.3.1 uses VM inv eng 10 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.2.1 uses VM inv eng 9 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.1.1 uses VM inv eng 8 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.0.1 uses VM inv eng 7 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.3.0 uses VM inv eng 6 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.2.0 uses VM inv eng 5 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.1.0 uses VM inv eng 4 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring comp_1.0.0 uses VM inv eng 1 on hub 0
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: ring gfx_0.0.0 uses VM inv eng 0 on hub 0
Apr 19 11:41:36 mycomputer kernel: [drm] JPEG decode initialized successfully.
Apr 19 11:41:36 mycomputer kernel: [drm] VCN decode and encode initialized successfully(under DPG Mode).
Apr 19 11:41:36 mycomputer kernel: nvme nvme0: 16/0/0 default/read/poll queues
Apr 19 11:41:36 mycomputer kernel: nvme nvme0: Shutdown timeout set to 10 seconds
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: SMU is resumed successfully!
Apr 19 11:41:36 mycomputer kernel: amdgpu 0000:33:00.0: amdgpu: SMU is resuming...
Apr 19 11:41:36 mycomputer kernel: [drm] PCIE GART of 1024M enabled (table at 0x000000F43FC00000).
Apr 19 11:41:36 mycomputer kernel: ACPI: EC: interrupt unblocked
Apr 19 11:41:36 mycomputer kernel: amd_pmc AMDI0007:00: Last suspend didn't reach deepest state
Apr 19 11:41:36 mycomputer kernel: ACPI: EC: interrupt blocked
Apr 19 11:41:36 mycomputer kernel: ACPI: EC: interrupt blocked
Apr 19 11:41:36 mycomputer kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Apr 19 11:41:36 mycomputer kernel: Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
Apr 19 11:41:36 mycomputer kernel: Freezing remaining freezable tasks
Apr 19 11:41:36 mycomputer kernel: OOM killer disabled.
Apr 19 11:41:36 mycomputer kernel: Freezing user space processes completed (elapsed 0.002 seconds)
Apr 19 11:41:36 mycomputer kernel: Freezing user space processes
Apr 19 11:41:34 mycomputer kernel: Filesystems sync: 0.021 seconds
Apr 19 11:41:34 mycomputer kernel: PM: suspend entry (s2idle)
Apr 19 11:41:34 mycomputer systemd-sleep[268112]: Performing sleep operation 'suspend'...
Apr 19 11:41:34 mycomputer wpa_supplicant[1366]: nl80211: deinit ifname=wlp1s0 disabled_11b_rates=0
Apr 19 11:41:34 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-DSCP-POLICY clear_all
Apr 19 11:41:34 mycomputer systemd[1]: Starting System Suspend...
Apr 19 11:41:34 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-DSCP-POLICY clear_all
Apr 19 11:41:34 mycomputer systemd[1]: Reached target Sleep.
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.6817] device (wlp1s0): set-hw-addr: reset MAC address to 04:7B:CB:29:7D:0A (unmanage)
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.5630] device (wlp1s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'man>
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.5626] device (wlp1s0): supplicant interface state: interface_disabled -> disconnected
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.5625] device (wlp1s0): supplicant interface state: disconnected -> interface_disabled
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3951] device (wlp1s0): set-hw-addr: set MAC address to 92:B0:15:00:F9:7E (scanning)
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3266] dhcp6 (wlp1s0): state changed no lease
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3266] dhcp6 (wlp1s0): activation: beginning transaction (timeout in 45 seconds)
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3265] dhcp6 (wlp1s0): canceled DHCP transaction
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3264] dhcp4 (wlp1s0): state changed no lease
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3263] dhcp4 (wlp1s0): activation: beginning transaction (timeout in 45 seconds)
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3263] dhcp4 (wlp1s0): canceled DHCP transaction
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3260] device (wlp1s0): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: '>
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.3258] device (wlp1s0): supplicant interface state: completed -> disconnected
Apr 19 11:41:34 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-DSCP-POLICY clear_all
Apr 19 11:41:34 mycomputer wpa_supplicant[1366]: wlp1s0: CTRL-EVENT-DISCONNECTED bssid=<confidential> reason=3 locally_generated=1
Apr 19 11:41:34 mycomputer kernel: wlp1s0: deauthenticating from <confidential> by local choice (Reason: 3=DEAUTH_LEAVING)
Apr 19 11:41:34 mycomputer systemd[1]: Started Network Manager Script Dispatcher Service.
Apr 19 11:41:34 mycomputer systemd[1]: Starting Network Manager Script Dispatcher Service...
Apr 19 11:41:34 mycomputer polkitd[1472]: Unregistered Authentication Agent for unix-process:268093:18628818 (system bus name :1.792, object path /org/freedesktop/PolicyKit>
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.0453] device (wlp1s0): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'man>
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.0450] manager: NetworkManager state is now ASLEEP
Apr 19 11:41:34 mycomputer NetworkManager[726]: <info>  [1713494494.0448] manager: sleep: sleep requested (sleeping: no  enabled: yes)
Apr 19 11:41:34 mycomputer systemd-logind[734]: The system will suspend now!
Apr 19 11:41:34 mycomputer polkitd[1472]: Registered Authentication Agent for unix-process:268093:18628818 (system bus name :1.792 [/usr/bin/pkttyagent --notify-fd 5 --fall>

Last edited by Samuelfaure (2024-04-19 03:03:54)

seth · 2024-04-19 07:06:17

Because it's like top-quoting.
Why?
Please don't use "-r" w/ journalctl.

Apr 19 11:41:34 mycomputer systemd-sleep[268112]: Performing sleep operation 'suspend'...
Apr 19 11:41:34 mycomputer kernel: PM: suspend entry (s2idle)
…
Apr 19 11:41:36 mycomputer kernel: ACPI: EC: interrupt blocked
Apr 19 11:41:36 mycomputer kernel: amd_pmc AMDI0007:00: Last suspend didn't reach deepest state
Apr 19 11:41:36 mycomputer kernel: ACPI: EC: interrupt unblocked
…
Apr 19 11:41:36 mycomputer kernel: OOM killer enabled.
Apr 19 11:41:36 mycomputer kernel: Restarting tasks ... done.
Apr 19 11:41:36 mycomputer kernel: random: crng reseeded on system resumption

You didn't wake up, you never fell asleep.
amd_pmc is the power management controller, https://bbs.archlinux.org/viewtopic.php?id=288637 # post #3

Arch Linux

#1 2024-04-19 03:03:09

Waking up from suspend, no idea why

#2 2024-04-19 07:06:17

Re: Waking up from suspend, no idea why

Board footer