Bug 782109

Description of problem:

Having a certain repository:

Id                      rhel-server-6-6Server-x86_64
Name                    Red Hat Enterprise Linux Server 6 (RPMs) (6Server-x86_64)
Repo URL                pulp.example.com
Feed URL                https://cdn.redhat.com/content/dist/rhel/rhui/server/6/6Server/x86_64/os
Feed Type               remote
Content Type            yum
Feed Certs              CA:Yes   Cert:Yes
Consumer Certs          CA:No   Cert:No
Architecture            x86_64
Sync Schedule           R0/2012-01-06T10:50:00+01:00/P1D
Packages                6710
Files                   0
Distributions           ks-rhel-server-6-6Server-x86_64-x86_64 ks-Red Hat Enterprise Linux-Server-6.1-x86_64
Publish                 True
Clones                  [u'clone1', u'clone2']
Groups                  [u'test', u'foo_pulp\\.example\\.com']
Filters                 []
Notes                   {}
Preserve Metadata       False
Checksum Type           sha256

Updating the sync schedule via the api fails:

Client error:

RestClient.put "https://pulp.example.com/pulp/api/repositories/rhel-server-6-6Server-x86_64/schedules/sync/", "{\"schedule\":\"R0/2012-01-06T10:50:00+01:00/P1D\"}", "Accept"=>"application/json", "Accept-Encoding"=>"gzip, deflate", "Content-Length"=>"47", "Content-Type"=>"application/json"
# => 500 InternalServerError | application/json 1693 bytes

Server error:

httpd log:
127.0.0.1 - - [16/Jan/2012:15:54:49 +0100] "PUT /pulp/api/repositories/rhel-server-6-6Server-x86_64/schedules/sync/ HTTP/1.1" 500 1693

pulp log:

2012-01-16 15:54:49,307 19067:140339614557952: pulp:WARNING: scheduler:122 IntervalScheduler created with start time more than one interval in the past: 2012-01-06 10:50:00+01:00, 1 day, 0:00:00
2012-01-16 15:54:49,309 19067:140339614557952: pulp.server.webservices.controllers.decorators:ERROR: decorators:52 Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/decorators.py", line 48, in report_error
    return method(self, *args, **kwargs)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/decorators.py", line 127, in _auth_decorator
    value = method(self, *args, **kwargs)
  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/repositories.py", line 527, in PUT
    scheduled_sync.update_repo_schedule(repo, new_schedule, new_options)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/scheduled_sync.py", line 252, in update_repo_schedule
    _add_repo_scheduled_sync_task(repo)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/scheduled_sync.py", line 180, in _add_repo_scheduled_sync_task
    return async.enqueue(task)
  File "/usr/lib/python2.6/site-packages/pulp/server/async.py", line 58, in enqueue
    _queue.enqueue(task, unique)
  File "/usr/lib/python2.6/site-packages/pulp/server/tasking/taskqueue/queue.py", line 262, in enqueue
    task.schedule() # UncheduledTaskException
  File "/usr/lib/python2.6/site-packages/pulp/server/tasking/task.py", line 364, in schedule
    raise UnscheduledTaskException(_('No more scheduled runs for task: %s') % str(self))
UnscheduledTaskException: No more scheduled runs for task: Task 09c274de-4052-11e1-afd9-005056172b5b: _sync(rhel-server-6-6Server-x86_64, synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7fa349125b10>, progress_callback=<bound method RepoSyncTask.progress_callback of <pulp.server.api.repo_sync_task.RepoSyncTask object at 0x7fa349125350>>)

However using a different sync schedule works:

Client:

RestClient.put "https://pulp.example.com/pulp/api/repositories/rhel-server-6-6Server-x86_64/schedules/sync/", "{\"schedule\":\"R1/2012-01-06T10:50:00+01:00/P1D\"}", "Accept"=>"application/json", "Accept-Encoding"=>"gzip, deflate", "Content-Length"=>"47", "Content-Type"=>"application/json"
# => 200 OK | application/json 165 bytes
 => {"href"=>"/pulp/api/repositories/rhel-server-6-6Server-x86_64/", "schedule"=>"R1/2012-01-06T10:50:00+01:00/P1D", "id"=>"rhel-server-6-6Server-x86_64", "options"=>{}} 

Server Log:

httpd log:
127.0.0.1 - - [16/Jan/2012:15:58:50 +0100] "PUT /pulp/api/repositories/rhel-server-6-6Server-x86_64/schedules/sync/ HTTP/1.1" 200 165


pulp log:
2012-01-16 15:58:50,837 19067:140339759265536: pulp:WARNING: scheduler:122 IntervalScheduler created with start time more than one interval in the past: 2012-01-06 10:50:00+01:00, 1 day, 0:00:00
2012-01-16 15:58:50,837 19067:140339759265536: pulp.server.tasking.task:WARNING: task:366 Task 99b909eb-4052-11e1-9f54-005056172b5b: _sync(rhel-server-6-6Server-x86_64, synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7fa3491259d0>, progress_callback=<bound method RepoSyncTask.progress_callback of <pulp.server.api.repo_sync_task.RepoSyncTask object at 0x7fa349125210>>) missed 10 scheduled runs


And funny enough setting the original sync schedule now works as well:

RestClient.put "https://pulp.example.com/pulp/api/repositories/rhel-server-6-6Server-x86_64/schedules/sync/", "{\"schedule\":\"R0/2012-01-06T10:50:00+01:00/P1D\"}", "Accept"=>"application/json", "Accept-Encoding"=>"gzip, deflate", "Content-Length"=>"47", "Content-Type"=>"application/json"
# => 200 OK | application/json 165 bytes
 => {"href"=>"/pulp/api/repositories/rhel-server-6-6Server-x86_64/", "schedule"=>"R0/2012-01-06T10:50:00+01:00/P1D", "id"=>"rhel-server-6-6Server-x86_64", "options"=>{}}

Waiting a bit and the setting the R0 sync schedule won't work again. Trying to set the original sync schedule multiple times, does also not work!

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

# rpm -qa | grep pulp
m2crypto-0.21.1.pulp-5.el6.x86_64
python-oauth2-1.5.170-2.pulp.el6.noarch
mod_wsgi-3.2-6.pulp.el6.x86_64
python-isodate-0.4.4-4.pulp.el6.noarch
pulp-selinux-server-0.0.254-8.el6.noarch
pulp-admin-0.0.254-8.el6.noarch
pulp-common-0.0.254-8.el6.noarch
pulp-client-lib-0.0.254-8.el6.noarch
pulp-0.0.254-8.el6.noarch


How reproducible:

Always.

Steps to Reproduce:
1. Try to set a sync schedule with R0 -> fails
2. Set a sync schedule with R1 -> works
3. Setting a sync schedule with R0 -> works as well
  
Actual results:

Setting the sync schedule raises a 500er

Expected results:

Should update the sync schedule.

Additional info:

As mentioned above this is always reproducible. I'm not quite sure, what triggers the problem, but usually waiting a bit (till the scheduler took up the new schedule?), allows me to retrigger the issue.