supervisor踩坑记录

线上一直以来都在用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完善和操做各项基础设施的操做指南，避免这种事情再发生了。