Bug 1781566

Summary: Cannot successfully suspend, machine starts again after a few seconds
Product: [Fedora] Fedora Reporter: Andre Klapper <a9016009>
Component: kernelAssignee: Kernel Maintainer List <kernel-maint>
Status: NEW --- QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 33CC: airlied, bskeggs, hdegoede, ichavero, itamar, jan.kratochvil, jarodwilson, jeremy, jglisse, john.j5live, jonathan, josef, kernel-maint, linville, masami256, mchehab, mjg59, steved
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Andre Klapper 2019-12-10 09:35:23 UTC
Version-Release number of selected component (if applicable):
kernel-core-5.3.14-300.fc31.x86_64

How reproducible:

Happens sometimes, but when it happens it is totally reproducible

Steps to Reproduce:
1. Run up to date Fedora 31
2. Click upper right corner to get GNOME Shell menu.
3. Press Alt key on keyboard
4. Click the Pause button

Actual results:
See that the machine suspends and restarts a few seconds later

Expected results:
See that the machine suspends and does not restart a few seconds later

Additional info:

`journalctl -b0` output from unsuccessful suspend attempt:


Dec 10 10:26:48 ac chronyd[1057]: Selected source 51.75.67.47
Dec 10 10:26:54 ac NetworkManager[1126]: <info>  [1575970014.8680] manager: sleep: sleep requested (sleeping: no  enabled: yes)
Dec 10 10:26:54 ac NetworkManager[1126]: <info>  [1575970014.8685] device (p2p-dev-wlp3s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec 10 10:26:54 ac NetworkManager[1126]: <info>  [1575970014.8691] device (cdc-wdm0): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec 10 10:26:54 ac NetworkManager[1126]: <info>  [1575970014.8695] manager: NetworkManager state is now ASLEEP
Dec 10 10:26:54 ac ModemManager[1020]: [/dev/cdc-wdm0] channel destroyed
Dec 10 10:26:56 ac systemd[1]: Reached target Sleep.
Dec 10 10:26:56 ac systemd[1]: Starting Suspend...
Dec 10 10:26:56 ac systemd-sleep[9378]: Suspending system...
Dec 10 10:26:56 ac kernel: PM: suspend entry (deep)
Dec 10 10:26:56 ac kernel: Filesystems sync: 0.025 seconds
Dec 10 10:27:00 ac kernel: Freezing user space processes ... (elapsed 0.002 seconds) done.
Dec 10 10:27:00 ac kernel: OOM killer disabled.
Dec 10 10:27:00 ac kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Dec 10 10:27:00 ac kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Dec 10 10:27:00 ac kernel: wlp3s0: deauthenticating from a8:c0:ea:02:89:88 by local choice (Reason: 3=DEAUTH_LEAVING)
Dec 10 10:27:00 ac kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Dec 10 10:27:00 ac kernel: sd 0:0:0:0: [sda] Stopping disk
Dec 10 10:27:00 ac kernel: e1000e: EEE TX LPI TIMER: 00000011
Dec 10 10:27:00 ac kernel: PM: suspend devices took 0.721 seconds
Dec 10 10:27:00 ac kernel: ACPI: EC: interrupt blocked
Dec 10 10:27:00 ac kernel: ACPI: Preparing to enter system sleep state S3
Dec 10 10:27:00 ac kernel: ACPI: EC: event blocked
Dec 10 10:27:00 ac kernel: ACPI: EC: EC stopped
Dec 10 10:27:00 ac kernel: PM: Saving platform NVS memory
Dec 10 10:27:00 ac kernel: Disabling non-boot CPUs ...
Dec 10 10:27:00 ac kernel: smpboot: CPU 1 is now offline
Dec 10 10:27:00 ac kernel: smpboot: CPU 2 is now offline
Dec 10 10:27:00 ac kernel: smpboot: CPU 3 is now offline
Dec 10 10:27:00 ac kernel: ACPI: Low-level resume complete
Dec 10 10:27:00 ac kernel: ACPI: EC: EC started
Dec 10 10:27:00 ac kernel: PM: Restoring platform NVS memory
Dec 10 10:27:00 ac kernel: Enabling non-boot CPUs ...
Dec 10 10:27:00 ac kernel: x86: Booting SMP configuration:
Dec 10 10:27:00 ac kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Dec 10 10:27:00 ac kernel: CPU1 is up
Dec 10 10:27:00 ac kernel: smpboot: Booting Node 0 Processor 2 APIC 0x2
Dec 10 10:27:00 ac kernel: CPU2 is up
Dec 10 10:27:00 ac kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
Dec 10 10:27:00 ac kernel: CPU3 is up
Dec 10 10:27:00 ac kernel: ACPI: Waking up from system sleep state S3
Dec 10 10:27:00 ac kernel: ACPI: EC: interrupt unblocked
Dec 10 10:27:00 ac kernel: sd 0:0:0:0: [sda] Starting disk
Dec 10 10:27:00 ac kernel: ACPI: EC: event unblocked
Dec 10 10:27:00 ac kernel: iwlwifi 0000:03:00.0: Applying debug destination EXTERNAL_DRAM
Dec 10 10:27:00 ac kernel: tpm tpm0: TPM is disabled/deactivated (0x6)
Dec 10 10:27:00 ac kernel: iwlwifi 0000:03:00.0: Applying debug destination EXTERNAL_DRAM
Dec 10 10:27:00 ac kernel: iwlwifi 0000:03:00.0: FW already configured (0) - re-configuring
Dec 10 10:27:00 ac kernel: usb 2-7: reset full-speed USB device number 4 using xhci_hcd
Dec 10 10:27:01 ac kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Dec 10 10:27:01 ac kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Dec 10 10:27:01 ac kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Dec 10 10:27:01 ac kernel: ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Dec 10 10:27:01 ac kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Dec 10 10:27:01 ac kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Dec 10 10:27:01 ac kernel: ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Dec 10 10:27:01 ac kernel: ata1.00: configured for UDMA/133
Dec 10 10:27:01 ac kernel: usb 2-5: reset full-speed USB device number 3 using xhci_hcd
Dec 10 10:27:01 ac kernel: usb 2-8: reset high-speed USB device number 5 using xhci_hcd
Dec 10 10:27:01 ac kernel: usb 2-4: reset high-speed USB device number 15 using xhci_hcd
Dec 10 10:27:01 ac kernel: usb 2-4: device firmware changed
Dec 10 10:27:01 ac kernel: PM: resume devices took 1.084 seconds
Dec 10 10:27:01 ac kernel: acpi LNXPOWER:02: Turning OFF
Dec 10 10:27:01 ac kernel: OOM killer enabled.
Dec 10 10:27:01 ac kernel: Restarting tasks ... 
Dec 10 10:27:01 ac kernel: usb 2-4: USB disconnect, device number 15
Dec 10 10:27:01 ac kernel: cdc_mbim 2-4:1.0 wwp0s20u4: unregister 'cdc_mbim' usb-0000:00:14.0-4, CDC MBIM
Dec 10 10:27:01 ac kernel: done.
Dec 10 10:27:00 ac bluetoothd[1024]: Endpoint unregistered: sender=:1.267 path=/MediaEndpoint/A2DPSink/sbc
Dec 10 10:27:00 ac systemd[1]: Starting Load/Save RF Kill Switch Status...
Dec 10 10:27:00 ac bluetoothd[1024]: Endpoint unregistered: sender=:1.267 path=/MediaEndpoint/A2DPSource/sbc
Dec 10 10:27:00 ac NetworkManager[1126]: <info>  [1575970020.9986] bluez5: NAP: removed interface 18:5E:0F:39:68:FD
Dec 10 10:27:00 ac wpa_supplicant[1205]: wlp3s0: CTRL-EVENT-DISCONNECTED bssid=a8:c0:ea:02:89:88 reason=3 locally_generated=1
Dec 10 10:27:00 ac NetworkManager[1126]: <warn>  [1575970020.9987] sup-iface[0x55bc1892f4b0,wlp3s0]: connection disconnected (reason -3)
Dec 10 10:27:00 ac wpa_supplicant[1205]: dbus: wpa_dbus_property_changed: no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/5
Dec 10 10:27:00 ac wpa_supplicant[1205]: wlp3s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=WORLD
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.0086] device (wlp3s0): supplicant interface state: completed -> disconnected
Dec 10 10:27:01 ac kernel: Bluetooth: hci0: read Intel version: 370810011003110e00
Dec 10 10:27:01 ac kernel: Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.8.10-fw-1.10.3.11.e.bseq
Dec 10 10:27:01 ac gnome-shell[1645]: An active wireless connection, in infrastructure mode, involves no access point?
Dec 10 10:27:01 ac kernel: PM: suspend exit
Dec 10 10:27:01 ac systemd-sleep[9378]: System resumed.
Dec 10 10:27:01 ac systemd[1]: systemd-suspend.service: Succeeded.
Dec 10 10:27:01 ac systemd[1]: Started Suspend.
Dec 10 10:27:01 ac audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? t>
Dec 10 10:27:01 ac systemd[1]: Stopped target Sleep.
Dec 10 10:27:01 ac systemd[1]: Reached target Suspend.
Dec 10 10:27:01 ac audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? te>
Dec 10 10:27:01 ac systemd-logind[1124]: Operation 'sleep' finished.
Dec 10 10:27:01 ac systemd[1]: Stopped target Suspend.
Dec 10 10:27:01 ac systemd[1534]: Stopped target Bluetooth.
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.0446] manager: sleep: wake requested (sleeping: yes  enabled: yes)
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.0448] device (enp0s25): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec 10 10:27:01 ac systemd[1]: Stopped target Bluetooth.
Dec 10 10:27:01 ac systemd[1534]: Reached target Bluetooth.
Dec 10 10:27:01 ac systemd[1]: Started Load/Save RF Kill Switch Status.
Dec 10 10:27:01 ac audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? te>
Dec 10 10:27:01 ac systemd[1]: Reached target Bluetooth.
Dec 10 10:27:01 ac kernel: e1000e: enp0s25 NIC Link is Down
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.1179] device (wlp3s0): state change: activated -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.1188] dhcp4 (wlp3s0): canceled DHCP transaction
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.1189] dhcp4 (wlp3s0): state changed bound -> done
Dec 10 10:27:01 ac avahi-daemon[1023]: Withdrawing address record for 10.10.10.54 on wlp3s0.
Dec 10 10:27:01 ac avahi-daemon[1023]: Leaving mDNS multicast group on interface wlp3s0.IPv4 with address 10.10.10.54.
Dec 10 10:27:01 ac avahi-daemon[1023]: Interface wlp3s0.IPv4 no longer relevant for mDNS.
Dec 10 10:27:01 ac avahi-daemon[1023]: Withdrawing address record for fe80::d91e:c33b:a093:2d6a on wlp3s0.
Dec 10 10:27:01 ac avahi-daemon[1023]: Leaving mDNS multicast group on interface wlp3s0.IPv6 with address fe80::d91e:c33b:a093:2d6a.
Dec 10 10:27:01 ac avahi-daemon[1023]: Interface wlp3s0.IPv6 no longer relevant for mDNS.
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.1256] manager: NetworkManager state is now CONNECTED_GLOBAL
Dec 10 10:27:01 ac kernel: usb 2-4: new high-speed USB device number 16 using xhci_hcd
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=raw family=2 entries=32
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.1333] manager: NetworkManager state is now DISCONNECTED
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=mangle family=2 entries=43
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=nat family=2 entries=58
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=filter family=2 entries=96
Dec 10 10:27:01 ac wpa_supplicant[1205]: nl80211: deinit ifname=p2p-dev-wlp3s0 disabled_11b_rates=0
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.1375] device (enp0s25): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=raw family=10 entries=34
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=mangle family=10 entries=43
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=nat family=10 entries=58
Dec 10 10:27:01 ac audit: NETFILTER_CFG table=filter family=10 entries=110
Dec 10 10:27:01 ac systemd[1]: Starting Network Manager Script Dispatcher Service...
Dec 10 10:27:01 ac systemd[1]: Started Network Manager Script Dispatcher Service.
Dec 10 10:27:01 ac audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=>
Dec 10 10:27:01 ac chronyd[1057]: Source 5.145.135.83 offline
Dec 10 10:27:01 ac chronyd[1057]: Source 5.9.121.21 offline
Dec 10 10:27:01 ac chronyd[1057]: Source 213.239.239.164 offline
Dec 10 10:27:01 ac chronyd[1057]: Source 51.75.67.47 offline
Dec 10 10:27:01 ac chronyd[1057]: Can't synchronise: no selectable sources
Dec 10 10:27:01 ac kernel: usb 2-4: New USB device found, idVendor=8087, idProduct=0716, bcdDevice= 0.00
Dec 10 10:27:01 ac kernel: usb 2-4: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Dec 10 10:27:01 ac kernel: usb_serial_simple 2-4:1.0: flashloader converter detected
Dec 10 10:27:01 ac kernel: usb 2-4: flashloader converter now attached to ttyUSB0
Dec 10 10:27:01 ac mtp-probe[9434]: checking bus 2, device 16: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-4"
Dec 10 10:27:01 ac mtp-probe[9434]: bus: 2, device: 16 was not an MTP device
Dec 10 10:27:01 ac kernel: Bluetooth: hci0: unexpected event for opcode 0xfc2f
Dec 10 10:27:01 ac kernel: Bluetooth: hci0: Intel firmware patch completed and activated
Dec 10 10:27:01 ac mtp-probe[9452]: checking bus 2, device 16: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-4"
Dec 10 10:27:01 ac mtp-probe[9452]: bus: 2, device: 16 was not an MTP device
Dec 10 10:27:01 ac wpa_supplicant[1205]: nl80211: deinit ifname=wlp3s0 disabled_11b_rates=0
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.3545] device (wlp3s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dec 10 10:27:01 ac kernel: iwlwifi 0000:03:00.0: Applying debug destination EXTERNAL_DRAM
Dec 10 10:27:01 ac kernel: iwlwifi 0000:03:00.0: Applying debug destination EXTERNAL_DRAM
Dec 10 10:27:01 ac kernel: iwlwifi 0000:03:00.0: FW already configured (0) - re-configuring
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.4833] device (wlp3s0): set-hw-addr: set MAC address to DE:71:F4:4F:9C:0F (scanning)
Dec 10 10:27:01 ac kernel: iwlwifi 0000:03:00.0: Applying debug destination EXTERNAL_DRAM
Dec 10 10:27:01 ac kernel: iwlwifi 0000:03:00.0: Applying debug destination EXTERNAL_DRAM
Dec 10 10:27:01 ac kernel: iwlwifi 0000:03:00.0: FW already configured (0) - re-configuring
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.5957] device (p2p-dev-wlp3s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dec 10 10:27:01 ac NetworkManager[1126]: <info>  [1575970021.5996] bluez5: NAP: added interface 18:5E:0F:39:68:FD
Dec 10 10:27:02 ac systemd[1]: Starting Fingerprint Authentication Daemon...
Dec 10 10:27:02 ac systemd[1]: Started Fingerprint Authentication Daemon.
Dec 10 10:27:02 ac audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=fprintd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=>
Dec 10 10:27:02 ac gdm[1148]: GdmManager: trying to open reauthentication channel for user acko
Dec 10 10:27:02 ac gdm[1148]: Finding a graphical session for user 1000
Dec 10 10:27:02 ac gdm[1148]: Considering session '2'
Dec 10 10:27:02 ac gdm[1148]: GdmManager: looking for user session on display
Dec 10 10:27:02 ac gdm[1148]: GdmSession: starting reauthentication for session 2 for client with pid 1000
Dec 10 10:27:02 ac gdm-password][1523]: GdmSessionWorker: start reauthentication
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Creating D-Bus server for worker for session
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: D-Bus server for workers listening on unix:abstract=/tmp/dbus-X50FjmqJ
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Creating D-Bus server for greeters and such for session (null) (0x5648da944480)
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: D-Bus server for greeters listening on unix:abstract=/tmp/dbus-E5RQ4T0E
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Setting display device: (null)
Dec 10 10:27:02 ac gdm[1148]: GdmSession: Emitting 'reauthentication-started' signal for caller pid '1645'
Dec 10 10:27:02 ac gdm[1148]: GdmManager: reauthentication started
Dec 10 10:27:02 ac gdm-password][1523]: GdmDBusServer: new connection 0x5648da8f59b0
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Handling new connection from outside
Dec 10 10:27:02 ac gdm-password][1523]: GdmSessionWorker: client connected to reauthentication server
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: starting conversation gdm-password for session (0x5648da944480)
Dec 10 10:27:02 ac gdm-password][1523]: GdmSessionWorkerJob: Starting worker...
Dec 10 10:27:02 ac gdm-password][1523]: GdmSessionWorkerJob: Running session_worker_job process: gdm-session-worker [pam/gdm-password] /usr/libexec/gdm-session-worker
Dec 10 10:27:02 ac gdm-password][1523]: GLib: posix_spawn avoided (fd close requested) (child_setup specified)
Dec 10 10:27:02 ac gdm-password][1523]: GdmSessionWorkerJob: : SessionWorkerJob on pid 9464
Dec 10 10:27:02 ac gdm-password][9464]: Enabling debugging
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: connecting to address: unix:abstract=/tmp/dbus-X50FjmqJ
Dec 10 10:27:02 ac gdm-password][1523]: GdmDBusServer: new connection 0x7f64680075c0
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Handling new connection from worker
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Authenticating new connection
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: Finding a graphical session for user 0
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: Failed to identify the current session
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: seat unloaded, so trying to set loaded property
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: Seat wouldn't load, so giving up on it and setting loaded property
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: already loaded, so not setting loaded property
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: worker connection is 0x7f64680075c0
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Emitting conversation-started signal
Dec 10 10:27:02 ac gdm-password][1523]: GdmSessionWorker: reauthentication service 'gdm-password' started
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: getting session command for file 'gnome.desktop'
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: checking if file 'gnome.desktop' is wayland session: yes
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: setting session to type 'wayland'
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Set up service gdm-password for username acko on session (0x5648da944480)
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: selecting user 'acko' for session '(null)' (0x5648da944480)
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Beginning initialization
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: getting session command for file 'gnome.desktop'
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: trying to track new user with username acko
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: finding user 'acko' state 1
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: finding user 'acko' state 2
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: Looking for user 'acko' in accounts service
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: checking if file 'gnome.desktop' is wayland session: yes
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: Conversation started
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: Found object path of user 'acko': /org/freedesktop/Accounts/User1000
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: finding user 'acko' state 3
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: user 'acko' fetched
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: user acko is now loaded
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: user acko was not yet known, adding it
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: tracking user 'acko'
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: not yet loaded, so not emitting user-added signal
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: no pending users, trying to set loaded property
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: already loaded, so not setting loaded property
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionSettings: saved session is gnome
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: Saved session is gnome
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionSettings: saved language is en_US.UTF-8
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: Saved language is en_US.UTF-8
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: queuing setup for user: acko (null)
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: finished handling request for user 'acko'
Dec 10 10:27:02 ac gdm-password][9464]: accountsservice: ActUserManager: unrefing manager owned by fetch user request
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: attempting to change state to SETUP_COMPLETE
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: initializing PAM; service=gdm-password username=acko seat=seat0
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: getting session command for file 'gnome.desktop'
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: getting session command for file 'gnome.desktop'
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: getting session command for file 'gnome.desktop'
Dec 10 10:27:02 ac gdm-password][1523]: GdmSession: checking if file 'gnome.desktop' is wayland session: yes
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'XDG_SEAT=seat0'
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: state SETUP_COMPLETE
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: attempting to change state to AUTHENTICATED
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: authenticating user acko
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: 1 new messages received from PAM
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: username is 'acko'
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: old-username='acko' new-username='acko'
Dec 10 10:27:02 ac gdm-password][9464]: GdmSessionWorker: received pam message of type 1 with payload 'Password: '
Dec 10 10:27:03 ac ModemManager[1020]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:19.0': not supported by any plugin
Dec 10 10:27:03 ac ModemManager[1020]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1c.1/0000:03:00.0': not supported by any plugin
Dec 10 10:27:04 ac bluetoothd[1024]: Loading LTKs timed out for hci0
Dec 10 10:27:04 ac bluetoothd[1024]: Endpoint registered: sender=:1.267 path=/MediaEndpoint/A2DPSink/sbc
Dec 10 10:27:04 ac bluetoothd[1024]: Endpoint registered: sender=:1.267 path=/MediaEndpoint/A2DPSource/sbc
Dec 10 10:27:04 ac NetworkManager[1126]: <info>  [1575970024.2072] sup-iface[0x55bc1892f3c0,wlp3s0]: supports 5 scan SSIDs
Dec 10 10:27:04 ac NetworkManager[1126]: <info>  [1575970024.2086] device (wlp3s0): supplicant interface state: starting -> ready
Dec 10 10:27:04 ac NetworkManager[1126]: <info>  [1575970024.2087] device (p2p-dev-wlp3s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Dec 10 10:27:04 ac NetworkManager[1126]: <info>  [1575970024.2095] device (wlp3s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Dec 10 10:27:04 ac kernel: usb 2-4: USB disconnect, device number 16
Dec 10 10:27:04 ac kernel: flashloader ttyUSB0: flashloader converter now disconnected from ttyUSB0
Dec 10 10:27:04 ac kernel: usb_serial_simple 2-4:1.0: device disconnected
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: trying to get updated username
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: PAM conversation returning 0: Success
Dec 10 10:27:05 ac gdm-password][9464]: gkr-pam: unlocked login keyring
Dec 10 10:27:05 ac audit[9464]: USER_AUTH pid=9464 uid=0 auid=1000 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:authentication grantors=pam_unix,pam_gnome_keyring acct="acko" exe="/usr/libexec/>
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: state AUTHENTICATED
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: trying to get updated username
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: username is 'acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: old-username='acko' new-username='acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: attempting to change state to AUTHORIZED
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: determining if authenticated user (password required:0) is authorized to session
Dec 10 10:27:05 ac audit[9464]: USER_ACCT pid=9464 uid=0 auid=1000 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="acko" exe="/usr/libexec/gdm-sess>
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: state AUTHORIZED
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: attempting to change state to ACCREDITED
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'LOGNAME=acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'USER=acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'USERNAME=acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'HOME=/home/acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'PWD=/home/acko'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'SHELL=/bin/bash'
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: Set PAM environment variable: 'PATH=/usr/local/bin:/usr/local/sbin:/usr/bin:/usr/sbin'
Dec 10 10:27:05 ac audit[9464]: CRED_REFR pid=9464 uid=0 auid=1000 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix,pam_gnome_keyring acct="acko" exe="/usr/libexec/gdm-ses>
Dec 10 10:27:05 ac gdm-password][9464]: GdmSessionWorker: state ACCREDITED
Dec 10 10:27:05 ac gdm-password][1523]: GdmSessionWorker: pid 1645 reauthenticated user 1000 with service 'gdm-password'
Dec 10 10:27:05 ac gdm-password][1523]: GdmSession: Stopping all conversations
Dec 10 10:27:05 ac gdm-password][1523]: GdmSessionWorkerJob: Stopping job pid:9464
Dec 10 10:27:05 ac gdm-password][1523]: GdmCommon: sending signal 15 to process 9464
Dec 10 10:27:05 ac gdm-password][1523]: GdmSessionWorkerJob: Waiting on process 9464
Dec 10 10:27:05 ac gdm-password][1523]: GdmCommon: process (pid:9464) done (status:0)
Dec 10 10:27:05 ac gdm-password][1523]: GdmSessionWorkerJob: SessionWorkerJob died
Dec 10 10:27:05 ac gdm-password][1523]: GdmSessionWorker: client cancelled reauthentication request
Dec 10 10:27:05 ac gdm-password][1523]: GdmSession: Stopping all conversations
Dec 10 10:27:05 ac gdm[1148]: GdmSession: Emitting 'reauthenticated' signal
Dec 10 10:27:05 ac gdm[1148]: GdmSession: type wayland, program? no, seat seat0
Dec 10 10:27:05 ac gdm[1148]: GdmManager: Considering session 2 on seat seat0 belonging to user acko
Dec 10 10:27:05 ac gdm[1148]: GdmManager: yes, found session 2
Dec 10 10:27:05 ac gdm[1148]: Unlocking session 2
Dec 10 10:27:05 ac NetworkManager[1126]: <info>  [1575970025.5328] agent-manager: req[0x55bc18bca730, :1.189/org.gnome.Shell.NetworkAgent/1000]: agent registered
Dec 10 10:27:06 ac systemd[1]: systemd-rfkill.service: Succeeded.
Dec 10 10:27:06 ac audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? ter>
Dec 10 10:27:07 ac kernel: usb 2-4: new high-speed USB device number 17 using xhci_hcd
Dec 10 10:27:07 ac kernel: usb 2-4: New USB device found, idVendor=1199, idProduct=a001, bcdDevice=17.29
Dec 10 10:27:07 ac kernel: usb 2-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Dec 10 10:27:07 ac kernel: usb 2-4: Product: Sierra Wireless EM7345 4G LTE
Dec 10 10:27:07 ac kernel: usb 2-4: Manufacturer: Sierra Wireless Inc.
Dec 10 10:27:07 ac kernel: usb 2-4: SerialNumber: 013937008581298
Dec 10 10:27:07 ac kernel: cdc_mbim 2-4:1.0: setting rx_max = 16384
Dec 10 10:27:07 ac kernel: cdc_mbim 2-4:1.0: cdc-wdm0: USB WDM device
Dec 10 10:27:07 ac kernel: cdc_mbim 2-4:1.0 wwan0: register 'cdc_mbim' at usb-0000:00:14.0-4, CDC MBIM, 6a:73:dc:eb:64:2a
Dec 10 10:27:07 ac kernel: cdc_acm 2-4:1.2: ttyACM0: USB ACM device
Dec 10 10:27:07 ac mtp-probe[9502]: checking bus 2, device 17: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-4"
Dec 10 10:27:07 ac mtp-probe[9502]: bus: 2, device: 17 was not an MTP device
Dec 10 10:27:07 ac systemd-udevd[9388]: Using default interface naming scheme 'v243'.
Dec 10 10:27:07 ac systemd-udevd[9388]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Dec 10 10:27:07 ac kernel: cdc_mbim 2-4:1.0 wwp0s20u4: renamed from wwan0
Dec 10 10:27:07 ac mtp-probe[9522]: checking bus 2, device 17: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-4"
Dec 10 10:27:07 ac mtp-probe[9522]: bus: 2, device: 17 was not an MTP device
Dec 10 10:27:07 ac systemd-udevd[9387]: Using default interface naming scheme 'v243'.
Dec 10 10:27:07 ac wpa_supplicant[1205]: wlp3s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=DE
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7579] policy: auto-activating connection 'DB IC Bus' (b0ad8e72-d8b2-4814-83a2-d895e1fa2095)
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7586] device (wlp3s0): Activation: starting connection 'DB IC Bus' (b0ad8e72-d8b2-4814-83a2-d895e1fa2095)
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7590] device (wlp3s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7595] manager: NetworkManager state is now CONNECTING
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7614] device (wlp3s0): set-hw-addr: reset MAC address to 18:5E:0F:39:68:F9 (preserve)
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7643] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7647] device (wlp3s0): Activation: (wifi) connection 'DB IC Bus' requires no security.  No secrets needed.
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7647] Config: added 'ssid' value 'DB IC Bus'
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7647] Config: added 'scan_ssid' value '1'
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7648] Config: added 'bgscan' value 'simple:30:-80:86400'
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7648] Config: added 'key_mgmt' value 'NONE'
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7777] device (wlp3s0): supplicant interface state: ready -> disconnected
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7777] device (p2p-dev-wlp3s0): supplicant management interface state: ready -> disconnected
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7786] device (wlp3s0): supplicant interface state: disconnected -> inactive
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7787] device (p2p-dev-wlp3s0): supplicant management interface state: disconnected -> inactive
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7842] device (wlp3s0): supplicant interface state: inactive -> scanning
Dec 10 10:27:07 ac NetworkManager[1126]: <info>  [1575970027.7842] device (p2p-dev-wlp3s0): supplicant management interface state: inactive -> scanning
Dec 10 10:27:08 ac wpa_supplicant[1205]: wlp3s0: SME: Trying to authenticate with a8:c0:ea:02:89:88 (SSID='DB IC Bus' freq=5580 MHz)
Dec 10 10:27:08 ac kernel: wlp3s0: authenticate with a8:c0:ea:02:89:88
Dec 10 10:27:08 ac kernel: wlp3s0: send auth to a8:c0:ea:02:89:88 (try 1/3)
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6658] device (wlp3s0): supplicant interface state: scanning -> authenticating
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6659] device (p2p-dev-wlp3s0): supplicant management interface state: scanning -> authenticating
Dec 10 10:27:08 ac wpa_supplicant[1205]: wlp3s0: Trying to associate with a8:c0:ea:02:89:88 (SSID='DB IC Bus' freq=5580 MHz)
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6759] device (wlp3s0): supplicant interface state: authenticating -> associating
Dec 10 10:27:08 ac kernel: wlp3s0: authenticated
Dec 10 10:27:08 ac kernel: wlp3s0: associate with a8:c0:ea:02:89:88 (try 1/3)
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6760] device (p2p-dev-wlp3s0): supplicant management interface state: authenticating -> associating
Dec 10 10:27:08 ac kernel: wlp3s0: RX AssocResp from a8:c0:ea:02:89:88 (capab=0x1 status=0 aid=1)
Dec 10 10:27:08 ac wpa_supplicant[1205]: wlp3s0: Associated with a8:c0:ea:02:89:88
Dec 10 10:27:08 ac kernel: wlp3s0: associated
Dec 10 10:27:08 ac wpa_supplicant[1205]: wlp3s0: CTRL-EVENT-CONNECTED - Connection to a8:c0:ea:02:89:88 completed [id=0 id_str=]
Dec 10 10:27:08 ac kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
Dec 10 10:27:08 ac wpa_supplicant[1205]: wlp3s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Dec 10 10:27:08 ac wpa_supplicant[1205]: wlp3s0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-62 noise=9999 txrate=6000
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6864] device (wlp3s0): supplicant interface state: associating -> completed
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6865] device (wlp3s0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "DB IC Bus"
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.6865] device (p2p-dev-wlp3s0): supplicant management interface state: associating -> completed
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=raw family=2 entries=31
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=mangle family=2 entries=42
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=nat family=2 entries=56
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=filter family=2 entries=93
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=raw family=10 entries=33
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=mangle family=10 entries=42
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=nat family=10 entries=56
Dec 10 10:27:08 ac audit: NETFILTER_CFG table=filter family=10 entries=107
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7015] device (wlp3s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7021] dhcp4 (wlp3s0): activation: beginning transaction (timeout in 45 seconds)
Dec 10 10:27:08 ac avahi-daemon[1023]: Joining mDNS multicast group on interface wlp3s0.IPv6 with address fe80::d91e:c33b:a093:2d6a.
Dec 10 10:27:08 ac avahi-daemon[1023]: New relevant interface wlp3s0.IPv6 for mDNS.
Dec 10 10:27:08 ac avahi-daemon[1023]: Registering new address record for fe80::d91e:c33b:a093:2d6a on wlp3s0.*.
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7165] dhcp4 (wlp3s0): state changed unknown -> bound
Dec 10 10:27:08 ac avahi-daemon[1023]: Joining mDNS multicast group on interface wlp3s0.IPv4 with address 10.10.10.54.
Dec 10 10:27:08 ac avahi-daemon[1023]: New relevant interface wlp3s0.IPv4 for mDNS.
Dec 10 10:27:08 ac avahi-daemon[1023]: Registering new address record for 10.10.10.54 on wlp3s0.IPv4.
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7195] device (wlp3s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7248] device (wlp3s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7254] device (wlp3s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7260] manager: NetworkManager state is now CONNECTED_LOCAL
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7307] manager: NetworkManager state is now CONNECTED_SITE
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7309] policy: set 'DB IC Bus' (wlp3s0) as default for IPv4 routing and DNS
Dec 10 10:27:08 ac NetworkManager[1126]: <info>  [1575970028.7315] device (wlp3s0): Activation: successful, device activated.
Dec 10 10:27:08 ac systemd[1]: iscsi.service: Unit cannot be reloaded because it is inactive.
Dec 10 10:27:08 ac chronyd[1057]: Source 51.75.67.47 online
Dec 10 10:27:08 ac chronyd[1057]: Source 5.145.135.83 online
Dec 10 10:27:08 ac chronyd[1057]: Source 5.9.121.21 online
Dec 10 10:27:08 ac chronyd[1057]: Source 213.239.239.164 online
Dec 10 10:27:08 ac ModemManager[1020]: opening device...
Dec 10 10:27:08 ac ModemManager[1020]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 512
Dec 10 10:27:08 ac ModemManager[1020]: [/dev/cdc-wdm0] channel destroyed
Dec 10 10:27:09 ac NetworkManager[1126]: <info>  [1575970029.1132] manager: NetworkManager state is now CONNECTED_GLOBAL
Dec 10 10:27:09 ac ModemManager[1020]: <info>  [device /sys/devices/pci0000:00/0000:00:14.0/usb2/2-4] creating modem with plugin 'Sierra' and '3' ports
Dec 10 10:27:09 ac ModemManager[1020]: <info>  Modem for device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-4' successfully created
Dec 10 10:27:09 ac ModemManager[1020]: opening device...
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 512
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy, mbim, expect-indications'...
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: cdc_mbim
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] created endpoint
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] creating MBIM device...
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] MBIM device created
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] opening MBIM device...
Dec 10 10:27:09 ac ModemManager[1020]: opening device...
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 512
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] MBIM device open
Dec 10 10:27:09 ac ModemManager[1020]: [/dev/cdc-wdm0] Checking version info (15 retries)...
Dec 10 10:27:10 ac ModemManager[1020]: transaction 0x1 aborted, but message is not abortable
Dec 10 10:27:11 ac ModemManager[1020]: [/dev/cdc-wdm0] MBIM error: Transaction timed out
Dec 10 10:27:11 ac ModemManager[1020]: transaction 0x2 aborted, but message is not abortable
Dec 10 10:27:11 ac gnome-keyring-daemon[1557]: asked to register item /org/freedesktop/secrets/collection/login/4, but it's already registered
Dec 10 10:27:12 ac ModemManager[1020]: transaction 0x3 aborted, but message is not abortable
Dec 10 10:27:12 ac ModemManager[1020]: [/dev/cdc-wdm0] MBIM error: Transaction timed out
Dec 10 10:27:12 ac gnome-keyring-daemon[1557]: asked to register item /org/freedesktop/secrets/collection/login/3, but it's already registered

