RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1764908 - systemd timers sometimes go "elapsed" after daemon reloads [rhel-7.9.z]
Summary: systemd timers sometimes go "elapsed" after daemon reloads [rhel-7.9.z]
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd
Version: 7.7
Hardware: x86_64
OS: Linux
urgent
medium
Target Milestone: rc
: ---
Assignee: David Tardon
QA Contact: Frantisek Sumsal
URL:
Whiteboard:
Depends On:
Blocks: 1899402
TreeView+ depends on / blocked
 
Reported: 2019-10-24 03:14 UTC by Sandeep MJ
Modified: 2024-03-25 15:28 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1899402 (view as bug list)
Environment:
Last Closed: 2021-02-02 12:08:30 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github systemd-rhel rhel-7 pull 130 0 None closed (#1764908) core: Detect initial timer state from serialized data 2021-02-03 00:17:29 UTC
Red Hat Product Errata RHBA-2021:0351 0 None None None 2021-02-02 12:08:35 UTC

Description Sandeep MJ 2019-10-24 03:14:22 UTC
Description of problem:
systemd timers sometimes shows as elapsed after reboots

Version-Release number of selected component (if applicable):
systemd-219-67.el7_7.2.x86_64

How reproducible:
Can trigger fairly reliably running daemon-reload a few times after rebooting

Steps to Reproduce:

---------
# /usr/lib/systemd/system/org-conf-apply-manifests.timer
[Unit]
Description=Runs org-conf and applies desired state configuration to the host

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

[Install]
WantedBy=timers.target
---------

---------
sudo systemctl cat org-conf-apply-manifests.service

# /usr/lib/systemd/system/org-conf-apply-manifests.service
[Unit]
Description=Runs org-conf and applies desired state configuration to the host
After=network-online.target org-conf-refresh-memberships.service
Wants=network-online.target
ConditionPathExists=/var/spool/org-conf/profile-and-tag-depency.mk

[Service]
Type=oneshot
ExecStart=/usr/sbin/org-conf-apply-manifests
---------

$ reboot

$ sudo systemctl list-timers org-conf-apply-manifests.timer

$ sudo systemctl status org-conf-apply-manifests.timer

NEXT                          LEFT     LAST PASSED UNIT                              ACTIVATES
Wed 2019-10-23 14:26:21 AEDT  12s left n/a  n/a    org-conf-apply-manifests.timer org-conf-apply-manifests.service
1 timers listed.
Pass --all to see loaded but inactive timers, too.
● org-conf-apply-manifests.timer - Runs org-conf and applies desired state configuration to the host
   Loaded: loaded (/usr/lib/systemd/system/org-conf-apply-manifests.timer; enabled; vendor preset: enabled)
   Active: active (waiting) since Wed 2019-10-23 14:25:19 AEDT; 50s ago

$ sudo systemctl daemon-reload

# Sometimes happens first time, sometimes takes multiple reloads - but can generally trigger it within a minute

$ sudo systemctl list-timers org-conf-apply-manifests.timer; sudo systemctl status org-conf-apply-manifests.timer;
NEXT LEFT LAST PASSED UNIT                              ACTIVATES
n/a  n/a  n/a  n/a    org-conf-apply-manifests.timer org-conf-apply-manifests.service

1 timers listed.
Pass --all to see loaded but inactive timers, too.
● org-conf-apply-manifests.timer - Runs org-conf and applies desired state configuration to the host
   Loaded: loaded (/usr/lib/systemd/system/org-conf-apply-manifests.timer; enabled; vendor preset: enabled)
   Active: active (elapsed) since Wed 2019-10-23 14:25:19 AEDT; 55s ago

Comment 2 Kyle Walker 2020-02-16 13:36:41 UTC
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?

Comment 3 nh2 2020-02-25 22:41:54 UTC
Likely corresponding upstream bug report:

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

Comment 4 Masahiro Matsuya 2020-02-26 08:40:43 UTC
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

Comment 5 Masahiro Matsuya 2020-02-26 09:02:28 UTC
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".

Comment 17 Chris Williams 2020-11-11 21:40:44 UTC
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

Comment 21 Lukáš Nykrýn 2021-01-15 17:52:55 UTC
fix merged to github master branch -> https://github.com/systemd-rhel/rhel-7/pull/130

Comment 31 errata-xmlrpc 2021-02-02 12:08:30 UTC
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


Note You need to log in before you can comment on or make changes to this bug.