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完善和操做各項基礎設施的操做指南，避免這種事情再發生了。