Recurring Logic next occurence is older than last occurence

Problem:
We have several Recurring Logics to automatically run some commands on multiple host_collections.
After running this morning on several of the RLs the Next occurrence is older than the Last occurrence

$ hammer recurring-logic info --id 24 --fields 'Id,Last occurrence,Next occurrence'
ID:              24
Last occurrence: 2021-11-24 08:30:12 UTC
Next occurrence: 2021-11-24 08:30:00 UTC

$ hammer recurring-logic info --id 26 --fields 'Id,Last occurrence,Next occurrence'
ID:              26
Last occurrence: 2021-11-24 08:15:11 UTC
Next occurrence: 2021-11-24 08:15:00 UTC

Expected outcome:
Something like this:

$ hammer recurring-logic info --id 24 --fields 'Id,Last occurrence,Next occurrence'
ID:              24
Last occurrence: 2021-11-24 08:30:12 UTC
Next occurrence: 2021-11-25 08:30:00 UTC

$ hammer recurring-logic info --id 26 --fields 'Id,Last occurrence,Next occurrence'
ID:              26
Last occurrence: 2021-11-24 08:15:11 UTC
Next occurrence: 2021-11-25 08:15:00 UTC

$ hammer recurring-logic info --id 27 --fields 'Id,Last occurrence,Next occurrence'
ID:              27
Last occurrence: 2021-11-24 08:30:13 UTC
Next occurrence: 2021-11-24 08:30:00 UTC

Foreman and Proxy versions:
Foreman version: 3.0.1

Foreman and Proxy plugin versions:
Plugins:

  • foreman-tasks 5.1.1
  • foreman_puppet 1.0.5
  • foreman_remote_execution 4.7.0
  • katello 4.2.1

Distribution and version:
CentOS Linux release 7.9.2009 (Core)

Other relevant data:
We had this issue about a month ago and we ended disabling the old RLs and created new ones.

Database info:

foreman=# select * from foreman_tasks_recurring_logics where id in (24,26,27);
 id |    cron_line    | end_time | max_iteration | iteration | task_group_id | state  | triggering_id | purpose 
----+-----------------+----------+---------------+-----------+---------------+--------+---------------+---------
 24 | 30 08 * * *     |          |               |        40 |           974 | active |           110 | 
 27 | 30 08 * * *     |          |               |        40 |           980 | active |           113 | 
 26 | 15 8 2-31/2 * * |          |               |        20 |           978 | active |           112 | 
(3 rows)

foreman=# select * from foreman_tasks_triggerings where id in (select triggering_id from foreman_tasks_recurring_logics where id in (24,26,27));
 id  |   mode    |          start_at          | start_before 
-----+-----------+----------------------------+--------------
 110 | recurring | 2021-10-15 15:36:09.369358 | 
 112 | recurring | 2021-10-15 15:44:36.952605 | 
 113 | recurring | 2021-10-15 15:46:01.406246 | 
(3 rows)

We also double checked and all the task of this morning finished successfully.

$ hammer task info --id c20ed7f6-eed9-4593-9efa-7410d07359c8 # RL 24
ID:          c20ed7f6-eed9-4593-9efa-7410d07359c8
Action:      Run hosts job: Run yum update -y
State:       stopped
Result:      success
Started at:  2021/11/24 08:30:12
Ended at:    2021/11/24 08:30:23
Owner:       ams
Task errors:

$ hammer task info --id 3d0bf172-b5e7-4e56-a20a-c957ca6dd437 # RL 26
ID:          3d0bf172-b5e7-4e56-a20a-c957ca6dd437
Action:      Run hosts job: Run yum update -y; needs-restarting -r; if [ "$(echo $?)" -eq "1" ]; then shutdown -r 1 ; fi
State:       stopped
Result:      success
Started at:  2021/11/24 08:15:11
Ended at:    2021/11/24 08:15:22
Owner:       ams
Task errors:

