線上一直以來都在用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完善和操作各項基礎設施的操作指南，避免這種事情再發生了。