芹菜节拍：crontab 两次执行相同的任务（间隔 10 分钟）

Posted 2023-02-24

【中文标题】芹菜节拍：crontab 两次执行相同的任务（间隔 10 分钟）

【英文标题】：Celery beat: crontab executed same task TWICE (interval 10min)

【发布时间】：2017-11-02 04:32:57

【问题描述】：

我像下面这样设置 celery crontab

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': ()
         ,
    )

但最后还是执行了两次， 2017/05/31 23:50:00 和 2017/06/01 00:00:00。

我找不到原因。 根据 crontab 参数，它不应该在 2017/05/31 完成。

为什么会这样？这是当时的相关日志。 如果需要项目的其他部分，我会稍后申请

[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

*编辑 2017.06.05

我发现了一些奇怪的东西 我看了芹菜日志，还有一个任务运行两次，间隔 10 分钟。 它比预定时间早 10 分钟运行。并且还运行了准确的预定时间。

<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)

我在几天前追踪到日志，任务'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

我想，正如@yetship 之前所说，它在运行 celery beat 后第一次启动任务时运行两次。但是当 celery beat 开始时它没有运行任务的确切时间，它比预定的时间早了 10 分钟。我跑过 celery beat 05-23 05:37:51

我认为问题已被指定，我怎样才能防止它在 10 分钟前运行..？并让它运行一次？

【参考方案1】：

它可能发生的原因之一是因为您的

Celery 宕机了，本来应该执行的任务还在队列中无法执行，但是在 23:50（当 celery 起来的时候）执行了。你能确认一下芹菜一直在运行吗？

另外，任务是否按预期执行？

【讨论】：

我看了日志，但是找不到 celery down 日志：OI 找到了 [2017-05-31 01:33:42,396] ~ [2017-06-01 01: 54:00,861]

【参考方案2】：

没有什么不对的。 原因是 celery 在 05-31 运行，当它开始时，我认为你之前没有运行它，它发现在 05-01 它没有运行，而 celery 认为它应该运行，所以它运行。

对于 06-01，这次运行是在 6 月，而且运行时间很合适。

所以结果是我认为你在 2017 年 5 月 31 日 23:50:00 开始你的芹菜打浆机，不是吗？

【讨论】：

感谢您的回答！ :D 但当时我没有运行 celery，实际上我在 2017-05-19 运行了 celery deamon。当时 celery 直到 2017-05-31 23:50:00... :) 谢谢！！

如果是真的，有什么办法可以防止 celery beat 在过去的日期执行？再次感谢！

太棒了，你有没有改过机器的时间？关于我之前说的，也许你可以在github@zisoozzoi 上查看芹菜crontab 的代码实现

不，生产服务器时间没有改变T^T

我在同一个项目中发现了类似的案例..我认为这有点像你之前所说的，但是......仍然无法澄清确切的问题