Every 2nd schedule update appears to fail

Steps to reproduce

Steps to reproduce:
1. Configure CA with org.opencastproject.capture.impl.ConfigurationManager.properties:capture.schedule.remote.polling.interval=5
2. Enable DEBUG logging
3. Examine logs for schedule updates

Actual Results:

Every 2nd schedule update appears to fail. In the CA logs:

2012-09-04 14:47:29 DEBUG (SchedulerImpl:746) - setCaptureSchedule(sched, newCal)
2012-09-04 14:47:29 DEBUG (SchedulerImpl:681) - Currently scheduled jobs for capture schedule: 33
2012-09-04 14:47:29 DEBUG (SchedulerImpl:689) - Currently scheduled jobs for capture related schedule: 0
2012-09-04 14:47:29 DEBUG (SchedulerImpl:697) - Currently scheduled jobs for poll schedule: 1
2012-09-04 14:47:29 DEBUG (SchedulerImpl:705) - Currently scheduled jobs for other schedule: 1
2012-09-04 14:52:29 DEBUG (SchedulerImpl:592) - Calendar already exists, and capture.schedule.remote.endpoint.url is invalid, skipping update.
2012-09-04 14:52:29 DEBUG (SchedulerImpl:681) - Currently scheduled jobs for capture schedule: 33
2012-09-04 14:52:29 DEBUG (SchedulerImpl:689) - Currently scheduled jobs for capture related schedule: 0
2012-09-04 14:52:29 DEBUG (SchedulerImpl:697) - Currently scheduled jobs for poll schedule: 1
2012-09-04 14:52:29 DEBUG (SchedulerImpl:705) - Currently scheduled jobs for other schedule: 1
2012-09-04 14:57:29 DEBUG (SchedulerImpl:746) - setCaptureSchedule(sched, newCal)
2012-09-04 14:57:29 DEBUG (SchedulerImpl:681) - Currently scheduled jobs for capture schedule: 33
2012-09-04 14:57:29 DEBUG (SchedulerImpl:689) - Currently scheduled jobs for capture related schedule: 0
2012-09-04 14:57:29 DEBUG (SchedulerImpl:697) - Currently scheduled jobs for poll schedule: 1
2012-09-04 14:57:29 DEBUG (SchedulerImpl:705) - Currently scheduled jobs for other schedule: 1
2012-09-04 15:02:29 DEBUG (SchedulerImpl:592) - Calendar already exists, and capture.schedule.remote.endpoint.url is invalid, skipping update.
2012-09-04 15:02:29 DEBUG (SchedulerImpl:681) - Currently scheduled jobs for capture schedule: 33
2012-09-04 15:02:29 DEBUG (SchedulerImpl:689) - Currently scheduled jobs for capture related schedule: 0
2012-09-04 15:02:29 DEBUG (SchedulerImpl:697) - Currently scheduled jobs for poll schedule: 1
2012-09-04 15:02:29 DEBUG (SchedulerImpl:705) - Currently scheduled jobs for other schedule: 1
2012-09-04 15:07:29 DEBUG (SchedulerImpl:746) - setCaptureSchedule(sched, newCal)
2012-09-04 15:07:29 DEBUG (SchedulerImpl:681) - Currently scheduled jobs for capture schedule: 33
2012-09-04 15:07:29 DEBUG (SchedulerImpl:689) - Currently scheduled jobs for capture related schedule: 0
2012-09-04 15:07:29 DEBUG (SchedulerImpl:697) - Currently scheduled jobs for poll schedule: 1
2012-09-04 15:07:29 DEBUG (SchedulerImpl:705) - Currently scheduled jobs for other schedule: 1
2012-09-04 15:12:29 DEBUG (SchedulerImpl:592) - Calendar already exists, and capture.schedule.remote.endpoint.url is invalid, skipping update.
2012-09-04 15:12:29 DEBUG (SchedulerImpl:681) - Currently scheduled jobs for capture schedule: 33
2012-09-04 15:12:29 DEBUG (SchedulerImpl:689) - Currently scheduled jobs for capture related schedule: 0
2012-09-04 15:12:29 DEBUG (SchedulerImpl:697) - Currently scheduled jobs for poll schedule: 1
2012-09-04 15:12:29 DEBUG (SchedulerImpl:705) - Currently scheduled jobs for other schedule: 1

BUT the core http access logs show the CA is retrieving the calendar every 5min, not every 10min as the above would suggest:
[
04/Sep/2012:14:47:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" 1478 "-" "Apache-HttpClient/4.0.1 (java 1.5)" 745 401
[04/Sep/2012:14:47:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" - "-" "Apache-HttpClient/4.0.1 (java 1.5)" 1896 304
[04/Sep/2012:14:52:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" 1478 "-" "Apache-HttpClient/4.0.1 (java 1.5)" 396 401
[04/Sep/2012:14:52:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" - "-" "Apache-HttpClient/4.0.1 (java 1.5)" 1643 304
[04/Sep/2012:14:57:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" 1478 "-" "Apache-HttpClient/4.0.1 (java 1.5)" 393 401
[04/Sep/2012:14:57:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" - "-" "Apache-HttpClient/4.0.1 (java 1.5)" 1760 304
[04/Sep/2012:15:02:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" 1478 "-" "Apache-HttpClient/4.0.1 (java 1.5)" 633 401
[04/Sep/2012:15:02:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" - "-" "Apache-HttpClient/4.0.1 (java 1.5)" 1931 304
[04/Sep/2012:15:07:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" 1478 "-" "Apache-HttpClient/4.0.1 (java 1.5)" 652 401
[04/Sep/2012:15:07:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" - "-" "Apache-HttpClient/4.0.1 (java 1.5)" 1864 304
[04/Sep/2012:15:12:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" 1478 "-" "Apache-HttpClient/4.0.1 (java 1.5)" 539 401
[04/Sep/2012:15:12:29 +0200] 137.158.76.67 "GET /recordings/calendars/?agentid=zoo-1 HTTP/1.1" - "-" "Apache-HttpClient/4.0.1 (java 1.5)" 1885 304

which is confusing. So either the logging or the behaviour or both is wrong.

Expected Results:

Calendar should update every 5min consistent with settings.

Workaround (if any):

Status

Assignee

Unassigned

Reporter

Stephen Marquard

Severity

Incorrectly Functioning With Workaround

Tags (folksonomy)

None

Components

Affects versions

1.3

Priority

Major
Configure