Bug 1764908

I am unable to reproduce the same condition on my testbed for either RHEL 7 or RHEL 8:

$ for file in test.service test.timer; do echo $file; echo "------------------------------------------------"; cat $file; echo "------------------------------------------------"; echo; done
test.service
------------------------------------------------
[Unit]
Description=Test service to start with a timer

[Service]
ExecStart=/bin/bash -c "echo This was a success on %H"
------------------------------------------------

test.timer
------------------------------------------------
[Unit]
Description=Runs test.service 1 minute after boot

[Timer]
RandomizedDelaySec=1m
OnBootSec=1m
OnUnitInactiveSec=15m

[Install]
WantedBy=timers.target

------------------------------------------------


Results:
[root@rhbz1764908-rhel7 ~]# systemctl status test.timer; for x in {0..9}; do systemctl daemon-reload; sleep 1; echo -n . ; done; echo; systemctl status test.timer
● test.timer - Runs test.service 1 minute after boot
   Loaded: loaded (/etc/systemd/system/test.timer; enabled; vendor preset: disabled)
   Active: active (waiting) since Sun 2020-02-16 08:18:14 EST; 14min ago

Feb 16 08:18:14 rhbz1764908-rhel7 systemd[1]: Started Runs test.service 1 minute after boot.
..........
● test.timer - Runs test.service 1 minute after boot
   Loaded: loaded (/etc/systemd/system/test.timer; enabled; vendor preset: disabled)
   Active: active (waiting) since Sun 2020-02-16 08:18:14 EST; 15min ago

Feb 16 08:18:14 rhbz1764908-rhel7 systemd[1]: Started Runs test.service 1 minute after boot.


[root@rhbz1764908-rhel8 ~]# systemctl status test.timer; for x in {0..9}; do systemctl daemon-reload; sleep 1; echo -n . ; done; echo; systemctl status test.timer
● test.timer - Runs test.service 1 minute after boot
   Loaded: loaded (/etc/systemd/system/test.timer; enabled; vendor preset: disabled)
   Active: active (waiting) since Sun 2020-02-16 08:18:36 EST; 14min ago
  Trigger: Sun 2020-02-16 08:35:17 EST; 2min 8s left

Feb 16 08:18:36 rhbz1764908-rhel8 systemd[1]: Started Runs test.service 1 minute after boot.
..........
● test.timer - Runs test.service 1 minute after boot
   Loaded: loaded (/etc/systemd/system/test.timer; enabled; vendor preset: disabled)
   Active: active (waiting) since Sun 2020-02-16 08:18:36 EST; 14min ago
  Trigger: Sun 2020-02-16 08:35:34 EST; 2min 12s left

Feb 16 08:18:36 rhbz1764908-rhel8 systemd[1]: Started Runs test.service 1 minute after boot.


Would it be possible to provide a sosreport from a system that is encountering this behaviour?

Likely corresponding upstream bug report:

https://github.com/systemd/systemd/issues/6680

I could reproduce this problem. This problem is related with RandomizedDelaySec= and OnBootSec= parameters.
The following is the important points in the current implementation.

 1) Reloading systemd causes changing the time to trigger the service by the recalculation of the random time upon RandomizedDelaySec=.
 2) OnBootSec= is the just one time event after boot.
 3) The time upon OnBootSec= value (not considering RandomizedDelaySec=) is compared with monotonic time. If the monotonic time is larger, the status is changed into "elapsed", and the service is never triggered upon OnBootSec=. 


In case of RandomizedDelaySec=1m and OnBootSec=1m...
  - The service is not triggered after 1m. It's triggered at 1m + [random time]. The maximum random time is 1m.
  - When the systemd daemon is reloaded after 1m and before 1m + [random time], timer_enter_waiting() function is called internally, and it can be changed into elapsed status without triggering the service.


