线上一直以来都在用supervisor管理各项服务,感觉非常舒心,supervisor管理`gunicorn`和`celery`进程,web服务和异步任务各司其职,跑起来一直很稳定。
前段时间却不小心踩了一个小坑,本来以为是celery的问题,后来查了半天才发现,原来根源在supervisor这儿。
灵异事件的表现是这样的,一个小项目里有用到了异步任务,但是发送到异步队列的某一个任务,有时候可以执行成功,有时候失败,不稳定重现。
刚开始的时候怀疑任务本身出了问题,但有点说不通,因为并没有任何的报错被发送出来,连任务代码第一行的日志都没有被输出。另外,其他任务都是正常的,日志也是正常的,每一次的任务都能成功。
所以,目光又开始聚焦到了任务的调用方式上面,就先改成了同步试试,然后发现同步是可以成功的,这至少是排除了任务本身的问题了,任务函数是正确的。
这就奇怪了,难不成是调用的姿势不对吗,翻了一下celery的源码,发现了`apply_async`这个函数中有个`task_id`这个参数,正好我在调用的时候用了`delay`函数,且业务上的参数也是`task_id`,而`delay`函数里面就一句话,调用`apply_async`函数。
看到这个地方的时候,我感觉自己找到了问题的关键,这不就是参数名冲突了吗,改改参数名就好了,然后就把自己的`task_id`改成了`task_id_`,刚兴奋得改完,回头瞅了一眼`delay`和`apply_async`这俩函数,发现自己又错了,我是用`delay`函数调用的,而`delay`函数的参数其实是`*args`和`**kwargs`,`delay`函数里面调用`apply_async`的时候,只传了这两个参数,并且是作为元组和字典传进去的,而`task_id`是独立的一个参数,和`args`这些参数是平级的,所以根本就不存在参数名冲突这个可能。
刚抓住的稻草又没了,只能再去分析了,又去翻了翻日志,突然发现,自己以前写的一个函数里的日志输出有异常,本来打印的info日志里面有个错别字被改掉了,但是最近刚刚打出来的日志,竟然还有这个错别字。
到这问题基本已经清楚了,那就是有不止一组的celery任务进程在开着,并且有一部分是旧的代码。赶紧验证一下,`ps -ef | grep celery`看了一下,当下在跑着的任务里,果然不止`supervisor`现在在监控的celery进程,还有一些老旧的celery进程,其父进程ID都变成了1,好了,到此真相大白了。赶紧把这些任务kill掉,再验证一遍,终于好了,任务又开始稳定得执行了。
后来问了问,原来是这台机器上的supervisord有一次被意外kill了,但是这些异步任务却留了下来,并且父进程ID都成了1。后来supervisord被启动了依赖,但是这个事情一直没有被发现,这些任务进程也会连接到相同的消息队列去进行消耗,但旧的任务队列里面并没有对应的新任务的处理方法,所以这些被旧的任务进程拿到的任务,就被丢弃了。
后来又看了看celery启动时候的日志,发现standalone启动的时候,是有下面这段提示的
[2017-01-05 19:51:47,815: INFO/MainProcess] mingle: searching for neighbors [2017-01-05 19:51:48,821: INFO/MainProcess] mingle: all alone
而有同名的node name存在的时候,也是有下面的日志的
[2017-02-09 19:10:50,872: INFO/MainProcess] mingle: searching for neighbors [2017-02-09 19:10:51,881: WARNING/MainProcess] /home/deploy/_pyvenv/xxxxx/lib/python3.4/site-packages/celery/app/control.py:36: DuplicateNodenameWarning: Received multiple replies from node name: celery@xxxxxxxxxxhostnamexxxxxxxx_
要是早点看看celery的日志,问题也是可以被解决的。
嗯,再次体现了看日志的重要性,这次因为这个异步任务本身并不怎么重要,只有开发和部分运营的同学用到的功能里包含了这个任务,所以并没有造成什么太大的损失。
但要是一个重要的项目重要的任务出这种问题就悲剧了,后面需要针对这种事情做好监控,并且规范线上的操作,做好checklist完善和操作各项基础设施的操作指南,避免这种事情再发生了。