Comment 1 Andre Klapper 2020-01-28 22:03:23 UTC
Still happening sometimes with `kernel-5.4.13-201.fc31.x86_64`

Comment 2 Hans de Goede 2020-01-29 10:23:29 UTC
Looking at the logs your system is using S3 suspend, which is mostly handled in firmware so this is somewhat surprising.

When this happens the next time, can you do:

cat /sys/power/pm_wakeup_irq 

And write down the output? This may give "No data available" as I'm not sure this debug method works with S3 suspend (most modern systems use a new suspend mode called suspend-to-idle aka s2idle). Assuming this gives useful data please also run:

cat /proc/interrupts

And copy and paste the output of both commands here, then we will see from there.

Comment 4 Justin M. Forbes 2020-03-03 16:33:40 UTC
*********** MASS BUG UPDATE **************

We apologize for the inconvenience.  There are a large number of bugs to go through and several of them have gone stale.  Due to this, we are doing a mass bug update across all of the Fedora 31 kernel bugs.

Fedora 31 has now been rebased to 5.5.7-200.fc31.  Please test this kernel update (or newer) and let us know if you issue has been resolved or if it is still present with the newer kernel.

If you have moved on to Fedora 32, and are still experiencing this issue, please change the version to Fedora 32.

If you experience different issues, please open a new bug report for those.