static void timer_enter_waiting(Timer *t, bool initial) {
...
        ts_monotonic = now(t->wake_system ? CLOCK_BOOTTIME : CLOCK_MONOTONIC);     <<===== get current monotonic time.
...
        LIST_FOREACH(value, v, t->values) {
...
                if (v->base == TIMER_CALENDAR) {
...
                } else  {
                        switch (v->base) {
...
                        case TIMER_BOOT:
                                /* CLOCK_MONOTONIC equals the uptime on Linux */
                                base = 0;                                          <<===== base = 0 (meaning the boot time)
                                break;
...
                        }

                        if (t->wake_system)
                                base = monotonic_to_boottime(base);

                        v->next_elapse = base + v->value;                          <<===== 1m (given from OnBootSec=)

                        if (!initial && v->next_elapse < ts_monotonic && IN_SET(v->base, TIMER_ACTIVE, TIMER_BOOT, TIMER_STARTUP)) {

                                ===> now, 1min has passed from boot. still not triggered by RandomizedDelaySec though.
                                ===> This condition can be true.
                                /* This is a one time trigger, disable it now */
                                v->disabled = true;
                                continue;
                        }
                        ...
                        found_monotonic = true;  <<=== never come here for TIMER_BOOT.
                }
        }

        if (!found_monotonic && !found_realtime) {
                log_unit_debug(UNIT(t)->id, "%s: Timer is elapsed.", UNIT(t)->id);    ====> changed into elapsed.
                timer_set_state(t, TIMER_ELAPSED);
                return;
        }

        if (found_monotonic) {
                char buf[FORMAT_TIMESPAN_MAX];

                add_random(t, &t->next_elapse_monotonic_or_boottime);

                log_unit_debug(UNIT(t)->id, "%s: Monotonic timer elapses in %s.",
                               UNIT(t)->id,
                               format_timespan(buf, sizeof(buf), t->next_elapse_monotonic_or_boottime > ts_monotonic ? t->next_elapse_monotonic_or_boottime - ts_monotonic : 0, 0));


The following is some logs with systemd debug enabled.

Feb 26 16:37:44 localhost.localdomain systemd[1]: Reloading.
Feb 26 16:37:44 localhost.localdomain systemd[1]: test.timer changed dead -> waiting
Feb 26 16:37:44 localhost.localdomain systemd[1]: Adding 56.902878s random time.
Feb 26 16:37:44 localhost.localdomain systemd[1]: test.timer: Monotonic timer elapses in 1min 2.334852s.  
                                                                        <=== 1min has passed from boot time after about 6secs (62-56)

Feb 26 16:37:46 localhost.localdomain systemd[1]: Reloading.
Feb 26 16:37:46 localhost.localdomain systemd[1]: test.timer changed dead -> waiting
Feb 26 16:37:46 localhost.localdomain systemd[1]: Adding 31.339812s random time.
Feb 26 16:37:46 localhost.localdomain systemd[1]: test.timer: Monotonic timer elapses in 34.425015s.
                                                                        <=== 1min has passed from boot time after about 3secs (34-31)
Feb 26 16:37:48 localhost.localdomain systemd[1]: Reloading.
Feb 26 16:37:48 localhost.localdomain systemd[1]: test.timer changed dead -> waiting
Feb 26 16:37:49 localhost.localdomain systemd[1]: Adding 27.904076s random time.
Feb 26 16:37:49 localhost.localdomain systemd[1]: test.timer: Monotonic timer elapses in 28.503233s. 
                                                                        <=== 1min has passed from boot time after about 1sec (28-27)

   ****  1min has passed from boot time ****

Feb 26 16:37:51 localhost.localdomain systemd[1]: Reloading.
Feb 26 16:37:51 localhost.localdomain systemd[1]: test.timer changed dead -> waiting
Feb 26 16:37:51 localhost.localdomain systemd[1]: test.timer: Timer is elapsed.          <<======= no message to add random time here.
Feb 26 16:37:51 localhost.localdomain systemd[1]: test.timer changed waiting -> elapsed

Clearer steps to reproduce the problem:

1) /etc/systemd/system/test.timer and /etc/systemd/system/test.service
 
# systemctl cat test.timer test.service
# /etc/systemd/system/test.timer
[Unit]
Description=test timer

[Timer]
RandomizedDelaySec=1m
OnBootSec=1m
OnUnitInactiveSec=15m

[Install]
WantedBy=timers.target

# /etc/systemd/system/test.service
[Unit]
Description=test timer service

[Service]
Type=oneshot
ExecStart=/bin/sleep 10


2) Reboot

3) Check the boot time.

# systemctl show |grep ^FinishTimestamp

Or check the elapsed time from boot

# uptime

4) check the scheduled time for next trigger.

# systemctl list-timers | grep test.timer

5) run "systemctl daemon-reload" before the first run of the timer.service after 1m has passed from boot time.

6) check the status of test.timer with "systemctl status test.timer".
and, check the next run is not scheduled with "systemctl list-timers | grep test.timer".

Red Hat Enterprise Linux 7 shipped it's final minor release on September 29th, 2020. 7.9 was the last minor releases scheduled for RHEL 7.
From intial triage it does not appear the remaining Bugzillas meet the inclusion criteria for Maintenance Phase 2 and will now be closed. 

From the RHEL life cycle page:
https://access.redhat.com/support/policy/updates/errata#Maintenance_Support_2_Phase
"During Maintenance Support 2 Phase for Red Hat Enterprise Linux version 7,Red Hat defined Critical and Important impact Security Advisories (RHSAs) and selected (at Red Hat discretion) Urgent Priority Bug Fix Advisories (RHBAs) may be released as they become available."

If this BZ was closed in error and meets the above criteria please re-open it flag for 7.9.z, provide suitable business and technical justifications, and follow the process for Accelerated Fixes:
https://source.redhat.com/groups/public/pnt-cxno/pnt_customer_experience_and_operations_wiki/support_delivery_accelerated_fix_release_handbook  

Feature Requests can re-opened and moved to RHEL 8 if the desired functionality is not already present in the product. 

Please reach out to the applicable Product Experience Engineer[0] if you have any questions or concerns.  

[0] https://bugzilla.redhat.com/page.cgi?id=agile_component_mapping.html&product=Red+Hat+Enterprise+Linux+7

fix merged to github master branch -> https://github.com/systemd-rhel/rhel-7/pull/130

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (systemd bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:0351