[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.