I set celery crontab like below
Proj_root/proj/celery.py
app.conf.update(
CELERYBEAT_SCHEDULE={
'do_every_1st_day_of_month': {
'task': 'foobar',
'schedule': crontab(0, 0, day_of_month='1'),
'args': ()
},
})
But finally it was executed twice, 2017/05/31 23:50:00 and 2017/06/01 00:00:00.
I cannot find reason. according to crontab params, it shouldn't be done at 2017/05/31.
why it's like this? and here's related log at that time. If other part of project is needed, I'll apply later
[2017-05-31 23:50:00,002: INFO/Beat] Scheduler: Sending due task (foobar)
[2017-05-31 23:50:00,004: DEBUG/Beat] foobar sent. id->8240fb96-994c-4f96-bf4d-4824f0e0c407
[2017-05-31 23:50:00,005: DEBUG/Beat] beat: Waking up in 5.00 minutes.
[2017-05-31 23:50:00,005: INFO/MainProcess] Received task: foobar[8240fb96-994c-4f96-bf4d-4824f0e0c407]
[2017-05-31 23:50:00,006: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x80740b1e0> (args:('foobar', '8240fb96-994c-4f96-bf4d-4824f0e0c407', {'lang': 'py', 'task': 'foobar', 'id': '8240fb96-994c-4f96-bf4d-4824f0e0c407', 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '8240fb96-994c-4f96-bf4d-4824f0e0c407', 'parent_id': None, 'argsrepr': '()', 'kwargsrepr': '{}', 'origin': 'gen63835@neadrc-test01', 'reply_to': '257ab156-57fa-3806-bdf1-28d5501b0472', 'correlation_id': '8240fb96-994c-4f96-bf4d-4824f0e0c407', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': None}}, b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-05-31 23:50:00,006: DEBUG/MainProcess] Task accepted: foobar[8240fb96-994c-4f96-bf4d-4824f0e0c407] pid:63838
[2017-05-31 23:50:00,789: INFO/PoolWorker-4] Task foobar[8240fb96-994c-4f96-bf4d-4824f0e0c407] succeeded in 0.7823948785662651s: None
[2017-05-31 23:55:00,006: DEBUG/Beat] beat: Synchronizing schedule...
[2017-05-31 23:55:00,007: DEBUG/Beat] beat: Waking up in 5.00 minutes.
[2017-05-31 23:59:59,991: DEBUG/Beat] beat: Synchronizing schedule...
[2017-06-01 00:00:00,001: INFO/Beat] Scheduler: Sending due task do_every_1st_day_of_month (foobar)
[2017-06-01 00:00:00,004: DEBUG/Beat] foobar sent. id->6da824e0-14bf-4e56-a279-bdc2d466ab1e
[2017-06-01 00:00:00,006: INFO/MainProcess] Received task: foobar[6da824e0-14bf-4e56-a279-bdc2d466ab1e]
[2017-06-01 00:00:00,006: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x80740b1e0> (args:('foobar', '6da824e0-14bf-4e56-a279-bdc2d466ab1e', {'lang': 'py', 'task': 'foobar', 'id': '6da824e0-14bf-4e56-a279-bdc2d466ab1e', 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '6da824e0-14bf-4e56-a279-bdc2d466ab1e', 'parent_id': None, 'argsrepr': '()', 'kwargsrepr': '{}', 'origin': 'gen63835@neadrc-test01', 'reply_to': '257ab156-57fa-3806-bdf1-28d5501b0472', 'correlation_id': '6da824e0-14bf-4e56-a279-bdc2d466ab1e', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': None}}, b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-06-01 00:00:00,010: DEBUG/MainProcess] Task accepted: foobar[6da824e0-14bf-4e56-a279-bdc2d466ab1e] pid:63838
[2017-06-01 00:00:00,615: INFO/PoolWorker-4] Task foobar[6da824e0-14bf-4e56-a279-bdc2d466ab1e] succeeded in 0.6074081044644117s: None
*EDIT 2017.06.05
I found some strange thing I watched celery log, there's one more task runs twice interval 10 min. it runs 10 minutes before scheduled time. and also ran exact scheduled time.
<ScheduleEntry: do-bar-every-midnight bar() <crontab: 0 23 * * * (m/h/d/dM/MY)>
...
[2017-05-31 01:33:43,324: DEBUG/Beat] beat: Ticking with max interval->5.00 minutes
[2017-05-31 22:50:00,002: INFO/Beat] Scheduler: Sending due task do-bar-every-midnight (bar)
[2017-05-31 22:50:00,003: DEBUG/Beat] bar sent. id->cf9c0268-3071-418a-be60-c7dee75c973b
[2017-05-31 22:50:00,004: DEBUG/Beat] beat: Waking up in 5.00 minutes.
[2017-05-31 22:50:00,005: INFO/MainProcess] Received task: bar[cf9c0268-3071-418a-be60-c7dee75c973b]
[2017-05-31 22:50:00,006: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x80740b1e0> (args:('bar', 'cf9c0268-3071-418a-be60-c7dee75c973b', {'lang': 'py', 'task': 'bar', 'id': 'cf9c0268-3071-418a-be60-c7dee75c973b', 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': 'cf9c0268-3071-418a-be60-c7dee75c973b', 'parent_id': None, 'argsrepr': '()', 'kwargsrepr': '{}', 'origin': 'gen63835@neadrc-test01', 'reply_to': '257ab156-57fa-3806-bdf1-28d5501b0472', 'correlation_id': 'cf9c0268-3071-418a-be60-c7dee75c973b', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': None}}, b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-05-31 22:50:00,007: DEBUG/MainProcess] Task accepted: bar[cf9c0268-3071-418a-be60-c7dee75c973b] pid:63836
...
[2017-05-31 23:00:00,000: INFO/Beat] Scheduler: Sending due task do-bar-every-midnight (bar)
[2017-05-31 23:00:00,002: DEBUG/Beat] bar sent. id->24c08011-a490-490e-a2fc-fc5ddd12ef27
[2017-05-31 23:00:00,002: INFO/MainProcess] Received task: bar[24c08011-a490-490e-a2fc-fc5ddd12ef27]
[2017-05-31 23:00:00,003: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x80740b1e0> (args:('bar', '24c08011-a490-490e-a2fc-fc5ddd12ef27', {'lang': 'py', 'task': 'bar', 'id': '24c08011-a490-490e-a2fc-fc5ddd12ef27', 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '24c08011-a490-490e-a2fc-fc5ddd12ef27', 'parent_id': None, 'argsrepr': '()', 'kwargsrepr': '{}', 'origin': 'gen63835@neadrc-test01', 'reply_to': '257ab156-57fa-3806-bdf1-28d5501b0472', 'correlation_id': '24c08011-a490-490e-a2fc-fc5ddd12ef27', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': None}}, b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-05-31 23:00:00,004: DEBUG/MainProcess] Task accepted: bar[24c08011-a490-490e-a2fc-fc5ddd12ef27] pid:63838
...
[2017-05-31 23:05:37,901: INFO/PoolWorker-4] Task bar[24c08011-a490-490e-a2fc-fc5ddd12ef27] succeeded in 337.8967144470662s: datetime.datetime(2017, 5, 31, 23, 5, 37, 899685)
...
[2017-05-31 23:05:40,014: INFO/PoolWorker-2] Task bar[cf9c0268-3071-418a-be60-c7dee75c973b] succeeded in 940.0073816571385s: datetime.datetime(2017, 5, 31, 23, 5, 40, 10523)
I traced to logs few more days before, the case of task 'bar'
[2017-05-23 05:37:51,155: INFO/Beat] beat: Starting...
...
[2017-05-23 22:50:00,004: DEBUG/Beat] bar sent. id->2bfe3ab4-abfd-419e-bfe1-8f64cebe0739
[2017-05-23 23:00:00,002: DEBUG/Beat] bar sent. id->96eeb154-688a-4e19-b793-c1017e3dcdfc
[2017-05-24 22:50:00,003: DEBUG/Beat] bar sent. id->b02db272-712f-4a5b-83d7-1823181367fa
[2017-05-24 23:00:00,002: DEBUG/Beat] bar sent. id->f510be26-7155-4707-b0da-309bf6e4d938
[2017-05-25 23:00:00,004: DEBUG/Beat] bar sent. id->67108a9f-5629-46e8-bd32-e7c7a5eaaa31
[2017-05-26 23:00:00,002: DEBUG/Beat] bar sent. id->d85cc8a0-c68d-4762-bd81-8ddfea19f177
[2017-05-27 23:00:00,002: DEBUG/Beat] bar sent. id->a1203df4-ac84-43ea-8ba8-c6f984e205d1
[2017-05-28 23:00:00,005: DEBUG/Beat] bar sent. id->716f01dd-f802-44a4-af40-801505317e71
I guess, as @yetship said before, it runs twice when it first launch task after run celery beat. but it did not run task exact time when celery beat start, it runs 10 min earlier than it scheduled. I've ran celery beat 05-23 05:37:51
I think problem is specified, how can I prevent it from run 10 min before..? and also make it run once?