Laravelのジョブのリトライの挙動について

laravel/framework: v6.20.34

参照されている箇所で気になるのは上記の部分で、特に getJobRetryDelay が気になる。

利用されているのは以下で、追いかけていくと以下でpayloadのdelayパラメータに使用されている。
https://github.com/laravel/framework/blob/6.x/src/Illuminate/Queue/Queue.php#L114-L143

payloadのdelayはまず、以下で参照されている。
https://github.com/laravel/framework/blob/6.x/src/Illuminate/Queue/Jobs/Job.php#L247-L257

JobのdelaySecondsは以下で参照されていて、これだとワーカーが例外をキャッチしたタイミングでジョブの実行をどれだけずらずかに使われているように見える。

https://github.com/laravel/framework/blob/6.x/src/Illuminate/Queue/Worker.php#L391-L420

これだと、公式ドキュメントにあったbackOffとの違いは...?

Laravel8だとドキュメント上で引っかかるものの、Laravel6では引っかからないので、ここまでの話はLaravel6固有の模様...。

実際にソースコードを検索すると、v6.xのブランチではbackOff では一切該当がない(Queueフォルダ内)。

ということは、v8に移行するまでのどこかで、retryAfterをbackOffに置き換える必要が発生しそう。

これだ...。
やはり理由は一貫性のためだった。
リネームだけであれば大がかりにはならなそう。
https://laravel.com/docs/8.x/upgrade#queue-retry-after-method

先ほどはあまり重要でないと思って控えなかったものの、DatabaseQueue.phpの中では以下で唯一参照されている。

https://github.com/laravel/framework/blob/6.x/src/Illuminate/Queue/DatabaseQueue.php#L259-L274

このメソッドは同じクラス内の getNextAvailableJob() から参照されていて、
「キュー上に残っていて、retryAfter を経過しているジョブを処理の候補として取得する」と考えると今までイメージしていたretryAfterと一致する。
(getNextAvailableJobが本当に次に処理するジョブになるのかまでは確認できていない)

ここまで考えると、ワーカーに設定する retryAfterとジョブのプロパティに指定するretryAfterは別々というのは確かそう。

タイムアウト時の判定。
maxTriesを意識せず、failさせているように見える。

https://github.com/laravel/framework/blob/7e82e1a272a72d75b4cd7f35a2267e9af5d642c2/src/Illuminate/Queue/Worker.php#L451-L471

ワーカーのタイムアウトを調べていたら、ワーカー側で以下のようなものが設定されているのを確認した。
意外なところでシグナルが使われていて驚いたけど、よくよく考えると自分自身がフリーズしている状態に割り込むにはこれしか方法がなさそう。
そうしないと、長時間のIOを待っている状況では次に処理できるのはIOが終わった時になってしまう。

https://github.com/laravel/framework/blob/6.x/src/Illuminate/Queue/Worker.php#L157-L176

この辺りを見ていると、ジョブがタイムアウトした場合、 MaxAttemptsExceededException が発生する。

Job::failed() が呼ばれた場合、JobFailed イベントが呼ばれているように見えるので、ここで受け取って検知が出来るかもしれない。
ジョブ自身の failedメソッドが呼ばれるようにも見える。
https://github.com/laravel/framework/blob/6.x/src/Illuminate/Queue/Jobs/Job.php#L196-L206

タイムアウト時の動作については、 artisan queue:work で実行させた上で、ジョブに以下のようなメソッドを持たせることで検知出来た。

    public function failed(\throwable $e)
    {
        if($e instanceof MaxAttemptsExceededException) {
            \Log::debug('タイムアウトしました: ' . $e->getMessage());
        } else {
            \Log::debug('失敗しました: ' . $e->getMessage());

        }
    }

タイムアウトはリトライの都度リセットされている。
なので、1回1回の実行時間のタイムアウトだった。
(そうでないと扱いにくい)

ジョブクラスが以下のような実装で、 php artisan queue:work で実行させた場合

class TestJob implements ShouldQueue
{
    use Dispatchable, InteractsWithQueue, Queueable, SerializesModels;

    public $timeout = 14;
    public $tries = 3;
    public $retryAfter = 1;

    public function handle()
    {
        for($i=0; $i<10; $i++) {
            \Log::debug($i);
            sleep(3);
            // trigger_error('aaa', E_USER_ERROR);
        }
    }

    public function failed(\throwable $e)
    {
        if($e instanceof MaxAttemptsExceededException) {
            \Log::debug('タイムアウトしました: ' . $e->getMessage());
        } else {
            \Log::debug('失敗しました: ' . $e->getMessage());

        }
    }
}

出力は以下のようになる。

DEBUG: 0
DEBUG: 1
DEBUG: 2
DEBUG: 3
DEBUG: 4

ここでタイムアウトして、 queue:workが終了するので手動でで再起動する。
この時、jobs.attemptsのカウントが1上がっている。

そして3回ワーカーを再起動させた時点で以下のようなログが残る。
リトライ上限超過だが、例外の種類が同じなのでこのようなログになっている。

DEBUG: 0
DEBUG: 1
DEBUG: 2
DEBUG: 3
DEBUG: 4
DEBUG: タイムアウトしました: App\Jobs\TestJob has been attempted too many times or run too long. The job may have previously timed out.  

実装を以下のように変えてみると、エラーの都度リトライするようになる。
リトライ間隔は10秒。

    public $timeout = 14;
    public $tries = 3;
-   public $retryAfter = 1;
+   public $retryAfter = 10;

    public function handle()
    {
        for($i=0; $i<10; $i++) {
            \Log::debug($i);
            sleep(3);
-           // trigger_error('aaa', E_USER_ERROR);
+           trigger_error('aaa', E_USER_ERROR);

        }
    }

ログの残り方は以下のように変わる。

DEBUG: 0  
ERROR: aaa
# ここで10秒空く
DEBUG: 0  
ERROR: aaa
# ここで10秒空く
DEBUG: 0  
DEBUG: 失敗しました: aaa  
ERROR: aaa