[systemd-devel] no log information about why machine is sleeping

[Andrei Borzenkov]

On 12.08.2021 00:11, George Avrunin wrote:
> Hello,
> 
> As a result of a major power outage and consequent issues with some
> switches, my office workstation, a Dell Precision T1700 running
> fully-updated Fedora 34, was off the network for most of last weekend.  As
> our department IT staff detected and fixed the switch issues, they noticed
> that my workstation was putting itself to sleep when it couldn't connect
> to the switch for my floor.  Right now, everything is back up and working,
> but they will probably have to replace the switch.
> 
> However, I haven't been able to figure out why the machine puts itself to
> sleep when it can't reach the switch.  I asked about this on the Fedora
> users list (and included the log entries shown below), and Chris Murphy
> noted that systemd doesn't normally insert the sleep request in the log,
> so it's not possible to determine what caused the sleep request.  He
> suggested that I start a thread here to ask if at least a single line of
> information about how the sleep is being initiated could be dumped into
> the log by default.  
> 
> I will experiment with rebooting with systemd.log_level=debug when I know
> the switch will be shut down for replacement.  But it would be good to get
> more information about what's initiating sleep by default.
> 
> Thanks,
> 
>   George Avrunin
> 
> 
> Here are the relevant log entries from one of the times the machine put
> itself to sleep, apparently because it couldn't connect to the network.
> If there's more information I can supply, please let me know.
> 
> (This starts after power was restored to the building and the machine had
> been manually rebooted just to be sure it would go online.)
> 
> Aug 06 17:47:32 ext.math.umass.edu kernel:
> Lockdown: systemd-logind: hibernation is restricted; see man
> kernel_lockdown.7 Aug 06 17:47:32 ext.math.umass.edu kernel: Lockdown:
> systemd-logind: hibernation is restricted; see man kernel_lockdown.7
> Aug 06 17:47:32 ext.math.umass.edu NetworkManager[2111]: <info>
> [1628286452.1872] manager: sleep: sleep requested (sleeping: no  enabled:
> yes) Aug 06 17:47:32 ext.math.umass.edu NetworkManager[2111]: <info>

Anything before these entries? In my case I see

авг 06 08:41:18 bor-Latitude-E5450 systemd-logind[1300]: Lid closed.
авг 06 08:41:18 bor-Latitude-E5450 systemd-logind[1300]: Suspending...
авг 06 08:41:18 bor-Latitude-E5450 kernel: Lockdown: systemd-logind:
hibernation is restricted;
 see man kernel_lockdown.7
авг 06 08:41:18 bor-Latitude-E5450 NetworkManager[1277]: <info>
[1628228478.4162] manager: sle
ep: sleep requested (sleeping: no  enabled: yes)
...

So here I see the reason for suspend in logs.

> [1628286452.1876] manager: NetworkManager state is now ASLEEP
> Aug 06 17:47:32 ext.math.umass.edu ModemManager[1954]: <info>
> [sleep-monitor] system is about to suspend
> Aug 06 17:47:32 ext.math.umass.edu gnome-shell[4292]: Screen lock is
> locked down, not locking
> Aug 06 17:47:32 ext.math.umass.edu systemd[1]: Reached target Sleep.
> Aug 06 17:47:32 ext.math.umass.edu systemd[1]: Starting System Suspend...
> Aug 06 17:47:32 ext.math.umass.edu systemd-sleep[40504]: Suspending
> system...
> Aug 06 17:47:32 ext.math.umass.edu kernel: PM: suspend entry (deep)
> Aug 07 14:09:22 ext.math.umass.edu kernel: Filesystems sync: 0.379 seconds
> Aug 07 14:09:22 ext.math.umass.edu kernel: Freezing user space processes
> ... (elapsed 0.002 seconds) done.
> Aug 07 14:09:22 ext.math.umass.edu kernel: OOM killer disabled.
> Aug 07 14:09:22 ext.math.umass.edu kernel: Freezing remaining freezable
> tasks ... (elapsed 0.001 seconds) done.
> Aug 07 14:09:22 ext.math.umass.edu kernel: printk: Suspending console(s)
> (use no_console_suspend to debug)
> Aug 07 14:09:22 ext.math.umass.edu kernel: serial 00:06: disabled
> Aug 07 14:09:22 ext.math.umass.edu kernel: e1000e: EEE TX LPI TIMER:
> 00000011
> Aug 07 14:09:22 ext.math.umass.edu kernel: sd 0:0:0:0: [sda] Synchronizing
> SCSI cache
> Aug 07 14:09:22 ext.math.umass.edu kernel: sd 1:0:0:0: [sdb] Synchronizing
> SCSI cache
> Aug 07 14:09:22 ext.math.umass.edu kernel: sd 1:0:0:0: [sdb] Stopping disk
> Aug 07 14:09:22 ext.math.umass.edu kernel: sd 0:0:0:0: [sda] Stopping disk
> Aug 07 14:09:22 ext.math.umass.edu kernel: PM: suspend devices took 1.031
> seconds
> Aug 07 14:09:22 ext.math.umass.edu kernel: ACPI: Preparing to enter system
> sleep state S3
> Aug 07 14:09:22 ext.math.umass.edu kernel: PM: Saving platform NVS memory
> Aug 07 14:09:22 ext.math.umass.edu kernel: Disabling non-boot CPUs ...
> lines 835-871
> etc.
>