task.delayからへんじがない。ただのしかばねのようだ(Celery+RabbitMQ)

python django

とある開発環境でCelery + RabbitMQを動かしてたら、いつのまにかtask.delay()が息をしてないというかハングアップしてる感じになった時の調査と対処のメモ

環境

  • Debian squeeze
  • RabbitMQ 3.1.3 (apt-getでinstall)

現象

  • DjangoアプリからCelelyのtask.delayでジョブを実行してるけど処理された気配がない
  • 特にアプリ、Celery、RabbitMQで目立ったエラーは出ていない
  • Celery起動時にRabbitMQの接続は出来てるというログは出てる
[2013-07-25 16:08:55,270: WARNING/MainProcess] celery@hogehoge ready.
[2013-07-25 16:08:55,284: INFO/MainProcess] consumer: Connected to amqp://guest@127.0.0.1:5672//
  • task.delayを実行するとRabbitMQのログには受け付けた旨のログは残る。
=WARNING REPORT==== 25-Jul-2013::17:10:59 ===
closing AMQP connection <0.304.0> (127.0.1.1:45367 -> 127.0.1.1:5672):
  • ところがどっこい結果を見に行こうとするとハングアップする (hangs up)
>> from tasks import add
>> result = add.delay(1, 2)
>> result.get()
(ここでハングアップ。なんのへんじもない。ただのしかばねのようだ)
  • なんでハングアップになったのか全くわからない。なんでや。しばらく頭ひねる。

原因

原因はこのissueの最後の方の話しと同じ感じだった

https://github.com/celery/celery/issues/1312

  • RabbitMQは disk_free_limit という設定がある
  • disk_free_limit は disk_free(ディスクの空き容量) が disk_free_limitを下回ったら、RabbitMQへのPublishをブロックするという設定値
  • disk_free_limitはデフォルトで1GBに設定されている

今回の仮想マシンはディスク容量が8GBバイトと比較的少なめのディスク容量だった。
そしたらログやら、DBやらでいつのまにか1GBを切っていたため、突然ジョブキューが音も無くブロックされて死んだ様に見えた。

よくよく調べるとRabbitMQを再起動したりするとログに以下のようなメッセージが書き込まれてた...orz

=WARNING REPORT==== 25-Jul-2013::16:03:15 ===
disk resource limit alarm set on node rabbit@hogehoge.

Publishers will be blocked until this alarm clears

まじかー。再起動のコマンド叩いた時に教えて欲しかったわー。欲しかったわー

対処

といわけで対処方法。まぁ単純にdisk_free_limit以上の空き容量を作ればいいんですが、
そもそも8GBしかないし、開発用だし、disk_free_limitを小さく設定すればいいよねて感じで設定します。

$ sudo vi /etc/rabbitmq/rabbitmq.config

# write this.
[
 {rabbit, [{disk_free_limit, {mem_relative, 0.1}}]}
].
  • 設定ファイル(rabbitmq.config)を所定の位置に作成
  • disk_free_limitを{mem_relative, 0.1}(メモリ容量の10%)に設定
  • メモリが500MBくらいだったので、大体50MBに設定された。
  • 単純に0にする事もできるけど、無限にディスク容量を喰わないためのセーフティ機能なのであまりお勧めしない。

あとはrabbitmq-serverを再起動してstatusを確認すればOK

$ sudo service rabbitmq-server restart
$ sudo service rabbitmq-server status
Status of node rabbit@hogehoge ...
.
.
 {disk_free_limit,52212122}, <- コレね

おわり。

余談

  • いやー本当に1日ってあっという間におわっちゃいますね。ハハハッハハハッ(白目)

追記(2013/07/26)

無知をさらけ出すとイケメンにチヤホヤされる職場です。

[2013/07/26 8:10:54] イケメンCTO: @tell-k かなり前にもしかしたら聞いたカモですが
http://tell-k.hatenablog.com/entry/2013/07/25/211848
[2013/07/26 8:10:54] イケメンCTO: CELERY_IGNORE_RESULT = True とかって設定しています？
[2013/07/26 8:12:26] tell-k: 設定してなかったです。
[2013/07/26 8:18:10] イケメンCTO: @tell-k 上 or CELERYのログのEXPIREを指定しないとログがどんどんBROKERにたまっていて、
[2013/07/26 8:18:28] イケメンCTO: Rabittmqだとまさに反応がなくなるってことが昔何度かありました。
[2013/07/26 8:19:15] tell-k: なるほど。
[2013/07/26 8:19:21] tell-k: ありがとうございます。
[2013/07/26 8:19:31] tell-k: 設定しないと！
[2013/07/26 8:20:14] イケメンCTO: これ設定例 -> 設定例のコピペをくれる
[2013/07/26 8:20:09] tell-k: おぉぉぉ
[2013/07/26 8:20:26] tell-k: ありがとうございます。
[2013/07/26 8:20:29] tell-k: cto++
[2013/07/26 8:20:48] イケメンCTO: >CELERY_SEND_TASK_ERROR_EMAILS = True
これやると、エラーメールが飛んでくるので解析が便利になりやす、これはいれたほうがいいっすね、CELERY_IGNORE_RESULTと合わせて
[2013/07/26 8:20:58] イケメンCTO: まぁ、設定したのはイケメンエンジニア(ike4)っす
[2013/07/26 8:20:59] イケメンCTO: イケメンエンジニア(ike4)++

参考