Although none failed the execution of RL 26 did not for any host - we made no changes to the host_collection

Description 	Search Query 	Status 	Succeeded 	Failed 	Pending 	Total hosts 	Start
Run yum update -y; needs-restarting -r; if [ "$(echo $?)" -eq "1" ]; then shu... 	host_collect... 	succeeded 	0 	0 	0 	0 	about 10 hours ago
Run yum update -y; needs-restarting -r; if [ "$(echo $?)" -eq "1" ]; then shu... 	host_collect... 	failed 	6 	1 	0 	7 	2 days ago
Run yum update -y; needs-restarting -r; if [ "$(echo $?)" -eq "1" ]; then shu... 	host_collect... 	failed 	6 	1 	0 	7 	4 days ago
Run yum update -y; needs-restarting -r; if [ "$(echo $?)" -eq "1" ]; then shu... 	host_collect... 	succeeded 	6 	0 	0 	6 	6 days ago
hammer host-collection info --id 4
Id:          4
Name:        auto-update-and-reboot-even-days
Limit:       None
Description: 
Total Hosts: 7

Hi,
since task c20ed7f6-eed9-4593-9efa-7410d07359c8 finished, RL 24 should have a new scheduled task. Does it have it? If not, are there any errors from around that time in production.log?

Hi,

