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
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.)
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
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
PR issued for this: https://github.com/pulp/pulp/pull/612
Fix merged in, in commit 51c93ef6371dfb57b12f917e4b2d1103354a5720
build: 2.3.0-0.14.alpha
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
Pulp 2.3 released.