Bug 968524

Summary: Repeating scheduled tasks do not run after the first one is completed, claiming that the first one is in progress
Product: [Retired] Pulp Reporter: Randy Barlow <rbarlow>
Component: async/tasksAssignee: Jason Connor <jconnor>
Status: CLOSED CURRENTRELEASE QA Contact: Preethi Thomas <pthomas>
Severity: high Docs Contact:
Priority: high    
Version: MasterCC: jason.dobies, jgreenleaf, mhrivnak, mmccune, skarmark
Target Milestone: ---Keywords: Triaged
Target Release: 2.3.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-12-09 14:31:11 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
A dump of my scheduled calls collecction none

Description Randy Barlow 2013-05-29 20:00:24 UTC 
I created an ISO repository, and scheduled it to sync every minute. The first sync completed successfully, according to the logs and the tasks list command in the CLI. However, the subsequent scheduled syncs would not run, claiming that the previously scheduled syncs were not complete.

Here are steps to reproduce:

$ pulp-admin iso repo create --repo-id test --feed http://pkilambi.fedorapeople.org/test_file_repo/

$ pulp-admin iso repo schedules create -s 2013-05-29T19:51:00Z/PT1M --repo-id test
Schedule successfully created

That creates an ISO repository that will sync with a small test repo with a few MBs of ISOs in it. It will then create a schedule that starts at 15:51 EDT and runs a sync once per minute. I had already sync'd this repository before, so the sync operation is very fast, and according to the logs it does complete inside of the first minute. Here are the logs:

2013-05-29 15:50:04,186 pulp.server.dispatch.task:INFO: SUCCESS: Task dd429766-0474-46ff-809f-12b843d5f9f6: CallRequest: AggregateScheduleManager.create_sync_schedule(u'test1', u'iso_importer', {'override_config': {}}, {'schedule': '2013-05-29T19:51:00Z/PT1M', 'enabled': True, 'failure_threshold': None})
2013-05-29 15:51:10,564 pulp.server.dispatch.task:INFO: SUCCESS: Task 210aad37-fffb-4620-986f-4f60f5a1d54a: CallRequest: sync_with_auto_publish_itinerary(u'test1', overrides={})
2013-05-29 15:51:10,627 pulp.server.dispatch.scheduler:INFO: Scheduled CallRequest: RepoSyncManager.sync(u'test1', sync_config_override={}): accepted [reasons: []]
2013-05-29 15:51:10,628 pulp.server.dispatch.scheduler:INFO: Scheduled CallRequest: RepoPublishManager.publish(u'test1', u'iso_distributor'): accepted [reasons: []]
2013-05-29 15:51:10,771 pulp.server.dispatch.task:INFO: SUCCESS: Task c27de872-5465-45fb-89de-159740484da8: CallRequest: RepoSyncManager.sync(u'test1', sync_config_override={})
2013-05-29 15:51:11,187 pulp_rpm.plugins.distributors.iso_distributor.publish:INFO: Beginning publish for repository <test1>
2013-05-29 15:51:11,207 pulp.server.dispatch.task:INFO: SUCCESS: Task 1e34f1ca-8177-44c9-bd83-f52042152c32: CallRequest: RepoPublishManager.publish(u'test1', u'iso_distributor')
2013-05-29 15:51:40,639 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running
2013-05-29 15:52:10,648 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running
2013-05-29 15:53:10,660 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running
2013-05-29 15:54:10,671 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running
2013-05-29 15:55:10,676 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running
2013-05-29 15:56:10,682 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running
2013-05-29 15:57:10,692 pulp.server.dispatch.scheduler:INFO: Schedule 51a65becb1a8a117eda36e10 skipped: last scheduled call still running

As you can see, the first sync finished at 15:51:11 EDT, leaving 39 seconds until the next one should have started. When it came time for the next one to start, there was an info message in the log that the last scheduled call was still running.

According to the tasks section, that sync is finished:

$ pulp-admin tasks list
+----------------------------------------------------------------------+
                                 Tasks
+----------------------------------------------------------------------+

Operations:  auto_publish, publish
Resources:   test (repository)
State:       Successful
Start Time:  2013-05-29T19:51:11Z
Finish Time: 2013-05-29T19:51:11Z
Result:      N/A
Task Id:     1e34f1ca-8177-44c9-bd83-f52042152c32

Also, according to the schedule list on the repo, it completed successfully:

$ pulp-admin iso repo schedules list --repo-id test
+----------------------------------------------------------------------+
                               Schedules
+----------------------------------------------------------------------+

