[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の大元の設定を行う設定ファイル。<br>一つ。|
|**laravel-worker.conf**（任意）|/etc/supervisor/conf.d/|supervisorで自動化したい設定などを書き込むファイル。<br>タスクごとに生成する。|
|**supervisord.log**|/var/log/supervisor/|supervisor自体のログファイル。|
|**worker.log**|（任意）|``laravel-worker.conf``で設定したジョブログ。|
|**error.log**|（任意）|``laravel-worker.conf``で設定したエラーログ。|

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

![image.png](https://qiita-image-store.s3.amazonaws.com/0/165355/2ee951be-00e2-0c3b-fba4-120396306922.png)

# 設定ファイル変遷
## 変更前ファイル
**[Homestead上に導入](https://qiita.com/tosite0345/items/a92367e8129d2be4ad53)**してみたり、**[とりあえず動く](https://qiita.com/tosite0345/items/b9ec1594f359f03b0403#supervisor%E3%82%B5%E3%83%BC%E3%83%93%E3%82%B9%E3%82%92%E5%85%A5%E3%82%8C%E3%82%8B)**ようにしてみたりした結果。

```ini:/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
```

```ini:/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
```

## なんか色々いじった後のファイル
**[この辺](http://webos-goodies.jp/archives/deploying_tornado_with_supervisord.html)**とか**[この辺](https://stackoverflow.com/questions/28937722/supervisord-exit-status-1-not-expected-running-php-script)**を参考に編集した結果。

```ini:/etc/supervisor/supervisord.conf
;;;;;;;;;;
;; 省略
;;;;;;;;;;

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

;;;;;;;;;;
;; 省略
;;;;;;;;;;
```

```ini:/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](https://stackoverflow.com/questions/34485265/how-can-i-learn-more-about-why-my-laravel-queued-job-failed)**さんにそれらしい質問が。

## エラー取得方法

``.env``内の``APP_DEBUG``が``true``になっていることを確認する。

```bash: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ファイルを書き換える

```ini:/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プロセスくらい割り当てられることとか

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