I don’t thing I have scheduled task for each of those RLs because a day has gone by and neither the Last occurrence or the Next occurrence` have changed.

I got these messages on production.log

$ grep 2021-11-24T08 /var/log/foreman/production.log| grep d53e7f2d
2021-11-24T08:30:12 [I|bac|d53e7f2d] Task {label: Actions::RemoteExecution::RunHostsJob, id: c20ed7f6-eed9-4593-9efa-7410d07359c8, execution_plan_id: b096bad9-b0a0-4c2f-93da-899dab8a98c2} state changed: planning 
2021-11-24T08:30:13 [I|bac|d53e7f2d] Task {label: Actions::RemoteExecution::RunHostsJob, id: c20ed7f6-eed9-4593-9efa-7410d07359c8, execution_plan_id: b096bad9-b0a0-4c2f-93da-899dab8a98c2} state changed: planned 
2021-11-24T08:30:13 [E|dyn|d53e7f2d] Failed to run hook 'trigger_repeat' for action 'Actions::RemoteExecution::RunHostsJob'
2021-11-24T08:30:13 [I|bac|d53e7f2d] Task {label: Actions::RemoteExecution::RunHostsJob, id: c20ed7f6-eed9-4593-9efa-7410d07359c8, execution_plan_id: b096bad9-b0a0-4c2f-93da-899dab8a98c2} state changed: running 
2021-11-24T08:30:13 [W|app|d53e7f2d] Scoped order is ignored, it's forced to be batch order.
2021-11-24T08:30:13 [W|app|d53e7f2d] Scoped order is ignored, it's forced to be batch order.
2021-11-24T08:30:23 [I|bac|d53e7f2d] Task {label: Actions::RemoteExecution::RunHostsJob, id: c20ed7f6-eed9-4593-9efa-7410d07359c8, execution_plan_id: b096bad9-b0a0-4c2f-93da-899dab8a98c2} state changed: stopped  result: success
2021-11-24T08:30:23 [I|bac|d53e7f2d] Task {label: Actions::RemoteExecution::RunHostsJob, id: c20ed7f6-eed9-4593-9efa-7410d07359c8, execution_plan_id: b096bad9-b0a0-4c2f-93da-899dab8a98c2} state changed: stopped  result: success

For all the other RLs the logs are similar (the only changes are the timestamps and ids).

This is it. It failed to prepare the next run. Sadly it doesn’t say why. Anything in output of journalctl -u dynflow-sidekiq@\*?

Hi,

For the 24th I’ve got this:

Nov 24 02:00:37 updates.example.com systemd[1]: Stopping Foreman jobs daemon - worker-hosts-queue-1 on sidekiq...
Nov 24 02:00:37 updates.example.com systemd[1]: Stopping Foreman jobs daemon - worker-1 on sidekiq...
Nov 24 02:00:39 updates.example.com systemd[1]: Stopped Foreman jobs daemon - worker-hosts-queue-1 on sidekiq.
Nov 24 02:00:40 updates.example.com systemd[1]: Stopped Foreman jobs daemon - worker-1 on sidekiq.
Nov 24 02:00:40 updates.example.com systemd[1]: Stopping Foreman jobs daemon - orchestrator on sidekiq...
Nov 24 02:00:42 updates.example.com systemd[1]: Stopped Foreman jobs daemon - orchestrator on sidekiq.
Nov 24 02:01:55 updates.example.com systemd[1]: Starting Foreman jobs daemon - orchestrator on sidekiq...
Nov 24 02:02:01 updates.example.com dynflow-sidekiq@orchestrator[70090]: 2021-11-24T02:02:01.645Z 70090 TID-1izi INFO: GitLab reliable fetch activated!
Nov 24 02:02:01 updates.example.com dynflow-sidekiq@orchestrator[70090]: 2021-11-24T02:02:01.706Z 70090 TID-1izm INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-70090", :url=>"redis://localhost:6379/0"}
Nov 24 02:02:16 updates.example.com dynflow-sidekiq@orchestrator[70090]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-1.0.4/lib/foreman_puppet/register.rb:141: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Nov 24 02:02:16 updates.example.com dynflow-sidekiq@orchestrator[70090]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Nov 24 02:02:34 updates.example.com systemd[1]: Started Foreman jobs daemon - orchestrator on sidekiq.
Nov 24 02:02:34 updates.example.com systemd[1]: Starting Foreman jobs daemon - worker-1 on sidekiq...
Nov 24 02:02:34 updates.example.com systemd[1]: Starting Foreman jobs daemon - worker-hosts-queue-1 on sidekiq...
Nov 24 02:02:36 updates.example.com dynflow-sidekiq@worker-1[71156]: 2021-11-24T02:02:36.025Z 71156 TID-1i74 INFO: GitLab reliable fetch activated!
Nov 24 02:02:36 updates.example.com dynflow-sidekiq@worker-1[71156]: 2021-11-24T02:02:36.026Z 71156 TID-1i70 INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-71156", :url=>"redis://localhost:6379/0"}
Nov 24 02:02:36 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[71169]: 2021-11-24T02:02:36.070Z 71169 TID-1i1h INFO: GitLab reliable fetch activated!
Nov 24 02:02:36 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[71169]: 2021-11-24T02:02:36.071Z 71169 TID-1i21 INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-71169", :url=>"redis://localhost:6379/0"}
Nov 24 02:02:44 updates.example.com dynflow-sidekiq@worker-1[71156]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-1.0.4/lib/foreman_puppet/register.rb:141: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Nov 24 02:02:44 updates.example.com dynflow-sidekiq@worker-1[71156]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Nov 24 02:02:44 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[71169]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-1.0.4/lib/foreman_puppet/register.rb:141: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Nov 24 02:02:44 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[71169]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Nov 24 02:02:58 updates.example.com systemd[1]: Started Foreman jobs daemon - worker-1 on sidekiq.
Nov 24 02:02:58 updates.example.com systemd[1]: Started Foreman jobs daemon - worker-hosts-queue-1 on sidekiq.
Nov 24 17:06:14 updates.example.com systemd[1]: Stopping Foreman jobs daemon - worker-hosts-queue-1 on sidekiq...
Nov 24 17:06:16 updates.example.com systemd[1]: Stopped Foreman jobs daemon - worker-hosts-queue-1 on sidekiq.
Nov 24 17:06:16 updates.example.com systemd[1]: Starting Foreman jobs daemon - worker-hosts-queue-1 on sidekiq...
Nov 24 17:06:18 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[16987]: 2021-11-24T17:06:18.543Z 16987 TID-dsf INFO: GitLab reliable fetch activated!
Nov 24 17:06:18 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[16987]: 2021-11-24T17:06:18.544Z 16987 TID-dtf INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-16987", :url=>"redis://localhost:6379/0"}
Nov 24 17:06:27 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[16987]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-1.0.5/lib/foreman_puppet/register.rb:141: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Nov 24 17:06:27 updates.example.com dynflow-sidekiq@worker-hosts-queue-1[16987]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Nov 24 17:06:41 updates.example.com systemd[1]: Started Foreman jobs daemon - worker-hosts-queue-1 on sidekiq.
Nov 24 17:07:09 updates.example.com systemd[1]: Stopping Foreman jobs daemon - orchestrator on sidekiq...
Nov 24 17:07:10 updates.example.com systemd[1]: Stopped Foreman jobs daemon - orchestrator on sidekiq.
Nov 24 17:07:10 updates.example.com systemd[1]: Starting Foreman jobs daemon - orchestrator on sidekiq...
Nov 24 17:07:12 updates.example.com dynflow-sidekiq@orchestrator[17477]: 2021-11-24T17:07:12.632Z 17477 TID-de9 INFO: GitLab reliable fetch activated!
Nov 24 17:07:12 updates.example.com dynflow-sidekiq@orchestrator[17477]: 2021-11-24T17:07:12.633Z 17477 TID-df1 INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-17477", :url=>"redis://localhost:6379/0"}
Nov 24 17:07:21 updates.example.com dynflow-sidekiq@orchestrator[17477]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-1.0.5/lib/foreman_puppet/register.rb:141: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Nov 24 17:07:21 updates.example.com dynflow-sidekiq@orchestrator[17477]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Nov 24 17:07:36 updates.example.com systemd[1]: Started Foreman jobs daemon - orchestrator on sidekiq.
Nov 24 17:07:37 updates.example.com systemd[1]: Stopping Foreman jobs daemon - worker-1 on sidekiq...
Nov 24 17:07:38 updates.example.com systemd[1]: Stopped Foreman jobs daemon - worker-1 on sidekiq.
Nov 24 17:07:38 updates.example.com systemd[1]: Starting Foreman jobs daemon - worker-1 on sidekiq...
Nov 24 17:07:40 updates.example.com dynflow-sidekiq@worker-1[17616]: 2021-11-24T17:07:40.449Z 17616 TID-dac INFO: GitLab reliable fetch activated!
Nov 24 17:07:40 updates.example.com dynflow-sidekiq@worker-1[17616]: 2021-11-24T17:07:40.451Z 17616 TID-dbs INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-17616", :url=>"redis://localhost:6379/0"}
Nov 24 17:07:49 updates.example.com dynflow-sidekiq@worker-1[17616]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-1.0.5/lib/foreman_puppet/register.rb:141: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Nov 24 17:07:49 updates.example.com dynflow-sidekiq@worker-1[17616]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Nov 24 17:08:02 updates.example.com systemd[1]: Started Foreman jobs daemon - worker-1 on sidekiq.

Everyday at 2AM we stop foreman to execute a foreman-maintain backup offline ...
The stop/start after 5PM was done because when we’re trying to debug this issue we noticed that we had somes updates, installed then we ran foreman-installer

    Updated tfm-rubygem-foreman-tasks-5.1.0-1.fm3_0.el7.noarch  @foreman-plugins
    Update                            5.1.1-1.fm3_0.el7.noarch  @foreman-plugins
    Updated tfm-rubygem-foreman_puppet-1.0.4-1.fm3_0.el7.noarch @foreman-plugins
    Update                             1.0.5-1.fm3_0.el7.noarch @foreman-plugins
    Updated tfm-rubygem-hammer_cli-3.0.0-1.el7.noarch           @foreman
    Update                         3.0.1-1.el7.noarch           @foreman