以前に弊社の津崎がElasticBeanstalkのワーカー環境の導入について紹介させていただきました。
弊社ではその後様々な定期実行のスケジュールを移行し、安定稼働に至っています！
ワーカー環境で実行されるコマンドが増えるにつれて、コマンドの実行状況をより詳細に確認したいというニーズが出てきました。
以下でどのように対応したのかを説明します。
Workerサーバーでスケジュールを実行する
弊社ではlaravel-aws-workerを利用しているので、Laravelのスケジュールの機能でElasticBeanstalk Workerからスケジュールを実行することができます。
app/Console/Kernel.phpに以下の様に書いていくことでコマンド実行の設定ができます
<?php namespace App\Console; use Illuminate\Console\Scheduling\Schedule; use Illuminate\Foundation\Console\Kernel as ConsoleKernel; class Kernel extends ConsoleKernel { /** * Define the application's command schedule. * * @param \Illuminate\Console\Scheduling\Schedule $schedule * @return void */ protected function schedule(Schedule $schedule) { $schedule->command('some-command') ->weeklyOn(1 /* 月曜日 */, '10:00') ->withoutOverlapping() ->onOneServer() ->runInBackground(); } } ?>
このようにして、月曜の10時にsome-commandを実行するという設定ができます。
課題
ここで問題になるのは、このコマンド実行はHTTPリクエスト経由の実行ではなくconsoleからのphpの実行だということです。Webサーバー経由での実行ではないので、Apacheのアクセスログ等は出ません。当たり前といえば当たり前なのですが…。標準出力にコマンドを実行したときのoutputが出るだけです。
しかし、これでは実際にコマンドがどのように実行されているのか細かく見ることができません。よって以下のような解決策を取っていきました。
解決策
実行時の標準出力相当のものをログに書き出す
コマンドのコードには、ログへの出力をするコードは書かれていませんでしたが、コマンドを人間が実行するためのテキスト等を出力するコードはちゃんと書かれていたのでこれを応用することにしました。command実行時の出力を同時にログファイルにも出力します。
Illuminate/Console/Command.phpを継承して以下のようなLoggableCommand.phpクラスを定義します。
<?php declare(strict_types=1); namespace App\Console\Commands\Base; use Illuminate\Console\Command; use Illuminate\Log\LogManager; abstract class LoggableCommand extends Command { public function info($string, $verbosity = null) { parent::info($string, $verbosity); $this->getLogger()->info($string); } public function warn($string, $verbosity = null) { parent::warn($string, $verbosity); $this->getLogger()->warning($string); } public function error($string, $verbosity = null) { parent::error($string, $verbosity); $this->getLogger()->error($string); } /** コマンド実行時までLoggerが生成されないので、ログに必要なときに都度生成 */ protected function getLogger() { $application = $this->getLaravel(); return $application->make(LogManager::class)->channel('command_log'); } } ?>
このクラスを継承することにより、コマンドを実行するとログファイルにコマンドの標準出力に出ているものと同じものがLogのformatにwrapされて書き出されます。 ログは以下のようにcommand_logのchannelに出力されます。
time:2020-11-24 21:37:15 level:INFO message:START some-command params:[]
Exceptionをキャッチする
コマンド実行時に発生するExceptionは何も設定しないとWebサーバー経由で起動されているPHPのerror_logと同じ箇所に出力されてしまいますが、先程のエラーと同様にcommand_logのchannelにコマンドログは統一したいです。
これにはapp/Exception/Handler.phpをカスタマイズすることで対応します。
<?php namespace App\Exceptions; class Handler extends ExceptionHandler { public function renderForConsole($output, Exception $e) { // コンソールコマンドはスケジューラーから実行される前提 $logger = $this->container->make(LogManager::class)->channel('command_log'); $logger->error("{$e->getMessage()} | {$e->getTraceAsString()}"); parent::renderForConsole($output, $e); } } ?>
renderForConsoleを実装することによってConsoleでのエラーのみこちらの関数が呼ばれるようにできます。
まとめ
Laravelのスケジューラー経由で実行されるコマンドのログを詳細に取る方法を説明しました。
- コマンドの標準出力に出力するとともにログに出力することで簡単にログへの書き込みが実装できました。
app/Exception/Handler.phpをカスタマイズすることでExceptionが発生した場合にもログ出力することができました。
これでスケジューラーから実行されるコマンドの内容も詳細にログに記録することができます。
