hrendoh's tech memo

Heroku SchedulerでLaravelのartisanコマンドを実行する

LaravelのartisanコマンドをHeroku Schedulerを使って、定期実行する手順に確認したのでまとめてみました。

Laravelのバージョンは、2019年9月時点での最新6.0で確認しています。

Heroku Schedulerのとは

Heroku Schedulerは、cronジョブ的な仕組みを提供するHeroku公式アドオンです。

ドキュメントによると実行間隔は10分、1時間、1日のみです。
この要件で問題なければ非常に便利な機能です。

実行時刻は正確ではないので、ジョブを正確な時刻に実行する必要がある場合はここで説明するSchedulerではなくCustom Clock Processを利用する必要があります。

また、Heroku Schedulerジョブで実行するタスクの実行時間について「Long-running jobs」には、実行時間が数分を超えるような長いタスクを実行する場合は、バックグラウンドキューに入れてワーカーDynoでタスクを実行するべきと書いてあります。
更に、スケジューラーで起動されたDynoは、次のスケジュール実行時間になると停止するとも書いてあります。
よって、基本的にはLaravelの場合QueuesをワーカーDynoで起動しておいて、スケジュールジョブではジョブをディスパッチするのみにするのが正しい実装になります。

しかし、この記事では、まずはHeroku Schedulerの動作の雰囲気を掴むため、Heroku Schedulerのジョブからシンプルなartisan commandを直接実行して動作を確認してみます。

検証用コマンドを作成

検証用のコマンドを作成します。

$ php artisan make:command HelloCommand
Console command created successfully.

HelloCommand.phpは以下のように、実行されたらログにメッセージを表示するだけのコマンドです。

<?php

namespace App\Console\Commands;

use Illuminate\Console\Command;
use Illuminate\Support\Facades\Log;

class HelloCommand extends Command
{
    /**
     * The name and signature of the console command.
     *
     * @var string
     */
    protected $signature = 'command:hello';

    /**
     * The console command description.
     *
     * @var string
     */
    protected $description = 'Command to say hello!';

    /**
     * Create a new command instance.
     *
     * @return void
     */
    public function __construct()
    {
        parent::__construct();
    }

    /**
     * Execute the console command.
     *
     * @return mixed
     */
    public function handle()
    {
        Log::info('Hello heroku Scheduler!');
    }
}

Heroku Schedulerのセットアップ

heroku addons:createコマンドでHeroku Schedulerをインストールします。

$ heroku addons:create scheduler
Creating scheduler on ⬢ morning-bastion-21992... free
 To manage scheduled jobs run:
 heroku addons:open scheduler

Created scheduler-parallel-37698
Use heroku addons:docs scheduler to view documentation

以下のコマンドを実行すると、Heroku Schedulerのダッシュボードが開きます。

$ heroku addons:open scheduler

ブラウザにダッシュボードが開いたら[Craete job]ボタンをクリック

[Schedule]は、「Every 10 minutes」を選択、[Run Command]には追加した検証用のカスタムコマンドを起動するコマンド「php artisan command:hello」をセットし、[Save Job]をクリックして保存します。

一覧に追加したジョブが表示されます。

実行の確認

heroku logsで、コマンドのスケジュール実行を確認します。

$ heroku logs --tail

