Machine often falls instantly back into sleep mode after wake up

tcn · 2022-10-31 07:46:06

Hi!

Since quite a while I have this weird issue, that when I wake up my Threadripper 1950x the machine instantly falls back to sleep. The 2nd attempt always work out. Sometimes I even get to see the screen but then it falls back to sleep anyway.

And today I experienced this weird phenomenon: woke up on 1st try, could see screen but mouse/keyboard were dead. This actually also happens from time to time and I fix it by replugging the wireless USB receiver. But this didn't work this time either.

After half a minute everything was fine again.

Then I discovered this in kernel log:

[2636852.648782] logitech-djreceiver 0003:046D:C52B.002C: hiddev96,hidraw7: USB HID v1.11 Device [Logitech USB Receiver] on usb-0000:0a:00.3-4.1.3/input2
[2636852.796205] input: Logitech MX Master as /devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb5/5-4/5-4.1/5-4.1.3/5-4.1.3:1.2/0003:046D:C52B.002C/0003:046D:4071.002D/input/input53
[2636852.796516] logitech-hidpp-device 0003:046D:4071.002D: input,hidraw11: USB HID v1.11 Keyboard [Logitech MX Master] on usb-0000:0a:00.3-4.1.3/input2:1
[2636852.832036] logitech-hidpp-device 0003:046D:4092.002E: HID++ 4.5 device connected.
[2636853.194220] input: Logitech MX Keys Mac as /devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb5/5-4/5-4.1/5-4.1.3/5-4.1.3:1.2/0003:046D:C52B.002C/0003:046D:4092.002E/input/input54
[2636853.194440] logitech-hidpp-device 0003:046D:4092.002E: input,hidraw12: USB HID v1.11 Keyboard [Logitech MX Keys Mac] on usb-0000:0a:00.3-4.1.3/input2:2

[2636870.869798] Freezing of tasks failed after 20.014 seconds (2 tasks refusing to freeze, wq_busy=0):
[2636870.869884] task:krunner         state:D stack:    0 pid:379099 ppid:     1 flags:0x00000006
[2636870.869889] Call Trace:
[2636870.869891]  <TASK>
[2636870.869894]  __schedule+0x300/0x930
[2636870.869901]  schedule+0x44/0xb0
[2636870.869904]  autofs_wait+0x219/0x7c0
[2636870.869909]  ? finish_wait+0x90/0x90
[2636870.869913]  ? autofs_mount_wait+0x49/0x100
[2636870.869915]  autofs_mount_wait+0x49/0x100
[2636870.869918]  autofs_d_automount+0xdb/0x220
[2636870.869921]  __traverse_mounts+0x8f/0x230
[2636870.869925]  step_into+0x3e3/0x710
[2636870.869928]  walk_component+0x83/0x1c0
[2636870.869931]  path_lookupat+0x5f/0x1a0
[2636870.869934]  filename_lookup+0xc2/0x1e0
[2636870.869938]  ? getname_flags.part.0+0x4c/0x1c0
[2636870.869941]  user_path_at_empty+0x3a/0x60
[2636870.869945]  user_statfs+0x54/0xe0
[2636870.869948]  __do_sys_statfs+0x31/0x70
[2636870.869951]  do_syscall_64+0x5c/0x90
[2636870.869955]  ? exit_to_user_mode_prepare+0x8d/0x180
[2636870.869959]  ? syscall_exit_to_user_mode+0x23/0x50
[2636870.869961]  ? do_syscall_64+0x69/0x90
[2636870.869965]  ? syscall_exit_to_user_mode+0x23/0x50
[2636870.869967]  ? do_syscall_64+0x69/0x90
[2636870.869971]  ? exit_to_user_mode_prepare+0x145/0x180
[2636870.869973]  ? syscall_exit_to_user_mode+0x23/0x50
[2636870.869976]  ? do_syscall_64+0x69/0x90
[2636870.869979]  ? exit_to_user_mode_prepare+0xd6/0x180
[2636870.869981]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[2636870.869985] RIP: 0033:0x7fb749cadadb
[2636870.869988] RSP: 002b:00007fff9c29f998 EFLAGS: 00000246 ORIG_RAX: 0000000000000089
[2636870.869991] RAX: ffffffffffffffda RBX: 00007fff9c29fb40 RCX: 00007fb749cadadb
[2636870.869993] RDX: 0000000000000000 RSI: 00007fff9c29f9a0 RDI: 0000557504234198
[2636870.869995] RBP: 00007fff9c29fa80 R08: 0000557504234180 R09: 0000000000000078
[2636870.869996] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007fff9c29f9a0
[2636870.869997] R13: 0000557503f8bb20 R14: 00007fff9c29fa68 R15: 00007fff9c29fa70
[2636870.870000]  </TASK>
[2636870.870888] task:fstrim          state:D stack:    0 pid:3243853 ppid:     1 flags:0x00004226
[2636870.870892] Call Trace:
[2636870.870893]  <TASK>
[2636870.870893]  ? __sched_text_start+0x8/0x8
[2636870.870898]  __schedule+0x300/0x930
[2636870.870901]  ? __sched_text_start+0x8/0x8
[2636870.870904]  schedule+0x44/0xb0
[2636870.870906]  schedule_timeout+0x10c/0x150
[2636870.870910]  io_schedule_timeout+0x4c/0x80
[2636870.870913]  __wait_for_common+0xc4/0x180
[2636870.870916]  submit_bio_wait+0xab/0xc0
[2636870.870920]  blkdev_issue_discard+0xab/0x100
[2636870.870925]  btrfs_issue_discard+0xff/0x180 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.870973]  btrfs_discard_extent+0x116/0x300 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871019]  do_trimming+0xde/0x270 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871077]  ? kmem_cache_free+0x3a7/0x400
[2636870.871080]  trim_no_bitmap+0x2af/0x430 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871138]  btrfs_trim_block_group+0x76/0x130 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871195]  btrfs_trim_fs+0xab/0x430 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871240]  ? security_capable+0x36/0x60
[2636870.871243]  btrfs_ioctl_fitrim+0x11f/0x190 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871298]  btrfs_ioctl+0x175a/0x2e30 [btrfs 5286cc6876ce26d5d4824c84494eb6093e0f5439]
[2636870.871354]  ? __audit_syscall_exit+0x255/0x2c0
[2636870.871359]  ? __seccomp_filter+0x39f/0x560
[2636870.871363]  ? __x64_sys_ioctl+0x8e/0xd0
[2636870.871366]  __x64_sys_ioctl+0x8e/0xd0
[2636870.871369]  do_syscall_64+0x5c/0x90
[2636870.871373]  ? do_syscall_64+0x69/0x90
[2636870.871376]  ? syscall_exit_to_user_mode+0x23/0x50
[2636870.871379]  ? do_syscall_64+0x69/0x90
[2636870.871382]  ? exc_page_fault+0x72/0x160
[2636870.871384]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[2636870.871387] RIP: 0033:0x7f6d15d92e6f
[2636870.871390] RSP: 002b:00007fffbe714a70 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[2636870.871392] RAX: ffffffffffffffda RBX: 00007fffbe714bc0 RCX: 00007f6d15d92e6f
[2636870.871394] RDX: 00007fffbe714ae0 RSI: 00000000c0185879 RDI: 0000000000000003
[2636870.871395] RBP: 000055d57ef26940 R08: 000000055d57ef2a R09: 0000000000000000
[2636870.871397] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000003
[2636870.871398] R13: 000055d57ef26b10 R14: 000055d57ef299e0 R15: 000055d57ef299e0
[2636870.871401]  </TASK>