Comment 6 Andre Klapper 2020-03-11 08:06:07 UTC
> Flags: needinfo?(a9016009@gmx.de)

No idea, that was already two months ago and I usually only suspend a lot when I'm at conferences / travelling which is both not very popular these days.

Comment 7 Andre Klapper 2020-08-02 07:27:42 UTC
(In reply to Hans de Goede from comment #2)
> cat /sys/power/pm_wakeup_irq 
> 
> And write down the output? This may give "No data available"

Exactly:

$:acko\> cat /sys/power/pm_wakeup_irq 
cat: /sys/power/pm_wakeup_irq: No data available
$:acko\> cat /sys/power/mem_sleep
s2idle [deep]

Comment 8 Andre Klapper 2020-12-20 23:57:03 UTC
And still happening in 33! Yay!

$:acko\> cat /sys/power/pm_wakeup_irq 
cat: /sys/power/pm_wakeup_irq: No data available
$:acko\> cat /proc/interrupts
           CPU0       CPU1       CPU2       CPU3       
  0:          8          0          0          0   IO-APIC   2-edge      timer
  1:      31815          0          0          0   IO-APIC   1-edge      i8042
  8:          0          1          0          0   IO-APIC   8-edge      rtc0
  9:        813       4208          0          0   IO-APIC   9-fasteoi   acpi
 12:          5          0          0        716   IO-APIC  12-edge      i8042
 18:      28214     695814          0          0   IO-APIC  18-fasteoi   i801_smbus
 23:         46         43          0          0   IO-APIC  23-fasteoi   ehci_hcd:usb1
 42:     255794          0          0          0   PCI-MSI 512000-edge      ahci[0000:00:1f.2]
 43:        568          0        582          0   PCI-MSI 327680-edge      xhci_hcd
 44:          4          0          6          0   PCI-MSI 1048576-edge      rtsx_pci
 45:          0         36          0          0   PCI-MSI 360448-edge      mei_me
 46:    1624382          0          0          0   PCI-MSI 32768-edge      i915
 47:          0        110          0          0   PCI-MSI 442368-edge      snd_hda_intel:card1
 48:          0          0          0          0   PCI-MSI 49152-edge      snd_hda_intel:card0
 49:          0          0          0         50   PCI-MSI 409600-edge      enp0s25
 50:       5468     481983          0          0   PCI-MSI 1572864-edge      iwlwifi
 51:       7035     174040          0          0     dummy  44  rmi4_smbus
 52:          0          0          0          0      rmi4   0  rmi4-00.fn34
 53:          0          0          0          0      rmi4   1  rmi4-00.fn01
 54:          0          0        322          0      rmi4   2  rmi4-00.fn03
 55:          0          0     180045          0      rmi4   3  rmi4-00.fn11
 56:          0          0          0          0      rmi4   4  rmi4-00.fn11
 57:          0          0       1204          0      rmi4   6  rmi4-00.fn30
NMI:        123        119        125        119   Non-maskable interrupts
LOC:    4306237    3655404    3676302    3440942   Local timer interrupts
SPU:          0          0          0          0   Spurious interrupts
PMI:        123        119        125        119   Performance monitoring interrupts
IWI:     492272         75         71         78   IRQ work interrupts
RTR:          2          0          0          0   APIC ICR read retries
RES:     420323     363821     525824     380391   Rescheduling interrupts
CAL:    1098769    1177251     991490    1140869   Function call interrupts
TLB:     678628     631950     662485     625867   TLB shootdowns
TRM:          0          0          0          0   Thermal event interrupts
THR:          0          0          0          0   Threshold APIC interrupts
DFR:          0          0          0          0   Deferred Error APIC interrupts
MCE:          0          0          0          0   Machine check exceptions
MCP:         32         32         32         32   Machine check polls
ERR:          0
MIS:          0
PIN:          0          0          0          0   Posted-interrupt notification event
NPI:          0          0          0          0   Nested posted-interrupt event
PIW:          0          0          0          0   Posted-interrupt wakeup event

Comment 9 Andre Klapper 2020-12-20 23:57:30 UTC
For the records, this is a Lenovo Thinkpad T450s (which I'd expect not to be that uncommon).

Comment 10 Andre Klapper 2021-01-15 08:02:45 UTC
Hans: Hi, any further info wanted / needed here? TIA.

Comment 11 Hans de Goede 2021-01-19 16:05:00 UTC
(In reply to Andre Klapper from comment #10)
> Hans: Hi, any further info wanted / needed here? TIA.

Since you get:

$:acko\> cat /sys/power/pm_wakeup_irq 
cat: /sys/power/pm_wakeup_irq: No data available

This really appears to be a firmware issue and there is not much which we can do.

You could try switching to using s2idle by doing:

echo s2idle > /sys/power/mem_sleep

(I think, if that does not work, try a websearch on how to enable s2idle)

Note on most modern hardware Linux will default to s2idle, so this is pretty well tested by now.

Comment 12 Andre Klapper 2021-01-19 18:19:59 UTC
For the records, most of the time suspend works fine and as expected. It only breaks sometimes, unpredictably.