Bug 1721055 - Hourly Scheduled sync plan executed every minute on upgraded Satellite VM's(6.4.z to 6.5 GA).
Summary: Hourly Scheduled sync plan executed every minute on upgraded Satellite VM's(6...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite 6
Classification: Red Hat
Component: Sync Plans
Version: 6.5.0
Hardware: x86_64
OS: Linux
unspecified
high vote
Target Milestone: 6.6.0
Assignee: Samir Jha
QA Contact: Stephen Wadeley
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-06-17 08:45 UTC by Devendra Singh
Modified: 2019-10-22 12:47 UTC (History)
6 users (show)

Fixed In Version: tfm-rubygem-foreman-tasks-0.15.5.1-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1726825 (view as bug list)
Environment:
Last Closed: 2019-10-22 12:47:39 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Foreman Issue Tracker 27091 Normal Closed Hourly Scheduled sync plan executed every minute on upgraded Satellite VM's(6.4.z to 6.5 GA). 2019-12-16 08:45:06 UTC
Red Hat Product Errata RHSA-2019:3172 None None None 2019-10-22 12:47:49 UTC

Description Devendra Singh 2019-06-17 08:45:43 UTC
Description of problem: Hourly Scheduled sync plan executed every minute on upgraded Satellite VM's(6.4.z to 6.5 GA).

Version-Release number of selected component (if applicable):
6.5

How reproducible:
frequently

Steps to Reproduce:
1. Created a 6.5 Satellite and Capsule templates from 6.4 Successfully.
2. By Using Step1 template created Satellite and Capsule VM.
3. Both VM's were running & upstate and had hourly, daily and weekly sync plan.
4. Restarted Katello services on both machines. 
5. Sync plan was already scheduled.
# hammer sync-plan list --organization="Default Organization"
---|-------|---------------------|----------|---------|-----------------|-------------------
ID | NAME  | START DATE          | INTERVAL | ENABLED | CRON EXPRESSION | RECURRING LOGIC ID
---|-------|---------------------|----------|---------|-----------------|-------------------
1  | sync1 | 2018/11/13 11:11:00 | hourly   | yes     |                 | 4                 
2  | sync2 | 2018/11/13 10:12:00 | daily    | yes     |                 | 5                 
3  | sync3 | 2018/11/13 10:13:00 | weekly   | yes     |                 | 6                 
---|-------|---------------------|----------|---------|-----------------|-------------------
hourly sync plan had the following info :
# hammer sync-plan info --organization="Default Organization" --id=1
ID:                 1
Name:               sync1
Start Date:         2018/11/13 11:11:00
Interval:           hourly
Enabled:            yes
Cron Expression:    
Recurring Logic ID: 4
Description:        
Created at:         2018/11/13 08:11:42
Updated at:         2019/05/15 10:00:41
Products:           
 1) ID:   2
    Name: Red Hat Software Collections (for RHEL Server)


Sync Status:

41306341-d6d1-457c-ac3d-f0f009793008 | Run Sync Plan: sync1       | stopped   | success | 2019/06/17 08:06:51 | 2019/06/17 08:07:05 |                   |                                                          c0554bf8-c9ee-4618-95c1-d592d28d42d2 | Run Sync Plan: sync1       | stopped   | success | 2019/06/17 08:06:35 | 2019/06/17 08:06:49 |                   |                                                          c06c0964-755e-444f-b600-ccac403be7b4 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:06:18 | 2019/06/17 08:06:33 |                   |                                                           3cba03c1-144c-4044-9162-91115df47795 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:06:02 | 2019/06/17 08:06:17 |                   |                                                           49c5ccd7-d17a-446f-bbba-70ca5c5771c3 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:05:46 | 2019/06/17 08:06:01 |                   |                                                           5be9408e-9774-4e40-82b0-30aeed6ff8f6 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:05:30 | 2019/06/17 08:05:43 |                   |                                                           6545a7bc-5864-49d6-82ee-175e257b0dee | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:05:14 | 2019/06/17 08:05:29 |                   |                                                           826721fd-bf38-4c27-92f9-0075175abe94 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:04:58 | 2019/06/17 08:05:11 |                   |                                                           cfbb9eb5-9c0f-4a5f-8fd5-30bc8e4f1347 | Run Sync Plan: sync1      | stopped   | error   | 2019/06/17 08:04:42 | 2019/06/17 08:04:42 |                   | Required lock is already taken by other running tasks.
db39bd6d-2154-4065-8c17-39ee50ee0e16 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:04:26 | 2019/06/17 08:04:49 |                   |                                                           e523963e-b664-4dbc-ae94-2849161509c0 | Run Sync Plan: sync1      | stopped   | error   | 2019/06/17 08:04:10 | 2019/06/17 08:04:10 |                   | Required lock is already taken by other running tasks.
53f692c5-de66-45b0-b607-1b52a58ac19c | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:03:54 | 2019/06/17 08:04:13 |                   |                                                           55a4f550-4681-4f03-ac1c-fca6b739c148 | Run Sync Plan: sync1      | stopped   | error   | 2019/06/17 08:03:38 | 2019/06/17 08:03:38 |                   | Required lock is already taken by other running tasks.
33eb8c2e-5801-44c7-ac76-36ade9ed52b8 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:03:22 | 2019/06/17 08:03:47 |                   |                                                           7c9fe850-9908-4804-b73d-d2cf41f346b1 | Run Sync Plan: sync1      | stopped   | error   | 2019/06/17 08:03:06 | 2019/06/17 08:03:06 |                   | Required lock is already taken by other running tasks.
854354e2-37ea-4ca6-89bd-f8d0040332e0 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:02:50 | 2019/06/17 08:03:07 |                   |                                                           8780fb7f-49bf-4039-a253-6bd431cb2381 | Run Sync Plan: sync1      | stopped   | success | 2019/06/17 08:02:34 | 2019/06/17 08:02:47 |                      


