laravel
supervisor
homestead

[laravel5.1] Supervisorで割り当てたジョブの挙動がおかしなことになった話

はじめに

Laravelのジョブ機能、便利ですよね。
Controller側から割り当てて、タスク監視サービスのsupervisorから自動で実行できれば、バックグラウンドで処理させることも簡単ですね。
アップロードしたファイルをDBにセットする処理をジョブ化したのですが、ここでハマってしまったので自分なりに理解するために現状を整理しました。
経緯はこんな感じ。

  1. おいィ?処理は正常終了してるはずなのにDBのレコード数が想定の倍になってるだとォ?
  2. ジョブが失敗したとき(public function failed())でログを吐くようにしてなかったので修正した
  3. 見かけ上はうまく行ってるのにfailedに引っかかってるナンデ?
  4. ログファイルを詳細に吐けるようにしてデバッグしたろ!
  5. そもそもtries=1の時点で最高2回は処理が走るとか言う仕様→二重になってたのはこれが原因では?
  6. confファイルを再度見直してみよう
  7. なんとかなった…

環境

Homestead (Ubuntu16.04)

ファイル名 場所(デフォルト設定) 用途
supervisord.conf /etc/supervisor/ supervisorの大元の設定を行う設定ファイル。
一つ。
laravel-worker.conf(任意) /etc/supervisor/conf.d/ supervisorで自動化したい設定などを書き込むファイル。
タスクごとに生成する。
supervisord.log /var/log/supervisor/ supervisor自体のログファイル。
worker.log (任意) laravel-worker.confで設定したジョブログ。
error.log (任意) laravel-worker.confで設定したエラーログ。

主に設定が必要なものは上記ファイルのうち、supervisord.conflaravel-worker.conf
念のため概略図も書いときます。念のため。

image.png

設定ファイル変遷

変更前ファイル

Homestead上に導入してみたり、とりあえず動くようにしてみたりした結果。

/etc/supervisor/supervisord.conf
[unix_http_server]
file=/var/run/supervisor.sock
chmod=0700

[supervisord]
logfile=/var/log/supervisor/supervisord.log
pidfile=/var/run/supervisord.pid
childlogdir=/var/log/supervisor

[rpcinterface:supervisor]
supervisor.rpcinterface_factory = supervisor.rpcinterface:make_main_rpcinterface

[supervisorctl]
serverurl=unix:///var/run/supervisor.sock

[include]
files = /etc/supervisor/conf.d/*.conf
/etc/supervisor/conf.d/laravel-worker.conf
[program:laravel-worker]
process_name=%(program_name)s_%(process_num)02d
php /project]/artisan queue:work --sleep=3 --tries=1 --daemon
autostart=true
autorestart=true
user=vagrant
numprocs=8
stdout_logfile=/[project]/storage/supervisor_logs/worker.log
redirect_stderr=true

なんか色々いじった後のファイル

この辺とかこの辺を参考に編集した結果。

/etc/supervisor/supervisord.conf
;;;;;;;;;;
;; 省略
;;;;;;;;;;

[supervisord]
logfile=/var/log/supervisor/supervisord.log
pidfile=/var/run/supervisord.pid
childlogdir=/var/log/supervisor
loglevel=debug

;;;;;;;;;;
;; 省略
;;;;;;;;;;
/etc/supervisor/conf.d/laravel-worker.conf
[program:laravel-worker]
process_name=%(program_name)s_%(process_num)02d
php /project]/artisan queue:work --sleep=3 --tries=1 --daemon
autostart=true
autorestart=true
user=vagrant
numprocs=8
stderr_logfile=/[project]/storage/supervisor_logs/error.log
stdout_logfile=/[project]/storage/supervisor_logs/worker.log
redirect_stderr=true

え、エラーログが出ない…。
ログが取れないと原因すら調査できないんですがそれは…。
と思ったらstackoverflowさんにそれらしい質問が。

エラー取得方法

.env内のAPP_DEBUGtrueになっていることを確認する。

console
php artisan queue:failed
# +----+------------+---------+--------------------+---------------------+
# | ID | Connection | Queue   | Class              | Failed At           |
# +----+------------+---------+--------------------+---------------------+
# | 1  | database   | default | App\Jobs\SampleJob | 2017-11-28 10:32:10 |
# +----+------------+---------+--------------------+---------------------+

sudo supervisorctl stop all
php artisan queue:retry 1 # IDに応じて書き換える
php artisan queue:work

これでコンソール上に実行時ログが出るので、何かエラーがあったらキャッチできるっぽいんだけど、私の環境では現象が再現しませんでした。

confファイルを書き換える

/etc/supervisor/conf.d/laravel-worker.conf
[program:laravel-worker]
command=php /[project]/artisan queue:work --sleep=3 --daemon
numprocs=1

ひとまずここの部分をより簡素にしてオプション外しました。
ついでに起動するプロセス数(numprocs)も減らしてみました。
そんなにジョブ割り当てないし。
外したところ、割とうまく行ってます。

所感

supervisorは色々と謎なことが多すぎる。

  • failedしてるにも関わらずその後の処理が進んでいることとか
  • エラーログに上がってこないこととか
  • そもそもなんでfailedしてるのかとか
  • デフォルトだとジョブが2プロセスくらい割り当てられることとか

未だに理解できてない。
でも動いた。とりあえず動いた。
これでいいかは別にして。