CeleryBeat crontab alters task schedule #973

Closed
tmehlinger opened this Issue Sep 10, 2012 · 6 comments

Projects

None yet

2 participants

@tmehlinger

I'm using crontab schedules for controlling recurring tasks with CeleryBeat. However, after running for some time, the schedule goes a little wonky.

In the paste below, I've got two tasks, one.minute.task and ten.minute.task. The former is configured with a bare crontab(), the latter with crontab(minute='*/10'). As you'll see everything works the way you would expect for a while, then ten.minute.task inexplicably starts running every minute. I've added linefeeds for readability.

ten.minute.task typically finishes running in about two minutes, so I know there's no problem with worker availability (until they start running every minute, anyway). I don't currently have any steps to reproduce the issue other than firing it up with crontab schedules and waiting for it to happen. My workaround in the meantime is to use timedelta scheduling.

[2012-09-09 23:30:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:30:00,073: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,076: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:30:00,077: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,078: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:30:00,079: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:30:00,082: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,083: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,084: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:30:00,085: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:30:00,087: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,088: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,089: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:30:00,091: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:31:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:31:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:31:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:31:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:31:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:31:00,069: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:31:00,072: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:32:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:32:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:32:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:32:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:32:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:32:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:32:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:33:00,055: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:33:00,057: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:33:00,058: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:33:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:33:00,060: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:33:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:33:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:34:00,058: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:34:00,070: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:34:00,074: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:34:00,075: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:34:00,076: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:34:00,078: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:34:00,079: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:35:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:35:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:35:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:35:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:35:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:35:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:35:00,070: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:36:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:36:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:36:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:36:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:36:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:36:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:36:00,069: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:37:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:37:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:37:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:37:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:37:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:37:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:37:00,069: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:38:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:38:00,074: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:38:00,076: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:38:00,078: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:38:00,080: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:38:00,082: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:38:00,085: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:39:00,058: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:39:00,060: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:39:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:39:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:39:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:39:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:39:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:40:00,054: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,055: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:40:00,056: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,057: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:40:00,058: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,060: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:40:00,061: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:40:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,065: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:40:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:40:00,068: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:40:00,069: INFO/Beat] Scheduler: Sending due task ten.minute.task

[2012-09-09 23:41:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:41:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:41:00,078: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:41:00,079: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:41:00,081: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:41:00,082: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:41:00,084: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:42:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:42:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:42:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:42:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:42:00,071: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:42:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:42:00,076: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:43:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:43:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:43:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:43:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:43:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:43:00,070: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:43:00,072: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:44:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:44:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:44:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:44:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:44:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:44:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:44:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:45:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:45:00,071: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:45:00,075: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:45:00,076: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:45:00,077: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:45:00,079: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:45:00,081: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:46:00,057: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:46:00,058: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:46:00,060: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:46:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:46:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:46:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:46:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:47:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:47:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:47:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:47:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:47:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:47:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:47:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:48:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:48:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:48:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:48:00,064: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:48:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:48:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:48:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:49:00,052: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:49:00,060: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:49:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:49:00,067: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:49:00,069: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:49:00,071: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:49:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:50:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:50:00,061: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,062: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:50:00,064: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:50:00,068: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:50:00,070: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,072: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:50:00,075: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:50:00,077: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,079: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,081: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:50:00,083: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:51:00,061: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:51:00,062: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,063: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:51:00,064: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,065: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:51:00,066: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:51:00,069: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,069: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:51:00,073: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:51:00,077: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,082: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,084: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:51:00,088: INFO/Beat] Scheduler: Sending due task one.minute.task

[2012-09-09 23:52:00,059: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:52:00,089: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,093: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:52:00,095: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,096: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:52:00,097: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:52:00,099: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,100: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,101: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:52:00,103: INFO/Beat] Scheduler: Sending due task one.minute.task
[2012-09-09 23:52:00,104: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,106: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,107: INFO/Beat] Scheduler: Sending due task ten.minute.task
[2012-09-09 23:52:00,108: INFO/Beat] Scheduler: Sending due task one.minute.task
@ask
Member
ask commented Sep 11, 2012

Not able to reproduce here.

What version of Celery (+Django) are you using?

What is the value of your TIME_ZONE, CELERY_TIMEZONE, USE_TZ, or CELERY_ENABLE_UTC settings?

@tmehlinger

I'm using Celery 3.0.9, no Django. Settings are all defaults.

I'm going to be working some more with this so I'll post any further information that turns up.

Thanks!

@ask
Member
ask commented Sep 20, 2012

I've made some more fixes in the celery 3.0 branch, could you try that?

If it still doesn't work you can start beat on its own with the C_REMDEBUG envvar set:

$ C_REMDEBUG=1 celery beat -l debug

this should give some more debugging output to see what it's actually trying to match

@tmehlinger

I'll give it a shot, thanks for checking it out. :)

FWIW, I did have this happen again when I had a crontab set up to fire tasks every second (it was a test case, not an insane production scenario). Perhaps high-resolution scheduling causes some kind of race condition in the schedule tracking?

@ask
Member
ask commented Sep 25, 2012

But crontabs can't be schedule every second can it? The regular schedules can, and it should definitely work with every-second schedules.

@ask
Member
ask commented Sep 25, 2012

Closing, please reopen if it's still an issue.

@ask ask closed this Sep 25, 2012
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment