Timer with WakeSystem=true increases elapse time after system suspend

[NAVras-Y]

systemd version the issue has been seen with

254.2-7.fc39.x86_64

Used distribution

Fedora Workstation 39 Beta

Linux kernel version used

6.5.3-300.fc39.x86_64

CPU architectures issue was seen on

x86_64

Component

systemd-run

Expected behaviour you didn't see

System wakes up and executes the command after timers with WakeSystem=true elaspe.
LEFT time of those timers reported by systemctl list-timers --all --user decreases after a suspend.

Unexpected behaviour you saw

LEFT time of the timers stayed the same (probably).
The system woke up as expected, but then waited LEFT time before executing the command.

Ref: 1 2 3

Steps to reproduce the problem

• systemd-run --collect --user --unit=alarm-clock --on-active="1m" --timer-property=WakeSystem=true flatpak run io.bassi.Amberol
• Suspend the system by pressing the power button.
• Wait 1 minute for system to wake up.
• Check the time left with systemctl list-timers --all --user.
• Wait another 1 minute to see Amberol.

Additional program output to the terminal or log subsystem illustrating the issue

$ systemd-run --collect --user --unit=alarm-clock --on-active="1m" --timer-property=WakeSystem=true flatpak run io.bassi.Amberol
Bus n/a: changing state UNSET → OPENING
sd-bus: starting bus by connecting to /run/user/1000/systemd/private...
Bus n/a: changing state OPENING → AUTHENTICATING
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartTransientUnit cookie=1 reply_cookie=0 signature=ssa(sv)a(sa(sv)) error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=3 reply_cookie=1 signature=o error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew  cookie=1 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew  cookie=2 reply_cookie=0 signature=uos error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/basic_2etarget interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/app_2eslice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew  cookie=6 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/shutdown_2etarget interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/timers_2etarget interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved  cookie=13 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Got result done/Success for job alarm-clock.timer
Running timer as unit: alarm-clock.timer
Will run service as unit: alarm-clock.service
Bus n/a: changing state RUNNING → CLOSED

$ systemctl list-timers --all --user
Cannot stat /proc/1/root: Permission denied
running_in_chroot(): Permission denied
Bus n/a: changing state UNSET → OPENING
sd-bus: starting bus by connecting to /run/user/1000/systemd/private...
Bus n/a: changing state OPENING → AUTHENTICATING
Successfully forked off '(pager)' as PID 12117.
Skipping PR_SET_MM, as we don't have privileges.
Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
Failed to execute 'pager', will try 'less' next: No such file or directory
Pager executable is "less", options "FRSXMK", quit_on_interrupt: yes
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=ListUnitsByPatterns cookie=1 reply_cookie=0 signature=asas error-name=n/a erro>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=1 reply_cookie=1 signature=a(ssssssouso) error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=2 reply_cookie=0 signature=ss error-name=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=2 reply_cookie=2 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=3 reply_cookie=0 signature=ss error-name=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=3 reply_cookie=3 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=4 reply_cookie=0 signature=ss error-name=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=4 reply_cookie=4 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=5 reply_cookie=0 signature=ss error-name=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=5 reply_cookie=5 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/alarm_2dclock_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=6 reply_cookie=0 signature=ss error-name=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=6 reply_cookie=6 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/systemd_2dtmpfiles_2dclean_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=7 reply_cookie=0 signature=s>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=7 reply_cookie=7 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/systemd_2dtmpfiles_2dclean_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=8 reply_cookie=0 signature=s>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=8 reply_cookie=8 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/systemd_2dtmpfiles_2dclean_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=9 reply_cookie=0 signature=s>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=9 reply_cookie=9 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/systemd_2dtmpfiles_2dclean_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=10 reply_cookie=0 signature=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=10 reply_cookie=10 signature=v error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/systemd_2dtmpfiles_2dclean_2etimer interface=org.freedesktop.DBus.Properties member=Get cookie=11 reply_cookie=0 signature=>
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a  cookie=11 reply_cookie=11 signature=v error-name=n/a error-message=n/a
NEXT                        LEFT LAST                             PASSED UNIT                         ACTIVATES                     
Wed 2023-09-20 11:23:53 UTC  43s -                                     - alarm-clock.timer            alarm-clock.service
Thu 2023-09-21 06:16:13 UTC  18h Wed 2023-09-20 06:13:36 UTC 5h 6min ago systemd-tmpfiles-clean.timer systemd-tmpfiles-clean.service
Bus n/a: changing state RUNNING → CLOSED