2019-09-23T14:04:02.169730+00:00 app[api]: Starting process with command `php artisan command:hello` by user scheduler@addons.heroku.com
2019-09-23T14:04:04.539418+00:00 heroku[scheduler.6047]: Starting process with command `php artisan command:hello`
2019-09-23T14:04:05.190737+00:00 heroku[scheduler.6047]: State changed from starting to up
2019-09-23T14:04:07.040168+00:00 heroku[scheduler.6047]: State changed from up to complete
2019-09-23T14:04:07.013558+00:00 heroku[scheduler.6047]: Process exited with status 0
2019-09-23T14:04:06.966168+00:00 app[scheduler.6047]: [2019-09-23 14:04:06] production.INFO: Hello heroku Scheduler!
2019-09-23T14:04:06.966187+00:00 app[scheduler.6047]: 
2019-09-23T14:12:09.872600+00:00 app[api]: Starting process with command `php artisan command:hello` by user scheduler@addons.heroku.com
2019-09-23T14:12:13.976692+00:00 heroku[scheduler.1815]: Starting process with command `php artisan command:hello`
2019-09-23T14:12:14.635017+00:00 heroku[scheduler.1815]: State changed from starting to up
2019-09-23T14:12:17.269609+00:00 heroku[scheduler.1815]: State changed from up to complete
2019-09-23T14:12:17.136798+00:00 app[scheduler.1815]: [2019-09-23 14:12:17] production.INFO: Hello heroku Scheduler!
2019-09-23T14:12:17.136827+00:00 app[scheduler.1815]: 
2019-09-23T14:12:17.243225+00:00 heroku[scheduler.1815]: Process exited with status 0
2019-09-23T14:21:47.840223+00:00 app[api]: Starting process with command `php artisan command:hello` by user scheduler@addons.heroku.com
2019-09-23T14:21:50.465803+00:00 heroku[scheduler.7897]: Starting process with command `php artisan command:hello`
2019-09-23T14:21:51.076322+00:00 heroku[scheduler.7897]: State changed from starting to up
2019-09-23T14:21:53.094749+00:00 heroku[scheduler.7897]: State changed from up to complete
2019-09-23T14:21:53.070247+00:00 heroku[scheduler.7897]: Process exited with status 0
2019-09-23T14:21:52.999636+00:00 app[scheduler.7897]: [2019-09-23 14:21:52] production.INFO: Hello heroku Scheduler!
2019-09-23T14:21:52.999659+00:00 app[scheduler.7897]:

2019-09-23 14:04:06、2019-09-23 14:12:17、2019-09-23 14:21:52とだいぶいい適当に10分おきに起動されていることが確認できます。

実行間隔を超えた場合の動作検証

HelloCommandのhandleメソッドを以下のように15分間10秒ごとにメッセージを出力するように書き換えてみます。

    public function handle()
    {
        for ($i = 1; $i <= 90; $i++) {
            Log::info('Hello heroku Scheduler! '. $i);        
            sleep(10);
        }
    }

再度ログを確認してみると確かにカウント62や65の出力の後強制的にDynoが停止していることが確認できました。
また、停止後10分間隔ですぐに次のジョブが起動することはなく3から5分おいてから起動するようです。