[2636870.871408] OOM killer enabled.
[2636870.871409] Restarting tasks ... done.
[2636870.885052] PM: suspend exit

This looks to me that it actually tried to fall back to sleep but was prevented by a just kicked off fstrim via systemd (what a timing!).

Has anyone else experienced this? Any thoughts on this? I'm really confused why this happens. Any idea on how to tackle this?

thx
tcn

cfr · 2022-11-01 02:28:24

How are you suspending? Post /etc/systemd/logind.conf. Are you using KDE power management?

tcn · 2022-11-01 06:25:52

I'm suspending with "systemctl suspend"

[Login]
#NAutoVTs=6
#ReserveVT=6
#KillUserProcesses=no
#KillOnlyUsers=
#KillExcludeUsers=root
#InhibitDelayMaxSec=5
#UserStopDelaySec=10
#HandlePowerKey=poweroff
#HandleSuspendKey=suspend
#HandleHibernateKey=hibernate
#HandleLidSwitch=suspend
#HandleLidSwitchExternalPower=suspend
#HandleLidSwitchDocked=ignore
#HandleRebootKey=reboot
#HandleRebootKeyLongPress=poweroff
#PowerKeyIgnoreInhibited=no
#SuspendKeyIgnoreInhibited=no
#HibernateKeyIgnoreInhibited=no
#LidSwitchIgnoreInhibited=yes
#RebootKeyIgnoreInhibited=no
#HoldoffTimeoutSec=30s
# https://github.com/systemd/systemd/issues/1295#issuecomment-142035562
# https://wiki.archlinux.org/index.php/Systemd/User#Xorg_as_a_systemd_user_service
#IdleAction=ignore
#IdleActionSec=30min
#RuntimeDirectorySize=10%
#RuntimeDirectoryInodes=400k
#RemoveIPC=yes
#InhibitorsMax=8192
#SessionsMax=8192

I do have KDE power management configured but almost always suspend manually with above mentioned command.

This issue started to arise out of "nothing" as far as I can tell, so I'm suspecting some kernel/systemd/whatever update that introduced this behavior (quite a while ago).

EDIT: oh, and I may add, waking up by pressing the USB keyboard also doesn't work, have to press the power button, unless after a fresh reboot...

Last edited by tcn (2022-11-01 08:26:32)

cfr · 2022-11-01 12:47:42

I was guessing KDE power management is also suspending, but I don't know how this would fit with it working properly before. For example, I had to change

#LidSwitchIgnoreInhibited=yes

to

LidSwitchIgnoreInhibited=no

to prevent double-suspension on my laptop, but I almost always suspend by closing the lid.

Look/post the journal from a suspend to see what's causing it.

If you disable KDE power management temporarily does that prevent the problem?

tcn · 2022-11-01 13:07:29

KDE power management: maybe I'm gonna give this a shot. The thing is that this doesn't happen always. And particularly not after a reboot.

Kernel log, I don't see anything. It wakes up, restores network connections and then just goes back to sleep again:

[2353786.546880] PM: suspend entry (deep)
[2353786.579090] Filesystems sync: 0.032 seconds
[2353786.581315] Freezing user space processes ... (elapsed 0.039 seconds) done.
[2353786.621132] OOM killer disabled.
[2353786.621133] Freezing remaining freezable tasks ... (elapsed 0.004 seconds) done.
[2353786.625470] printk: Suspending console(s) (use no_console_suspend to debug)
[2353786.626696] wlp3s0: deauthenticating from c8:0e:14:8a:8f:38 by local choice (Reason: 3=DEAUTH_LEAVING)
[2353786.712544] sd 1:0:0:0: [sda] Synchronizing SCSI cache
[2353786.714619] sd 1:0:0:0: [sda] Stopping disk
[2353786.773356] sd 3:0:0:0: [sdb] Synchronizing SCSI cache
[2353786.775324] sd 3:0:0:0: [sdb] Stopping disk
[2353787.482450] bond0: (slave enp67s0f0): link status definitely down, disabling slave
[2353787.482463] device enp67s0f1 entered promiscuous mode
[2353787.482550] bond0: (slave enp67s0f1): link status definitely down, disabling slave
[2353787.482559] device enp67s0f1 left promiscuous mode
[2353787.482590] bond0: now running without any active interface!
[2353787.957036] amdgpu 0000:44:00.0: amdgpu: BACO reset
[2353788.364502] ACPI: EC: interrupt blocked
[2353788.502611] ACPI: PM: Preparing to enter system sleep state S3
[2353788.822721] ACPI: EC: event blocked
[2353788.822723] ACPI: EC: EC stopped
[2353788.822723] ACPI: PM: Saving platform NVS memory
[2353788.822766] Disabling non-boot CPUs ...
[2353788.834957] smpboot: CPU 1 is now offline
[2353788.851527] smpboot: CPU 2 is now offline
[2353788.866451] smpboot: CPU 3 is now offline
[2353788.880991] smpboot: CPU 4 is now offline
[2353788.894481] smpboot: CPU 5 is now offline
[2353788.907252] smpboot: CPU 6 is now offline
[2353788.920692] smpboot: CPU 7 is now offline
[2353788.933071] smpboot: CPU 8 is now offline
[2353788.945677] smpboot: CPU 9 is now offline
[2353788.957091] smpboot: CPU 10 is now offline
[2353788.967632] smpboot: CPU 11 is now offline
[2353788.979216] smpboot: CPU 12 is now offline
[2353788.989804] smpboot: CPU 13 is now offline
[2353788.999295] smpboot: CPU 14 is now offline
[2353789.007888] smpboot: CPU 15 is now offline
[2353789.016552] smpboot: CPU 16 is now offline
[2353789.026481] smpboot: CPU 17 is now offline
[2353789.034404] smpboot: CPU 18 is now offline
[2353789.041907] smpboot: CPU 19 is now offline
[2353789.049916] smpboot: CPU 20 is now offline
[2353789.057272] smpboot: CPU 21 is now offline
[2353789.064957] smpboot: CPU 22 is now offline
[2353789.071088] smpboot: CPU 23 is now offline
[2353789.077695] smpboot: CPU 24 is now offline
[2353789.083937] smpboot: CPU 25 is now offline
[2353789.091376] smpboot: CPU 26 is now offline
[2353789.097856] smpboot: CPU 27 is now offline
[2353789.103171] smpboot: CPU 28 is now offline
[2353789.108922] smpboot: CPU 29 is now offline
[2353789.114254] smpboot: CPU 30 is now offline
[2353789.119219] smpboot: CPU 31 is now offline
[2353789.122457] ACPI: PM: Low-level resume complete
[2353789.122491] ACPI: EC: EC started
[2353789.122491] ACPI: PM: Restoring platform NVS memory
[2353789.123342] Enabling non-boot CPUs ...
[2353789.126126] x86: Booting SMP configuration:
[2353789.126127] smpboot: Booting Node 0 Processor 1 APIC 0x2
[2353789.126324] microcode: CPU1: patch_level=0x08001137
[2353789.128638] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.128640] ACPI: \_PR_.C002: Found 2 idle states
[2353789.128923] CPU1 is up
[2353789.128988] smpboot: Booting Node 0 Processor 2 APIC 0x4
[2353789.129248] microcode: CPU2: patch_level=0x08001137
[2353789.131541] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.131543] ACPI: \_PR_.C004: Found 2 idle states
[2353789.131946] CPU2 is up
[2353789.131995] smpboot: Booting Node 0 Processor 3 APIC 0x6
[2353789.132114] microcode: CPU3: patch_level=0x08001137
[2353789.134888] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.134890] ACPI: \_PR_.C006: Found 2 idle states
[2353789.135440] CPU3 is up
[2353789.135484] smpboot: Booting Node 0 Processor 4 APIC 0x8
[2353789.135590] microcode: CPU4: patch_level=0x08001137
[2353789.137945] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.137947] ACPI: \_PR_.C008: Found 2 idle states
[2353789.138607] CPU4 is up
[2353789.138656] smpboot: Booting Node 0 Processor 5 APIC 0xa
[2353789.138770] microcode: CPU5: patch_level=0x08001137
[2353789.141088] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.141091] ACPI: \_PR_.C00A: Found 2 idle states
[2353789.142007] CPU5 is up
[2353789.142061] smpboot: Booting Node 0 Processor 6 APIC 0xc
[2353789.142180] microcode: CPU6: patch_level=0x08001137
[2353789.144519] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.144522] ACPI: \_PR_.C00C: Found 2 idle states
[2353789.145658] CPU6 is up
[2353789.145710] smpboot: Booting Node 0 Processor 7 APIC 0xe
[2353789.145832] microcode: CPU7: patch_level=0x08001137
[2353789.148164] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.148166] ACPI: \_PR_.C00E: Found 2 idle states
[2353789.149445] CPU7 is up
[2353789.149500] smpboot: Booting Node 1 Processor 8 APIC 0x10
[2353789.149682] microcode: CPU8: patch_level=0x08001137
[2353789.152177] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.152180] ACPI: \_PR_.C010: Found 2 idle states
[2353789.152318] intel_rapl_common: Found RAPL domain package
[2353789.152320] intel_rapl_common: Found RAPL domain core
[2353789.152333] powercap intel-rapl:1: PM: parent intel-rapl should not be sleeping
[2353789.154041] CPU8 is up
[2353789.154088] smpboot: Booting Node 1 Processor 9 APIC 0x12
[2353789.154226] microcode: CPU9: patch_level=0x08001137
[2353789.156601] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.156604] ACPI: \_PR_.C012: Found 2 idle states
[2353789.158576] CPU9 is up
[2353789.158622] smpboot: Booting Node 1 Processor 10 APIC 0x14
[2353789.158762] microcode: CPU10: patch_level=0x08001137
[2353789.161135] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.161138] ACPI: \_PR_.C014: Found 2 idle states
[2353789.163313] CPU10 is up
[2353789.163368] smpboot: Booting Node 1 Processor 11 APIC 0x16
[2353789.163508] microcode: CPU11: patch_level=0x08001137
[2353789.165889] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.165892] ACPI: \_PR_.C016: Found 2 idle states
[2353789.168211] CPU11 is up
[2353789.168258] smpboot: Booting Node 1 Processor 12 APIC 0x18
[2353789.168377] microcode: CPU12: patch_level=0x08001137
[2353789.170781] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.170784] ACPI: \_PR_.C018: Found 2 idle states
[2353789.173369] CPU12 is up
[2353789.173416] smpboot: Booting Node 1 Processor 13 APIC 0x1a
[2353789.173559] microcode: CPU13: patch_level=0x08001137
[2353789.175941] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.175944] ACPI: \_PR_.C01A: Found 2 idle states
[2353789.178783] CPU13 is up
[2353789.178829] smpboot: Booting Node 1 Processor 14 APIC 0x1c
[2353789.178977] microcode: CPU14: patch_level=0x08001137
[2353789.181357] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.181359] ACPI: \_PR_.C01C: Found 2 idle states
[2353789.184449] CPU14 is up
[2353789.184496] smpboot: Booting Node 1 Processor 15 APIC 0x1e
[2353789.184647] microcode: CPU15: patch_level=0x08001137
[2353789.187034] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.187037] ACPI: \_PR_.C01E: Found 2 idle states
[2353789.190329] CPU15 is up
[2353789.190379] smpboot: Booting Node 0 Processor 16 APIC 0x1
[2353789.190588] microcode: CPU16: patch_level=0x08001137
[2353789.192957] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.192960] ACPI: \_PR_.C001: Found 2 idle states
[2353789.196809] CPU16 is up
[2353789.196868] smpboot: Booting Node 0 Processor 17 APIC 0x3
[2353789.197028] microcode: CPU17: patch_level=0x08001137
[2353789.199362] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.199364] ACPI: \_PR_.C003: Found 2 idle states
[2353789.203173] CPU17 is up
[2353789.203219] smpboot: Booting Node 0 Processor 18 APIC 0x5
[2353789.203534] microcode: CPU18: patch_level=0x08001137
[2353789.205895] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.205897] ACPI: \_PR_.C005: Found 2 idle states
[2353789.209983] CPU18 is up
[2353789.210034] smpboot: Booting Node 0 Processor 19 APIC 0x7
[2353789.210340] microcode: CPU19: patch_level=0x08001137
[2353789.212664] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.212667] ACPI: \_PR_.C007: Found 2 idle states
[2353789.217146] CPU19 is up
[2353789.217191] smpboot: Booting Node 0 Processor 20 APIC 0x9
[2353789.217472] microcode: CPU20: patch_level=0x08001137
[2353789.219839] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.219842] ACPI: \_PR_.C009: Found 2 idle states
[2353789.224827] CPU20 is up
[2353789.224881] smpboot: Booting Node 0 Processor 21 APIC 0xb
[2353789.225379] microcode: CPU21: patch_level=0x08001137
[2353789.227729] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.227731] ACPI: \_PR_.C00B: Found 2 idle states
[2353789.232917] CPU21 is up
[2353789.232969] smpboot: Booting Node 0 Processor 22 APIC 0xd
[2353789.233321] microcode: CPU22: patch_level=0x08001137
[2353789.235685] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.235687] ACPI: \_PR_.C00D: Found 2 idle states
[2353789.241186] CPU22 is up
[2353789.241242] smpboot: Booting Node 0 Processor 23 APIC 0xf
[2353789.241608] microcode: CPU23: patch_level=0x08001137
[2353789.243984] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.243988] ACPI: \_PR_.C00F: Found 2 idle states
[2353789.249729] CPU23 is up
[2353789.249784] smpboot: Booting Node 1 Processor 24 APIC 0x11
[2353789.249922] microcode: CPU24: patch_level=0x08001137
[2353789.252335] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.252337] ACPI: \_PR_.C011: Found 2 idle states
[2353789.258802] CPU24 is up
[2353789.258856] smpboot: Booting Node 1 Processor 25 APIC 0x13
[2353789.259039] microcode: CPU25: patch_level=0x08001137
[2353789.261436] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.261439] ACPI: \_PR_.C013: Found 2 idle states
[2353789.267800] CPU25 is up
[2353789.267849] smpboot: Booting Node 1 Processor 26 APIC 0x15
[2353789.268031] microcode: CPU26: patch_level=0x08001137
[2353789.270433] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.270436] ACPI: \_PR_.C015: Found 2 idle states
[2353789.277057] CPU26 is up
[2353789.277104] smpboot: Booting Node 1 Processor 27 APIC 0x17
[2353789.277286] microcode: CPU27: patch_level=0x08001137
[2353789.279682] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.279685] ACPI: \_PR_.C017: Found 2 idle states
[2353789.286831] CPU27 is up
[2353789.286879] smpboot: Booting Node 1 Processor 28 APIC 0x19
[2353789.287036] microcode: CPU28: patch_level=0x08001137
[2353789.289458] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.289461] ACPI: \_PR_.C019: Found 2 idle states
[2353789.296909] CPU28 is up
[2353789.296958] smpboot: Booting Node 1 Processor 29 APIC 0x1b
[2353789.297147] microcode: CPU29: patch_level=0x08001137
[2353789.299555] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.299557] ACPI: \_PR_.C01B: Found 2 idle states
[2353789.307563] CPU29 is up
[2353789.307611] smpboot: Booting Node 1 Processor 30 APIC 0x1d
[2353789.307803] microcode: CPU30: patch_level=0x08001137
[2353789.310205] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.310208] ACPI: \_PR_.C01D: Found 2 idle states
[2353789.318505] CPU30 is up
[2353789.318554] smpboot: Booting Node 1 Processor 31 APIC 0x1f
[2353789.318747] microcode: CPU31: patch_level=0x08001137
[2353789.321149] [Firmware Bug]: ACPI MWAIT C-state 0x0 not supported by HW (0x0)
[2353789.321152] ACPI: \_PR_.C01F: Found 2 idle states
[2353789.329677] CPU31 is up
[2353789.333646] ACPI: PM: Waking up from system sleep state S3
[2353789.334628] ACPI: EC: interrupt unblocked
[2353789.465930] ACPI: EC: event unblocked
[2353789.466026] usb usb1: root hub lost power or was reset
[2353789.466030] usb usb2: root hub lost power or was reset
[2353789.466292] sd 3:0:0:0: [sdb] Starting disk
[2353789.466292] sd 1:0:0:0: [sda] Starting disk
[2353789.567255] nvme nvme1: Shutdown timeout set to 8 seconds
[2353789.567294] nvme nvme2: Shutdown timeout set to 8 seconds
[2353789.594824] nvme nvme2: 32/0/0 default/read/poll queues
[2353789.595219] nvme nvme1: 32/0/0 default/read/poll queues
[2353789.603119] [drm] PCIE GART of 256M enabled (table at 0x000000F400300000).
[2353789.689492] nvme nvme0: 7/0/0 default/read/poll queues
[2353789.795307] ata6: SATA link down (SStatus 0 SControl 300)
[2353789.795327] ata1: SATA link down (SStatus 0 SControl 300)
[2353789.795349] ata3: SATA link down (SStatus 0 SControl 300)
[2353789.795991] ata5: SATA link down (SStatus 0 SControl 300)
[2353789.796549] ata7: SATA link down (SStatus 0 SControl 330)
[2353789.796698] ata9: SATA link down (SStatus 0 SControl 300)
[2353789.796709] ata10: SATA link down (SStatus 0 SControl 300)
[2353789.874164] usb 1-2: reset full-speed USB device number 2 using xhci_hcd
[2353789.894615] ixgbe 0000:43:00.1: Multiqueue Enabled: Rx Queue count = 32, Tx Queue count = 32 XDP Queue count = 0
[2353789.963780] ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[2353789.963799] ata4: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[2353789.964097] ata2.00: supports DRM functions and may not be fully accessible
[2353789.964119] ata4.00: supports DRM functions and may not be fully accessible
[2353789.964872] ata4.00: disabling queued TRIM support
[2353789.965012] ata2.00: disabling queued TRIM support
[2353789.968043] ata4.00: supports DRM functions and may not be fully accessible
[2353789.968272] ata2.00: supports DRM functions and may not be fully accessible
[2353789.968794] ata4.00: disabling queued TRIM support
[2353789.969032] ata2.00: disabling queued TRIM support
[2353789.971684] ata4.00: configured for UDMA/133
[2353789.972022] ata4.00: Enabling discard_zeroes_data
[2353789.972044] ata2.00: configured for UDMA/133
[2353789.972253] ata2.00: Enabling discard_zeroes_data
[2353790.164604] ixgbe 0000:43:00.0: Multiqueue Enabled: Rx Queue count = 32, Tx Queue count = 32 XDP Queue count = 0
[2353790.174251] ixgbe 0000:43:00.1 enp67s0f1: initiating reset to clear Tx work after link loss
[2353790.243766] [drm] Fence fallback timer expired on ring sdma0
[2353790.273965] usb 1-9: reset full-speed USB device number 3 using xhci_hcd
[2353790.432929] ixgbe 0000:43:00.1 enp67s0f1: Reset adapter
[2353790.563776] ata8: failed to resume link (SControl 0)
[2353790.563787] ata8: SATA link down (SStatus 0 SControl 0)
[2353790.663893] usb 1-11: reset full-speed USB device number 4 using xhci_hcd
[2353790.753770] [drm] Fence fallback timer expired on ring sdma0
[2353791.030218] ixgbe 0000:43:00.0 enp67s0f0: initiating reset to clear Tx work after link loss
[2353791.054837] usb 2-3: reset SuperSpeed USB device number 2 using xhci_hcd
[2353791.093795] ixgbe 0000:43:00.0 enp67s0f0: Reset adapter
[2353791.263758] [drm] Fence fallback timer expired on ring sdma0
[2353791.773780] [drm] Fence fallback timer expired on ring sdma0
[2353792.283776] [drm] Fence fallback timer expired on ring sdma0
[2353792.793770] [drm] Fence fallback timer expired on ring sdma0
[2353793.303774] [drm] Fence fallback timer expired on ring sdma0
[2353793.813756] [drm] Fence fallback timer expired on ring sdma0
[2353793.858728] [drm] UVD and UVD ENC initialized successfully.
[2353793.959733] [drm] VCE initialized successfully.
[2353793.970531] OOM killer enabled.
[2353793.970533] Restarting tasks ... 
[2353793.971286] audit: type=1700 audit(1666463960.408:9829): dev=enp67s0f1 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[2353793.971296] audit: type=1700 audit(1666463960.408:9830): dev=enp67s0f1 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
[2353793.983196] done.
[2353793.983210] PM: suspend exit
[2353793.995627] audit: type=1334 audit(1666502954.870:9831): prog-id=262 op=LOAD
[2353794.004745] audit: type=1130 audit(1666502954.880:9832): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353794.057028] audit: type=1130 audit(1666502954.930:9833): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353794.057039] audit: type=1131 audit(1666502954.930:9834): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353794.071969] audit: type=1131 audit(1666502954.940:9835): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353794.106811] audit: type=1130 audit(1666502954.980:9836): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353794.121097] audit: type=1130 audit(1666502954.990:9837): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=logrotate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353794.121108] audit: type=1131 audit(1666502954.990:9838): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=logrotate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353795.638423] ixgbe 0000:43:00.1 enp67s0f1: NIC Link is Up 10 Gbps, Flow Control: None
[2353795.733977] bond0: (slave enp67s0f1): link status definitely up, 10000 Mbps full duplex
[2353795.733989] bond0: (slave enp67s0f1): making interface the new active one
[2353795.735316] bond0: active interface up!
[2353796.043881] ixgbe 0000:43:00.1 enp67s0f1: NIC Link is Down
[2353796.063963] bond0: (slave enp67s0f1): link status definitely down, disabling slave
[2353796.065067] bond0: now running without any active interface!
[2353796.373539] ixgbe 0000:43:00.0 enp67s0f0: NIC Link is Up 10 Gbps, Flow Control: None
[2353796.403923] bond0: (slave enp67s0f0): link status definitely up, 10000 Mbps full duplex
[2353796.403936] bond0: (slave enp67s0f0): making interface the new active one
[2353796.405244] device enp67s0f0 entered promiscuous mode
[2353796.405861] bond0: active interface up!
[2353797.358143] ixgbe 0000:43:00.1 enp67s0f1: NIC Link is Up 10 Gbps, Flow Control: None
[2353797.434065] bond0: (slave enp67s0f1): link status definitely up, 10000 Mbps full duplex
[2353798.918939] wlp3s0: authenticate with c8:0e:14:8a:8f:37
[2353798.982030] wlp3s0: send auth to c8:0e:14:8a:8f:37 (try 1/3)
[2353798.991987] wlp3s0: authenticated
[2353799.003739] wlp3s0: associate with c8:0e:14:8a:8f:37 (try 1/3)
[2353799.038407] wlp3s0: RX AssocResp from c8:0e:14:8a:8f:37 (capab=0x1431 status=0 aid=1)
[2353799.041053] wlp3s0: associated
[2353799.108664] kauditd_printk_skb: 4 callbacks suppressed
[2353799.108669] audit: type=1131 audit(1666502959.980:9843): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2353799.164006] wlp3s0: Limiting TX power to 20 (20 - 0) dBm as advertised by c8:0e:14:8a:8f:37
[2353807.703676] device enp67s0f0 left promiscuous mode
[2353807.703727] audit: type=1700 audit(1666502968.580:9844): dev=enp67s0f0 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
[2353835.774482] wlp3s0: deauthenticated from c8:0e:14:8a:8f:37 (Reason: 6=CLASS2_FRAME_FROM_NONAUTH_STA)
[2353836.584134] wlp3s0: authenticate with c8:0e:14:8a:8f:38
[2353836.632250] wlp3s0: send auth to c8:0e:14:8a:8f:38 (try 1/3)
[2353836.636134] wlp3s0: authenticated
[2353836.653503] wlp3s0: associate with c8:0e:14:8a:8f:38 (try 1/3)
[2353836.657117] wlp3s0: RX AssocResp from c8:0e:14:8a:8f:38 (capab=0x1511 status=0 aid=3)
[2353836.659939] wlp3s0: associated
[2353836.673714] wlp3s0: Limiting TX power to 27 (30 - 3) dBm as advertised by c8:0e:14:8a:8f:38
[2355700.403157] audit: type=1130 audit(1666504861.281:9845): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapperd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2355760.647098] audit: type=1131 audit(1666504921.521:9846): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapperd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2357140.389790] audit: type=1130 audit(1666506301.851:9847): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapperd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2357200.756023] audit: type=1131 audit(1666506362.222:9848): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapperd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2359299.648475] audit: type=1130 audit(1666508461.124:9849): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapperd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2359359.873475] audit: type=1131 audit(1666508521.354:9850): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapperd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[2359839.847764] audit: type=1101 audit(1666509001.327:9851): pid=2537080 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2359839.847835] audit: type=1103 audit(1666509001.327:9852): pid=2537080 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2359839.847891] audit: type=1006 audit(1666509001.327:9853): pid=2537080 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=471 res=1
[2359839.847902] audit: type=1300 audit(1666509001.327:9853): arch=c000003e syscall=1 success=yes exit=1 a0=3 a1=7ffe03065f40 a2=1 a3=0 items=0 ppid=920 pid=2537080 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=471 comm="crond" exe="/usr/bin/crond" key=(null)
[2359839.847906] audit: type=1327 audit(1666509001.327:9853): proctitle=2F7573722F62696E2F63726F6E64002D6E
[2359839.851909] audit: type=1105 audit(1666509001.337:9854): pid=2537080 uid=0 auid=0 ses=471 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2359839.852003] audit: type=1110 audit(1666509001.337:9855): pid=2537080 uid=0 auid=0 ses=471 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2359839.868995] audit: type=1101 audit(1666509001.357:9856): pid=2537085 uid=0 auid=0 ses=471 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
[2359839.869144] audit: type=1110 audit(1666509001.357:9857): pid=2537085 uid=0 auid=0 ses=471 msg='op=PAM:setcred grantors=pam_faillock,pam_permit,pam_env,pam_faillock acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
[2359839.871322] audit: type=1105 audit(1666509001.357:9858): pid=2537085 uid=0 auid=0 ses=471 msg='op=PAM:session_open grantors=pam_systemd_home,pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
[2360140.526784] kauditd_printk_skb: 24 callbacks suppressed
[2360140.526789] audit: type=1101 audit(1666509302.009:9883): pid=2542677 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360140.526885] audit: type=1103 audit(1666509302.009:9884): pid=2542677 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360140.526939] audit: type=1006 audit(1666509302.009:9885): pid=2542677 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=472 res=1
[2360140.526948] audit: type=1300 audit(1666509302.009:9885): arch=c000003e syscall=1 success=yes exit=1 a0=3 a1=7ffe03065f40 a2=1 a3=0 items=0 ppid=920 pid=2542677 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=472 comm="crond" exe="/usr/bin/crond" key=(null)
[2360140.526951] audit: type=1327 audit(1666509302.009:9885): proctitle=2F7573722F62696E2F63726F6E64002D6E
[2360140.531490] audit: type=1105 audit(1666509302.009:9886): pid=2542677 uid=0 auid=0 ses=472 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360140.531631] audit: type=1110 audit(1666509302.009:9887): pid=2542677 uid=0 auid=0 ses=472 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360141.554090] audit: type=1104 audit(1666509303.029:9888): pid=2542677 uid=0 auid=0 ses=472 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360141.554186] audit: type=1106 audit(1666509303.029:9889): pid=2542677 uid=0 auid=0 ses=472 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360439.556610] audit: type=1101 audit(1666509601.040:9890): pid=2548720 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360439.556661] audit: type=1103 audit(1666509601.040:9891): pid=2548720 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360439.556711] audit: type=1006 audit(1666509601.040:9892): pid=2548720 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=473 res=1
[2360439.556722] audit: type=1300 audit(1666509601.040:9892): arch=c000003e syscall=1 success=yes exit=1 a0=3 a1=7ffe03065f40 a2=1 a3=0 items=0 ppid=920 pid=2548720 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=473 comm="crond" exe="/usr/bin/crond" key=(null)
[2360439.556726] audit: type=1327 audit(1666509601.040:9892): proctitle=2F7573722F62696E2F63726F6E64002D6E
[2360439.561465] audit: type=1105 audit(1666509601.040:9893): pid=2548720 uid=0 auid=0 ses=473 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360439.561584] audit: type=1110 audit(1666509601.040:9894): pid=2548720 uid=0 auid=0 ses=473 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360448.878872] audit: type=1104 audit(1666509610.360:9895): pid=2548720 uid=0 auid=0 ses=473 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2360448.878949] audit: type=1106 audit(1666509610.360:9896): pid=2548720 uid=0 auid=0 ses=473 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
[2361557.343673] PM: suspend entry (deep)
[2361557.370310] Filesystems sync: 0.026 seconds
[2361557.372177] Freezing user space processes ... (elapsed 0.021 seconds) done.
[2361557.393977] OOM killer disabled.
[2361557.393978] Freezing remaining freezable tasks ... (elapsed 0.003 seconds) done.

