CODEWITHSUNDEEP
djangocrontaskcelery
zisoo zzoi
zisoo zzoi

Reputation: 23

Celery beat: crontab executed same task TWICE (interval 10min)

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?

Upvotes: 2

Views: 1726

Answers (2)

Nikhil Rajawat
Nikhil Rajawat

Reputation: 121

One of the reasons it might have happened is because your

Celery was down and the task which was supposed to be executed remained in the queue and couldn't be executed, but was executed at 23:50(when the celery was up). Can you please confirm the celery was up and running the whole time.

Also, did the tasks execute as expected?

Upvotes: 2

Liqang Liu
Liqang Liu

Reputation: 1883

there are no thing wrong for it. the reason for that is celery run in 05-31 and when it start, i think you have not run it before and it found that on 05-01 it's not run and celery think it should run, so it runs.

and for 06-01, this run is for June, and it run at the right time.

so the result is that's i think you start your celery beater at 2017-05-31 23:50:00, don't you?

Upvotes: 0

Related Questions