Actual results:
Hourly scheduled sync plan executed every minute.

Expected results:
The scheduled task should be executed at the scheduled time.

Additional info:
After resaving the sync plan problem get resolved, This is one observation.

Comment 7 Samir Jha 2019-06-17 15:55:46 UTC
What I understand from the tasks logs is that the server was off for some days after upgrade. The current behavior is that if we have a recurring logic in place and the server is down, whenever the server comes up, the recurring logic runs the task as many times was missed in the period the server was down. That is what you are seeing on the server above.

Comment 8 vijsingh 2019-06-18 05:09:35 UTC
(In reply to Samir Jha from comment #7)
> What I understand from the tasks logs is that the server was off for some
> days after upgrade. The current behavior is that if we have a recurring
> logic in place and the server is down, whenever the server comes up, the
> recurring logic runs the task as many times was missed in the period the
> server was down. That is what you are seeing on the server above.

I have below queries on same:

1. Why sync plan execute in every min for pending recurring logic even sync plan scheduled for every hour? 

2. Also if server is down then it should keep one 'recurring logic' same job/syncplan and run after up however keeping all('recurring logic') still does not make much worth here ? what do you think ?

2. After resaving the sync plan problem get resolved , so how that remove the recurring logic ?

Comment 9 Samir Jha 2019-06-18 14:22:02 UTC
> 1. Why sync plan execute in every min for pending recurring logic even sync plan scheduled for every hour? 

Since, the server was down for a while, the sync plan(with a scheduled task in the background) picks up the task with a backdated start date and runs it as many times it was missed while the server was down.

> Also if server is down then it should keep one 'recurring logic' same job/syncplan and run after up however keeping all('recurring logic') still does not make much worth here ? what do you think ?
That does sound like the behavior we should lean towards for sync plans specifically. I will defer to Ivan/Adam to verify the behavior of running all missed scheduled tasks for recurring logic on server start.

> 2. After resaving the sync plan problem get resolved , so how that remove the recurring logic ?

For some fields on sync plan, updating it causes a new recurring logic to get created and the old one is cancelled along with the scheduled job tied to it. Once, the scheduled job is cancelled, the pending tasks for the job don't run anymore.

Comment 10 vijsingh 2019-06-18 15:01:16 UTC
(In reply to Samir Jha from comment #9)
> > 1. Why sync plan execute in every min for pending recurring logic even sync plan scheduled for every hour? 
> 
> Since, the server was down for a while, the sync plan(with a scheduled task
> in the background) picks up the task with a backdated start date and runs it
> as many times it was missed while the server was down.
> 
Might be I am missing something , But imagine if a syncplan has 20+ or more repos .. then there would more tasks in pending list if it picks in every mins in such scenarios.

Comment 11 Samir Jha 2019-06-18 15:51:25 UTC
Yes..The Sync Plan run is the parent task and individual repo syncs are the sub-tasks for it. You can see all the child repo syncs in the dynflow console for the job that is scheduled in this case. It's not necessarily every minute though, it runs the task as many times it was skipped one by one. Once it's done running the skipped number of times, it settles back to it's intended schedule.

Comment 12 Samir Jha 2019-06-20 20:33:10 UTC
Created redmine issue http://projects.theforeman.org/issues/27091 from this bug

Comment 14 Bryan Kearney 2019-06-21 16:05:19 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue https://projects.theforeman.org/issues/27091 has been resolved.

Comment 19 errata-xmlrpc 2019-10-22 12:47:39 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, 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/RHSA-2019:3172


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