[systemd-devel] [229] systemd timers not triggered after resume

[Kai Krakow]

Hello!

I found that systemd no longer triggers the timer after waking the
system. I'm not sure since which version this is true because I
couldn't use suspend for a longer time due to driver bugs in the kernel.

# /etc/systemd/system/internal-backup.timer
[Unit]
Description=Daily Backup Timer

[Timer]
OnCalendar=03:00
WakeSystem=true

[Install]
WantedBy=timers.target

The system will wake up and go back to sleep after 2 hours later as
configured. But the associated service won't start:

$ systemctl list-timers
NEXT                         LEFT        LAST                         PASSED        UNIT                         ACTIVATES
...
Mi 2016-08-31 03:00:00 CEST  19h left    n/a                          n/a           internal-backup.timer        internal-backup.service
...

9 timers listed.
Pass --all to see loaded but inactive timers, too.


It simply skips triggering and queues the service for the next
invocation.

Aug 30 03:00:35 jupiter.sol.local kernel: pcieport 0000:00:1c.6: System wakeup enabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: PM: noirq suspend of devices complete after 11.418 msecs
Aug 30 03:00:35 jupiter.sol.local kernel: ACPI: Preparing to enter system sleep state S3
Aug 30 03:00:35 jupiter.sol.local kernel: PM: Saving platform NVS memory
Aug 30 03:00:35 jupiter.sol.local kernel: Disabling non-boot CPUs ...
Aug 30 03:00:35 jupiter.sol.local kernel: smpboot: CPU 1 is now offline
Aug 30 03:00:35 jupiter.sol.local kernel: smpboot: CPU 2 is now offline
Aug 30 03:00:35 jupiter.sol.local kernel: smpboot: CPU 3 is now offline
Aug 30 03:00:35 jupiter.sol.local kernel: ACPI: Low-level resume complete
Aug 30 03:00:35 jupiter.sol.local kernel: PM: Restoring platform NVS memory
Aug 30 03:00:35 jupiter.sol.local kernel: Enabling non-boot CPUs ...
Aug 30 03:00:35 jupiter.sol.local kernel: x86: Booting SMP configuration:
Aug 30 03:00:35 jupiter.sol.local kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Aug 30 03:00:35 jupiter.sol.local kernel:  cache: parent cpu1 should not be sleeping
Aug 30 03:00:35 jupiter.sol.local kernel: CPU1 is up
Aug 30 03:00:35 jupiter.sol.local kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
Aug 30 03:00:35 jupiter.sol.local kernel:  cache: parent cpu2 should not be sleeping
Aug 30 03:00:35 jupiter.sol.local kernel: CPU2 is up
Aug 30 03:00:35 jupiter.sol.local kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
Aug 30 03:00:35 jupiter.sol.local kernel:  cache: parent cpu3 should not be sleeping
Aug 30 03:00:35 jupiter.sol.local kernel: CPU3 is up
Aug 30 03:00:35 jupiter.sol.local kernel: ACPI: Waking up from system sleep state S3
Aug 30 03:00:35 jupiter.sol.local kernel: ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: pcieport 0000:00:1c.6: System wakeup disabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: ehci-pci 0000:00:1a.0: System wakeup disabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: PM: noirq resume of devices complete after 11.299 msecs
Aug 30 03:00:35 jupiter.sol.local kernel: PM: early resume of devices complete after 0.266 msecs
Aug 30 03:00:35 jupiter.sol.local kernel: rtc_cmos 00:02: System wakeup disabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: usb usb3: root hub lost power or was reset
Aug 30 03:00:35 jupiter.sol.local kernel: usb usb4: root hub lost power or was reset
Aug 30 03:00:35 jupiter.sol.local kernel: sd 3:0:0:0: [sdd] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 0:0:0:0: [sda] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 4:0:0:0: [sde] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 1:0:0:0: [sdb] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 2:0:0:0: [sdc] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: usb 4-1: reset SuperSpeed USB device number 2 using xhci_hcd
Aug 30 03:00:35 jupiter.sol.local kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd b1/c1:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: supports DRM functions and may not be fully accessible
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd b1/c1:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: supports DRM functions and may not be fully accessible
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: configured for UDMA/133
Aug 30 03:00:35 jupiter.sol.local kernel: PM: noirq resume of devices complete after 11.299 msecs
Aug 30 03:00:35 jupiter.sol.local kernel: PM: early resume of devices complete after 0.266 msecs
Aug 30 03:00:35 jupiter.sol.local kernel: rtc_cmos 00:02: System wakeup disabled by ACPI
Aug 30 03:00:35 jupiter.sol.local kernel: usb usb3: root hub lost power or was reset
Aug 30 03:00:35 jupiter.sol.local kernel: usb usb4: root hub lost power or was reset
Aug 30 03:00:35 jupiter.sol.local kernel: sd 3:0:0:0: [sdd] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 0:0:0:0: [sda] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 4:0:0:0: [sde] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 1:0:0:0: [sdb] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: sd 2:0:0:0: [sdc] Starting disk
Aug 30 03:00:35 jupiter.sol.local kernel: usb 4-1: reset SuperSpeed USB device number 2 using xhci_hcd
Aug 30 03:00:35 jupiter.sol.local kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd b1/c1:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: supports DRM functions and may not be fully accessible
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: ACPI cmd b1/c1:00:00:00:00:00 (unknown) filtered out
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: supports DRM functions and may not be fully accessible
Aug 30 03:00:35 jupiter.sol.local kernel: ata1.00: configured for UDMA/133
Aug 30 03:00:35 jupiter.sol.local kernel: usb 4-2: reset SuperSpeed USB device number 3 using xhci_hcd
Aug 30 03:00:35 jupiter.sol.local kernel: usb 3-1: reset high-speed USB device number 2 using xhci_hcd
Aug 30 03:00:35 jupiter.sol.local kernel: PM: resume of devices complete after 581.970 msecs
Aug 30 03:00:35 jupiter.sol.local kernel: Restarting tasks ... done.
Aug 30 03:00:34 jupiter.sol.local systemd[1546]: Time has been changed
Aug 30 03:00:34 jupiter.sol.local systemd[1]: Time has been changed
Aug 30 03:00:34 jupiter.sol.local systemd-sleep[15459]: System resumed.
Aug 30 03:00:34 jupiter.sol.local systemd[1]: Started Suspend.
Aug 30 03:00:34 jupiter.sol.local systemd[1]: sleep.target: Unit not needed anymore. Stopping.
Aug 30 03:00:34 jupiter.sol.local systemd[1]: Stopped target Sleep.
Aug 30 03:00:34 jupiter.sol.local systemd[1]: Reached target Suspend.
Aug 30 03:00:34 jupiter.sol.local systemd[1]: suspend.target: Unit is bound to inactive unit systemd-suspend.service. Stopping, too.
Aug 30 03:00:34 jupiter.sol.local systemd[1]: Stopped target Suspend.
Aug 30 03:00:34 jupiter.sol.local systemd-logind[1021]: Operation 'sleep' finished.
[following is some network related initialization, some more ATA logs
and cron invocation but not my service]

-- 
Regards,
Kai

Replies to list-only preferred.