2 timers listed.

[poettering]

WakeSystem= is not supported in --user sessions unless you allow CAP_WAKE_ALARM in your session. Hence what you are asking for here simply has no effect at all.

[NAVras-Y]

Edit:
@poettering Sorry, are you aware this is filed against v254?

[NAVras-Y]

@poettering Same behavior when running as system. The system is suspended after the 1st timedatectl command. After it woke up I ran the 2nd timedatectl. Despite more than 1min has passed, the timer still reports having 42s left.

$ systemd-run --collect --unit=alarm-clock --on-active="1m" --timer-property=WakeSystem=true flatpak run io.bassi.Amberol
Running timer as unit: alarm-clock.timer
Will run service as unit: alarm-clock.service
$ timedatectl
               Local time: Wed 2023-09-20 20:51:40 UTC
           Universal time: Wed 2023-09-20 20:51:40 UTC
                 RTC time: Wed 2023-09-20 20:51:41
                Time zone: Etc/UTC (UTC, +0000)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
$ timedatectl
               Local time: Wed 2023-09-20 20:53:08 UTC
           Universal time: Wed 2023-09-20 20:53:08 UTC
                 RTC time: Wed 2023-09-20 20:53:09
                Time zone: Etc/UTC (UTC, +0000)
System clock synchronized: no
              NTP service: active
          RTC in local TZ: no
$ systemctl list-timers --all
NEXT                           LEFT LAST                        PASSED UNIT                         ACTIVATES                     
Wed 2023-09-20 20:53:56 UTC     42s -                                - alarm-clock.timer            alarm-clock.service

8 timers listed.

Edit: Also tried suspending less than 1min and manual wake up, the timer didn't count down either.

p.s. No issue when using --on-calendar, command is run right after wake up.

[NAVras-Y]

Not sure if this is useful but, v->next_elapse increases after suspend:

[NAVras-Y]

It seems that time change is detected after wake up, which triggers a recalculation of next_elapse.

$ systemctl log-level debug --user
$ journalctl -b --user-unit AlarmClock.timer
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Failed to load configuration: No such file or directory
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Trying to enqueue job AlarmClock.timer/start/fail
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Installed new job AlarmClock.timer/start as 643
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Enqueued job AlarmClock.timer/start as 643
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Monotonic timer elapses in 30.000001s.
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Changed dead -> waiting
Nov 14 10:50:25 dyn systemd[1936]: AlarmClock.timer: Job 643 AlarmClock.timer/start finished, result=done
Nov 14 10:50:25 dyn systemd[1936]: Started AlarmClock.timer - /usr/bin/flatpak run io.bassi.Amberol.
Nov 14 10:51:49 fedora systemd[1936]: AlarmClock.timer: Time change, recalculating next elapse.
Nov 14 10:51:49 fedora systemd[1936]: AlarmClock.timer: Monotonic timer elapses in 25.390216s.
Nov 14 10:52:49 dyn systemd[1936]: AlarmClock.timer: Timer elapsed.
Nov 14 10:52:49 dyn systemd[1936]: AlarmClock.timer: Changed waiting -> running
Nov 14 11:02:40 dyn systemd[1936]: AlarmClock.timer: Got notified about unit deactivation.
Nov 14 11:02:40 dyn systemd[1936]: AlarmClock.timer: Timer is elapsed.
Nov 14 11:02:40 dyn systemd[1936]: AlarmClock.timer: Deactivated successfully.
Nov 14 11:02:40 dyn systemd[1936]: AlarmClock.timer: Changed running -> dead
Nov 14 11:02:40 dyn systemd[1936]: AlarmClock.timer: Collecting.

And next_elapse is increased by how much time system was suspended for (/CLOCK_BOOTTIME_ALARM increased).

systemd/src/core/timer.c

Line 471 in 8c5f649

v->next_elapse = usec_add(usec_shift_clock(base, CLOCK_MONOTONIC, TIMER_MONOTONIC_CLOCK(t)), v->value);