seth · 2022-11-01 14:59:57

It actually takes some secodns and there're also snapperd, crond and sudo audits - please post the system journal, not only the kernel ringbuffer

sudo journalctl -b

Ceterum censeo: is there a parallel windows installation?
Edit: typo

Last edited by seth (2022-11-02 07:47:23)

tcn · 2022-11-02 06:41:45

Wow, that's 500k lines total...

Excerpt from the corresponding section (why's there an audit logging from the day before??), still can't spot anything:

Nov 02 06:50:00 box kernel: OOM killer enabled.
Nov 02 06:50:00 box kernel: Restarting tasks ... 
Nov 02 06:50:00 box kernel: audit: type=1700 audit(1667328534.647:11729): dev=enp67s0f1 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Nov 02 06:50:00 box kernel: audit: type=1700 audit(1667328534.647:11730): dev=enp67s0f1 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
Nov 02 06:50:00 box kernel: done.
Nov 02 06:50:00 box kernel: PM: suspend exit
Nov 02 06:50:00 box kernel: audit: type=1334 audit(1667368200.840:11731): prog-id=376 op=LOAD
Nov 01 19:48:54 box audit: ANOM_PROMISCUOUS dev=enp67s0f1 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Nov 01 19:48:54 box audit: ANOM_PROMISCUOUS dev=enp67s0f1 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
Nov 02 06:50:00 box audit: BPF prog-id=376 op=LOAD
Nov 02 06:50:00 box systemd-sleep[301473]: System returned from sleep state.
Nov 02 06:50:00 box dhcpcd[258614]: wlp3s0: carrier lost
Nov 02 06:50:00 box systemd[1]: Starting Load/Save RF Kill Switch Status...
Nov 02 06:50:00 box systemd[1]: Starting Rotate log files...
Nov 02 06:50:00 box avahi-daemon[917]: Withdrawing address record for 192.168.178.20 on wlp3s0.
Nov 02 06:50:00 box avahi-daemon[917]: Leaving mDNS multicast group on interface wlp3s0.IPv4 with address 192.168.178.20.
Nov 02 06:50:00 box avahi-daemon[917]: Interface wlp3s0.IPv4 no longer relevant for mDNS.
Nov 02 06:50:00 box systemd[1]: Starting Daily man-db regeneration...
Nov 02 06:50:00 box dhcpcd[258614]: wlp3s0: deleting route to 192.168.178.0/24
Nov 02 06:50:00 box dhcpcd[258614]: wlp3s0: deleting default route via 192.168.178.100
Nov 02 06:50:00 box systemd[1]: Started Verify integrity of password and group files.
Nov 02 06:50:00 box audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box systemd[1]: systemd-suspend.service: Deactivated successfully.
Nov 02 06:50:00 box systemd[1]: Finished System Suspend.
Nov 02 06:50:00 box audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box systemd[1]: Stopped target Sleep.
Nov 02 06:50:00 box systemd[1]: Reached target Suspend.
Nov 02 06:50:00 box kernel: audit: type=1130 audit(1667368200.850:11732): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box kernel: audit: type=1130 audit(1667368200.850:11733): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box kernel: audit: type=1131 audit(1667368200.850:11734): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box systemd[1]: Stopped target Suspend.
Nov 02 06:50:00 box systemd-logind[935]: Operation 'sleep' finished.
Nov 02 06:50:00 box audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box systemd[1]: shadow.service: Deactivated successfully.
Nov 02 06:50:00 box kernel: audit: type=1131 audit(1667368200.870:11735): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=shadow comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box upowerd[1764]: treating change event as add on /sys/devices/pci0000:00/0000:00:01.1/0000:01:00.0/usb1/1-2
Nov 02 06:50:00 box upowerd[1764]: treating change event as add on /sys/devices/pci0000:00/0000:00:01.1/0000:01:00.0/usb1/1-2
Nov 02 06:50:00 box systemd[1260]: Stopped target Bluetooth.
Nov 02 06:50:00 box systemd[1]: Stopped target Bluetooth Support.
Nov 02 06:50:00 box systemd[1]: Reached target Bluetooth Support.
Nov 02 06:50:00 box systemd[1260]: Reached target Bluetooth.
Nov 02 06:50:00 box systemd[1]: Started Load/Save RF Kill Switch Status.
Nov 02 06:50:00 box audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box kernel: audit: type=1130 audit(1667368200.900:11736): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box systemd[1]: logrotate.service: Deactivated successfully.
Nov 02 06:50:00 box systemd[1]: Finished Rotate log files.
Nov 02 06:50:00 box audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=logrotate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=logrotate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box kernel: audit: type=1130 audit(1667368200.920:11737): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=logrotate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box kernel: audit: type=1131 audit(1667368200.920:11738): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=logrotate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 02 06:50:00 box avahi-daemon[917]: Got SIGHUP, reloading.
Nov 02 06:50:00 box avahi-daemon[917]: No service file found in /etc/avahi/services.
Nov 02 06:50:01 box audit: BPF prog-id=0 op=UNLOAD
Nov 02 06:50:01 box systemd[1]: Reached target Sleep.
Nov 02 06:50:01 box systemd[1]: Starting System Suspend...
Nov 02 06:50:01 box systemd-sleep[302002]: Entering sleep state 'suspend'...
Nov 02 06:50:01 box kernel: PM: suspend entry (deep)
Nov 02 06:50:38 box kernel: Filesystems sync: 0.040 seconds
Nov 02 06:50:38 box kernel: Freezing user space processes ... (elapsed 0.004 seconds) done.

Last edited by tcn (2022-11-02 06:43:33)

seth · 2022-11-02 07:51:30

why's there an audit logging from the day before??

The limited context doesn't reveal that, but when did you send the system to sleep?

There's also a nearly 40s delay?

Nov 02 06:50:01 box systemd[1]: Reached target Sleep.
Nov 02 06:50:01 box systemd[1]: Starting System Suspend...
Nov 02 06:50:01 box systemd-sleep[302002]: Entering sleep state 'suspend'...
Nov 02 06:50:01 box kernel: PM: suspend entry (deep)
================================================
Nov 02 06:50:38 box kernel: Filesystems sync: 0.040 seconds
Nov 02 06:50:38 box kernel: Freezing user space processes ... (elapsed 0.004 seconds) done.

seth wrote:

Ceterum censeo: is there a parallel windows installation?

The implication being to follow the 3rd link below.

tcn · 2022-11-02 08:12:26

Yes, waking this threadripper thing up takes about a minute...

Yes, there is parallel Windows installation but on a separate drive. But it's always been there. Fast boot is probably enabled, rarely boot into it.

Last edited by tcn (2022-11-02 08:14:18)

seth · 2022-11-02 08:23:34

Separate drive doesn't matter, fast start is a windows feature that conceals hibernation as shutdown to promote the illusion that windows can boot fast.
It's the primary way to fuck up the ACPI and very relevant in this context.
Disable is, reboot windows and linux twice (for voodoo reasons, it's purely anecdotal and I cannot explain it) and see whether the spontanous sleeps remain.
Otherwise please post more context of the lead up to the first S3

d.ALT · 2022-11-02 09:37:26

seth wrote:

reboot windows and linux twice (for voodoo reasons, it's purely anecdotal and I cannot explain it)

Hey seth, done some tests with Windows--->shutdown--->Linux? (shutting-down works for my bluetooth, not suspension)

seth · 2022-11-02 11:43:28

I'm not really sure what you're trying to say or how it relates to this thread about "double" suspends?

d.ALT · 2022-11-02 15:00:17

seth wrote:

I'm not really sure what you're trying to say or how it relates to this thread about "double" suspends?

I know it's unrelated (Or maybe not?... Who knows what Windows does to the ACPI).
Anyway, mine was simply a suggestion about shutting down instead double rebooting.

seth · 2022-11-02 15:09:45

The double reboot in voodoo science to "unconfuse" the BIOS after stopping windows from hibernating.
You must propery shutdown windows (any OS) before you start linux (any OS, even a second windows) because otherwise two OS are "running" at the same time.
The whole problem is that windows by default never shuts down, but always hibernates (even if you say "shut down" in the start menu).

tcn · 2023-04-12 12:42:58

So, it took me just half a year to give this a shot The fast boot option doesn't even show up for me for whatever reason, so this arguably was not the cause :\

seth · 2023-04-12 13:05:10

"Fast start" and unless you're running windows 7, it is there and the default behavior.

Last edited by seth (2023-04-12 13:05:20)

Arch Linux

#1 2022-10-31 07:46:06

Machine often falls instantly back into sleep mode after wake up

#2 2022-11-01 02:28:24

Re: Machine often falls instantly back into sleep mode after wake up

#3 2022-11-01 06:25:52

Re: Machine often falls instantly back into sleep mode after wake up

#4 2022-11-01 12:47:42

Re: Machine often falls instantly back into sleep mode after wake up

#5 2022-11-01 13:07:29

Re: Machine often falls instantly back into sleep mode after wake up

#6 2022-11-01 14:59:57

Re: Machine often falls instantly back into sleep mode after wake up

#7 2022-11-02 06:41:45

Re: Machine often falls instantly back into sleep mode after wake up

#8 2022-11-02 07:51:30

Re: Machine often falls instantly back into sleep mode after wake up

#9 2022-11-02 08:12:26

Re: Machine often falls instantly back into sleep mode after wake up

#10 2022-11-02 08:23:34

Re: Machine often falls instantly back into sleep mode after wake up

#11 2022-11-02 09:37:26

Re: Machine often falls instantly back into sleep mode after wake up

#12 2022-11-02 11:43:28

Re: Machine often falls instantly back into sleep mode after wake up

#13 2022-11-02 15:00:17

Re: Machine often falls instantly back into sleep mode after wake up

#14 2022-11-02 15:09:45

Re: Machine often falls instantly back into sleep mode after wake up

#15 2023-04-12 12:42:58

Re: Machine often falls instantly back into sleep mode after wake up

#16 2023-04-12 13:05:10

Re: Machine often falls instantly back into sleep mode after wake up

Board footer