Sep 26 07:50:32 morning-bastion-21992 app/api: Starting process with command `php artisan command:hello` by user scheduler@addons.heroku.com 
Sep 26 07:50:34 morning-bastion-21992 heroku/scheduler.7896: Starting process with command `php artisan command:hello` 
Sep 26 07:50:34 morning-bastion-21992 heroku/scheduler.7896: State changed from starting to up 
Sep 26 07:50:37 morning-bastion-21992 app/scheduler.7896: [2019-09-26 14:50:36] production.INFO: Hello heroku Scheduler! 1   
Sep 26 07:50:46 morning-bastion-21992 app/scheduler.7896: [2019-09-26 14:50:46] production.INFO: Hello heroku Scheduler! 2   
Sep 26 07:50:56 morning-bastion-21992 app/scheduler.7896: [2019-09-26 14:50:56] production.INFO: Hello heroku Scheduler! 3   
中略
Sep 26 07:59:56 morning-bastion-21992 app/scheduler.7896: [2019-09-26 14:59:56] production.INFO: Hello heroku Scheduler! 57   
Sep 26 08:00:06 morning-bastion-21992 app/scheduler.7896: [2019-09-26 15:00:06] production.INFO: Hello heroku Scheduler! 58   
Sep 26 08:00:16 morning-bastion-21992 app/scheduler.7896: [2019-09-26 15:00:16] production.INFO: Hello heroku Scheduler! 59   
Sep 26 08:00:26 morning-bastion-21992 app/scheduler.7896: [2019-09-26 15:00:26] production.INFO: Hello heroku Scheduler! 60   
Sep 26 08:00:36 morning-bastion-21992 app/scheduler.7896: [2019-09-26 15:00:36] production.INFO: Hello heroku Scheduler! 61   
Sep 26 08:00:45 morning-bastion-21992 heroku/scheduler.7896: Idling 
Sep 26 08:00:45 morning-bastion-21992 heroku/scheduler.7896: State changed from up to complete 
Sep 26 08:00:46 morning-bastion-21992 heroku/scheduler.7896: Stopping all processes with SIGTERM 
Sep 26 08:00:46 morning-bastion-21992 app/scheduler.7896: [2019-09-26 15:00:46] production.INFO: Hello heroku Scheduler! 62   
Sep 26 08:00:46 morning-bastion-21992 heroku/scheduler.7896: Process exited with status 143 
Sep 26 08:04:07 morning-bastion-21992 app/api: Starting process with command `php artisan command:hello` by user scheduler@addons.heroku.com 
Sep 26 08:04:17 morning-bastion-21992 heroku/scheduler.9055: Starting process with command `php artisan command:hello` 
Sep 26 08:04:17 morning-bastion-21992 heroku/scheduler.9055: State changed from starting to up 
Sep 26 08:04:20 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:04:19] production.INFO: Hello heroku Scheduler! 1   
Sep 26 08:04:30 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:04:29] production.INFO: Hello heroku Scheduler! 2   
Sep 26 08:04:40 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:04:39] production.INFO: Hello heroku Scheduler! 3   
中略
Sep 26 08:13:40 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:13:39] production.INFO: Hello heroku Scheduler! 57   
Sep 26 08:13:50 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:13:49] production.INFO: Hello heroku Scheduler! 58   
Sep 26 08:14:00 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:13:59] production.INFO: Hello heroku Scheduler! 59   
Sep 26 08:14:10 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:14:09] production.INFO: Hello heroku Scheduler! 60   
Sep 26 08:14:20 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:14:19] production.INFO: Hello heroku Scheduler! 61   
Sep 26 08:14:30 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:14:29] production.INFO: Hello heroku Scheduler! 62   
Sep 26 08:14:40 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:14:39] production.INFO: Hello heroku Scheduler! 63   
Sep 26 08:14:50 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:14:49] production.INFO: Hello heroku Scheduler! 64   
Sep 26 08:15:00 morning-bastion-21992 app/scheduler.9055: [2019-09-26 15:14:59] production.INFO: Hello heroku Scheduler! 65   
Sep 26 08:15:08 morning-bastion-21992 heroku/scheduler.9055: Cycling 
Sep 26 08:15:08 morning-bastion-21992 heroku/scheduler.9055: State changed from up to complete 
Sep 26 08:15:09 morning-bastion-21992 heroku/scheduler.9055: Stopping all processes with SIGTERM 
Sep 26 08:15:09 morning-bastion-21992 heroku/scheduler.9055: Process exited with status 143 
Sep 26 08:20:53 morning-bastion-21992 app/api: Starting process with command `php artisan command:hello` by user scheduler@addons.heroku.com 
Sep 26 08:20:54 morning-bastion-21992 heroku/scheduler.5046: Starting process with command `php artisan command:hello` 
Sep 26 08:20:54 morning-bastion-21992 heroku/scheduler.5046: State changed from starting to up 
Sep 26 08:20:57 morning-bastion-21992 app/scheduler.5046: [2019-09-26 15:20:55] production.INFO: Hello heroku Scheduler! 1   
Sep 26 08:21:06 morning-bastion-21992 app/scheduler.5046: [2019-09-26 15:21:05] production.INFO: Hello heroku Scheduler! 2   
Sep 26 08:21:16 morning-bastion-21992 app/scheduler.5046: [2019-09-26 15:21:15] production.INFO: Hello heroku Scheduler! 3

hrendoh

,