Schedule: 2013-05-29T19:51:00Z/PT1M
Id:       51a65becb1a8a117eda36e10
Enabled:  True
Last Run: 2013-05-29T19:51:00Z
Next Run: 2013-05-29T19:53:00Z
Comment 1 Randy Barlow 2013-05-29 20:01:59 UTC 
Note also that the first attempted repeat of the sync happened too early, at 15:51:40 (it shouldn't have tried until 15:52 or later.)
Comment 2 Jason Connor 2013-07-30 19:35:08 UTC 
RAW DATA PASTE OF TRACEBACK AFTER SCHEDULE CREATION:

2013-07-29 15:13:41,009 pulp.server.dispatch.task:INFO: SUCCESS: Task 074b3e20-9834-445c-bf1c-fe3eac3fa104: CallRequest: AggregateScheduleManager.create_sync_schedule(u'bt_laser', u'yum_importer', {'overri
de_config': {}}, {'schedule': '2013-07-29T10:50:00/P5M', 'enabled': True, 'failure_threshold': None})
2013-07-29 15:14:31,306 pulp.server.webservices.middleware.exception:ERROR: Missing resource(s): resource_id=074b3e20-9834-445c-bf1c-fe3eac3fa104
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/middleware/exception.py", line 44, in __call__
    return self.app(environ, start_response)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/middleware/postponed.py", line 39, in __call__
    return self.app(environ, start_response)
  File "/usr/lib/python2.6/site-packages/web/application.py", line 279, in wsgi
    result = self.handle_with_processors()
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 26, in _handle_with_processors
    return process(self.processors)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in process
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/web/application.py", line 566, in processor
    return handler()
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in <lambda>
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in process
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/web/application.py", line 581, in processor
    result = handler()
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in <lambda>
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 25, in process
    return self.handle()
  File "/usr/lib/python2.6/site-packages/web/application.py", line 230, in handle
    return self._delegate(fn, self.fvars, args)
  File "/usr/lib/python2.6/site-packages/web/application.py", line 422, in _delegate
    return f()
  File "/usr/lib/python2.6/site-packages/web/application.py", line 430, in <lambda>
    f = lambda: self._delegate_sub_application(pat, what)
  File "/usr/lib/python2.6/site-packages/web/application.py", line 455, in _delegate_sub_application
    return app.handle_with_processors()
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 26, in _handle_with_processors
    return process(self.processors)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in process
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/web/application.py", line 566, in processor
    return handler()
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in <lambda>
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in process
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/web/application.py", line 581, in processor
    result = handler()
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 23, in <lambda>
    return p(lambda : process(processors))
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 25, in process
    return self.handle()
  File "/usr/lib/python2.6/site-packages/web/application.py", line 230, in handle
    return self._delegate(fn, self.fvars, args)
  File "/usr/lib/python2.6/site-packages/web/application.py", line 405, in _delegate
    return handle_class(f)
  File "/usr/lib/python2.6/site-packages/web/application.py", line 396, in handle_class
    return tocall(*args)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/decorators.py", line 231, in _auth_decorator
    value = method(self, *args, **kwargs)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/dispatch.py", line 108, in DELETE
    raise MissingResource(call_request_id)
MissingResource: Missing resource(s): resource_id=074b3e20-9834-445c-bf1c-fe3eac3fa104
Comment 3 Jim 2013-07-30 19:45:22 UTC 
Created attachment 780822 [details]
A dump of my scheduled calls collecction

A dump of my scheduled calls collection for linear from IRC

[13:31] <xenophon> Is this the right syntax for scheduling a periodic sync? pulp doesn't seem to reschedule it after running it once.... "pulp-admin rpm repo sync schedules create -s '2013-07-29T15:20:00/P5M' --repo-id=bt_laser"
[14:22] <mhrivnak> linear, ^
[14:25] <linear> xenophon: that is the correct syntax
[14:26] <linear> there's currently a bug filled against that, that we're going to look at next sprint
[14:27] <linear> though, xenophon, that syntax schedules the sync for once every 5 months
[14:27] <linear> is that what you're looking for?
[14:29] <xenophon> oh, no, that is not at all waht I was looking for
[14:29] <xenophon> is it a lower case m for minuets?
[14:29] <linear> no, there's a T divider for date and time
[14:30] <xenophon> also, I found this in /var/log/pulp/pulp.log: http://pastebin.com/LzsnRVNP
[14:30] <linear> if you're looking for every 5 minutes, the last part should be PT5M
[14:30] <xenophon> oh, thanks
[14:30] * linear looks
[14:31] <linear> yeah, no problem
[14:31] <linear> interesting traceback
[14:31] <linear> it looks like the schedule was created, but the REST API failed to find it for serialization
[14:32] <xenophon> weird... is there any more data I can get you?
[14:32] <linear> yeah, one sec
[14:33] <linear> xenophon: if you could get me a dump of the "scheduled_calls" collection in your mongo database
[14:33] <linear> that would be super helpful
Comment 4 Jason Connor 2013-09-13 20:43:08 UTC 
PR issued for this:
https://github.com/pulp/pulp/pull/612
Comment 5 Jason Connor 2013-09-17 21:36:10 UTC 
Fix merged in, in commit 51c93ef6371dfb57b12f917e4b2d1103354a5720
Comment 6 Jeff Ortel 2013-09-18 23:58:36 UTC 
build: 2.3.0-0.14.alpha
Comment 7 Preethi Thomas 2013-09-20 12:46:47 UTC 
verified
[root@pulp-v2-server ~]# rpm -qa pulp-server
pulp-server-2.3.0-0.14.alpha.el6.noarch
[root@pulp-v2-server ~]# 

[root@pulp-v2-server ~]# pulp-admin iso repo sync schedules list --repo-id test+----------------------------------------------------------------------+
                               Schedules
+----------------------------------------------------------------------+

Schedule: 2013-05-29T19:51:00Z/PT1M
Id:       523c4ef1d669f05dff000303
Enabled:  True
Last Run: 2013-09-20T13:59:00Z
Next Run: 2013-09-20T14:00:00Z


[root@pulp-v2-server ~]# pulp-admin rpm repo sync schedules list --repo-id zoo1
+----------------------------------------------------------------------+
                               Schedules
+----------------------------------------------------------------------+

Schedule: 2013-09-15T19:51:00Z/PT6M
Id:       523c5191d669f05dff00041d
Enabled:  True
Last Run: 2013-09-20T13:57:00Z
Next Run: 2013-09-20T14:03:00Z


[root@pulp-v2-server ~]# 

both these schedules have been running without any errors
Comment 8 Preethi Thomas 2013-12-09 14:31:11 UTC 
Pulp 2.3 released.