【Laravel】Command実行ログにトレースIDを付与するための共通処理を実装する #Laravel

はじめに

仕事で Laravel を使っています。
コマンドラインアプリケーションが出力するログに一律でトレースIDと実行コマンド名を付与したいという要望に対応したのですが、その際に色々な学びを得たので記事にして残しておこうと思います。

動作環境

だいぶ古い環境での実装方法になります。
より新しいバージョンのLaravelをお使いの場合は実装内容が異なる可能性があるので注意してください。

PHP

$ php --version

PHP 7.2.34 (cli) (built: Dec 19 2022 16:08:00) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.2.0, Copyright (c) 1998-2018 Zend Technologies
    with Xdebug v3.1.5, Copyright (c) 2002-2022, by Derick Rethans

Laravel

$ php artisan --version

Laravel Framework 5.8.37

Monolog

$ composer show -i | grep monolog

monolog/monolog           1.25.3           Sends your logs to files, sockets, inboxes, databases and various web services

背景知識

この Laravel アプリケーションにはすでにいくつものコマンドラインアプリケーションが実装されており、いずれもログ出力は Illuminate\Support\Facades\Log を使って行われています。
本記事では、サンプルとして以下のコマンドラインアプリケーションを使います。

app/Console/Commands/Sample.php

<?php

namespace App\Console\Commands;

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

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

    /**
     * The console command description.
     *
     * @var string
     */
    protected $description = 'Qiita記事の執筆用に作成したサンプルコマンドです。';

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

    /**
     * Execute the console command.
     *
     * @return mixed
     */
    public function handle()
    {
        Log::info('処理開始');

        Log::info('処理の経過状況を表す何かしらのメッセージ');

        Log::info('処理終了');
    }
}

また、ログ出力に関する設定は以下のようになっています。

.env

APP_ENV=dev
LOG_CHANNEL=daily_log

config/logging.php

<?php

return [

    // ...前略...

    'channels' => [
    
        'daily_log' => [
            'driver' => 'daily',
            'path' => storage_path('logs/laravel.log'),
            'level' => 'info',
            'days' => 14,
            'permission' => 0666,
        ],
        
    ],
];

この状態で先のコマンドラインアプリケーションを実行した場合、次のようなフォーマットでログ出力がなされます。

# サンプルコマンドが正常に実行されてプロンプトが返ってきたとします。
$ php artisan something:do

# YYYY-MM-DDの部分は、実際にはログ出力日時に置き換えられます
$ cat storage/logs/laravel-YYYY-MM-DD.log
[2023-12-03 08:22:12] dev.INFO: 処理開始
[2023-12-03 08:22:12] dev.INFO: 処理の経過状況を表す何かしらのメッセージ {"hoge":"fuga"}
[2023-12-03 08:22:12] dev.INFO: 処理終了

ログフォーマットのビフォー・アフター

具体的な実装内容に入る前に、ログフォーマットのビフォー・アフターに触れておきます。

ビフォー

[%datetime%] %channel%.%level_name%: %message% %context%

アフター

ログの構成要素に大きな違いはありませんが、付加情報として『実行したコマンド名』と『トレースID』を付与します。

[%datetime%] %channel%.%level_name%: [%extra.command%][%extra.trace_id%] %message% %context%

やったこと

ログチャンネルの新設とCustomFormatterの作成する
コマンドラインアプリケーション実行時のログチャンネルを変更する
トレースIDを付与する
実行コマンド名を付与する

ログチャンネルの新設とCustomFormattterの作成

ログフォーマットを変更したいのはコマンドラインアプリケーションだけなので、Webアプリケーションとして出力されるログが本対応の影響を受けないよう、ログチャンネルを分けることにしました。¹

config/logging.php

<?php

return [

    // ...前略...

    'channels' => [
    
        'daily_log' => [
            'driver' => 'daily',
            'path' => storage_path('logs/laravel.log'),
            'level' => 'info',
            'days' => 14,
            'permission' => 0666,
        ],

+       // 記事内で言及していませんが、日次ログである点やログ出力先などはあえて同じにしています。
+       'command_log' => [
+           'driver' => 'daily',
+           'path' => storage_path('logs/laravel.log'),
+           'level' => 'info',
+           'days' => 14,
+           'tap' => [App\Logging\CommandFormatter::class],
+           'permission' => 0666,
+       ],
        
    ],
];

daily_logとcommand_logの大きな違いはtapという設定項目の有無です。
tapが設定されていると Monolog インスタンスを生成する過程で、設定値に定義された配列のクラスの__invoke()メソッドが走ります。
この__invoke()メソッド内でMonologインスタンスをカスタマイズすることで要件に応じたログフォーマットの出力を目指します。²

したがってApp\Logging\CommandFormatterも合わせて実装する必要があります。

app/Logging/CommandFormatter.php

<?php

namespace App\Logging;

use App\Logging\Formatters\CustomLineFormatter;

class CommandFormatter
{
    public function __invoke($logger)
    {
        foreach ($logger->getHandlers() as $handler) {
            // この時点ではまだ大したカスタマイズは行なっていません。
            // 使用するフォーマッタを`CustomLineFormatter`にしているだけです。
            // `CustomLineFormatter`の実装内容についてはすぐ下のコードブロックを参照してください。
            $handler->setFormatter(new CustomLineFormatter());
        }
    }
}

app/Logging/Formatters/CustomLineFormatter.php

<?php

namespace App\Logging\Formatters;

use Monolog\Formatter\LineFormatter;

// LineFormatterを継承したカスタムクラスを実装します
class CustomLineFormatter extends LineFormatter
{
    // とりあえずカスタマイズしたことが分かるように`テストです:`という文字列を必ず付与するようにしてみます。
    const LINE_FORMAT = "[%datetime%] %channel%.%level_name%: テストです: %message% %context%\n";
    const DATE_FORMAT = "Y-m-d H:i:s";

    public function __construct()
    {
        parent::__construct(self::LINE_FORMAT, self::DATE_FORMAT, true, true);
    }
}

これでcommand_logチャンネルを指定したログ出力時にログフォーマットを変更できるようになりました。

コマンドラインアプリケーション実行時のログチャンネルを変更する

先ほど実装したログファイルのカスタマイズが効いているか確認を兼ね、このタイミングでコマンドラインアプリーション実行時に使用するログチャンネルをcommand_logに切り替えます。

今回、コマンドラインアプリケーション実行時は等しくこのログフォーマットを適用したいので、ログチャンネルの切り替えは共通処理として実装します。³

app/Listeners/CommandStartingListener

<?php

namespace App\Listeners;

class CommandStartingListener
{
    /**
     * Handle the event.
     *
     * @param  object  $event
     * @return void
     */
    public function handle($event)
    {
        // コマンド実行時にログチャンネルを`command_log`に変更する。
        config(['logging.default' => 'command_log']);
    }
}

app/Listeners/CommandFinishedListener

<?php

namespace App\Listeners;

class CommandFinishedListener
{
    /**
     * Handle the event.
     *
     * @param  object  $event
     * @return void
     */
    public function handle($event)
    {
        // 念の為、コマンド実行後はログチャンネルを標準設定に戻す。
        config(['logging.default' => env('LOG_CHANNEL')]);
    }
}

app/Providers/EventServiceProvider.php

<?php

namespace App\Providers;

+ use App\Listeners\CommandFinishedListener;
+ use App\Listeners\CommandStartingListener;
+ use Illuminate\Console\Events\CommandFinished;
+ use Illuminate\Console\Events\CommandStarting;
use Illuminate\Support\ServiceProvider;

class EventServiceProvider extends ServiceProvider
{
    protected $listen = [
        // ...他にも登録しているイベントリスナーがあるかもですが省略...
+       CommandStarting::class => [
+           CommandStartingListener::class
+       ],
+       CommandFinished::class => [
+           CommandFinishedListener::class
+       ],
    ];

    /**
     * Register services.
     *
     * @return void
     */
    public function register()
    {
        // ...省略...
    }

    /**
     * Bootstrap services.
     *
     * @return void
     */
    public function boot()
    {
        // ...省略...
    }
}

config/app.php

<?php

return [

    // ...省略...

    /*
    |--------------------------------------------------------------------------
    | Autoloaded Service Providers
    |--------------------------------------------------------------------------
    |
    | The service providers listed here will be automatically loaded on the
    | request to your application. Feel free to add your own services to
    | this array to grant expanded functionality to your applications.
    |
    */

    'providers' => [
+       // 無かったら追加してください。
+       App\Providers\EventServiceProvider::class,
    ],

    // ...省略...
];

イベントリスナーへの追加が完了したので、実際にコマンドラインアプリケーションを実行してログの内容を確認してみます。
出力した全てのログに、先ほどログフォーマットをカスタマイズした時に記述したテストです:が付与されているのがわかります。

# サンプルコマンドが正常に実行されてプロンプトが返ってきたとします。
$ php artisan something:do

# YYYY-MM-DDの部分は、実際にはログ出力日時に置き換えられます
$ cat storage/logs/laravel-YYYY-MM-DD.log
[2023-12-03 08:28:59] dev.INFO: テストです: 処理開始 
[2023-12-03 08:28:59] dev.INFO: テストです: 処理の経過状況を表す何かしらのメッセージ {"hoge":"fuga"}
[2023-12-03 08:28:59] dev.INFO: テストです: 処理終了

トレースIDを付与する

ここまで来たらいよいよログフォーマットを要件通りのものにしていきます。
まずはトレースIDを付与します。

トレースIDの定義はシステム要件によって変わると思いますが、今回は以下の2点を満たすこととします。

半角英数字で構成されたランダムな12桁の文字列であること
コマンドラインアプリケーションの同一プロセス内であれば変化せず、異なるプロセスであれば異なる値となること

そこで色々調べていたところ、Monolog には Processor という機能があり、ログに付帯する情報を拡張できることを知りました。⁴
今回はこのうち UidProcessor というものを使い、プロセスごとに生成される UID をトレースIDとして利用することにしました。

app/Logging/CommandFormatter.php

<?php

namespace App\Logging;

use App\Logging\Formatters\CustomLineFormatter;
+ use Monolog\Processor\UidProcessor;

class CommandFormatter
{
    public function __invoke($logger)
    {
+       $uidProcessor = new UidProcessor(12);
+       
        foreach ($logger->getHandlers() as $handler) {
+           $handler->pushProcessor($uidProcessor);
            $handler->setFormatter(new CustomLineFormatter());
        }
    }
}

app/Logging/Formatters/CustomLineFormatter.php

<?php

namespace App\Logging\Formatters;

use Monolog\Formatter\LineFormatter;

// LineFormatterを継承したカスタムクラスを実装します
class CustomLineFormatter extends LineFormatter
{
-   // とりあえずカスタマイズしたことが分かるように`テストです:`という文字列を必ず付与するようにしてみます。
-   const LINE_FORMAT = "[%datetime%] %channel%.%level_name%: テストです: %message% %context%\n";
+   const LINE_FORMAT = "[%datetime%] %channel%.%level_name%: [%extra.trace_id%] %message% %context%\n";
    const DATE_FORMAT = "Y-m-d H:i:s";

    public function __construct()
    {
        parent::__construct(self::LINE_FORMAT, self::DATE_FORMAT, true, true);
    }

+   public function format(array $record): string
+   {
+       // 変数 $record に出力するログの各種情報が格納されています。
+       // UidProcessor を利用すると $record['extra']['uid'] が追加されるので、
+       // トレースIDのプレースホルダである %extra.trace_id% を置換できるように $record['extra']['trace_id'] に値を格納します。
+       //
+       // ちなみにシステム要件に合ったトレースIDを生成する必要がある場合は、ここで代入する値を変更してあげれば良いです。
+       // その場合は CommandFormatter における UidProcessor のインスタンス化および pushProcessor() は必要ありません。
+       $record['extra']['trace_id'] = $record['extra']['uid'] ?? 'null';
+       return parent::format($record);
+   }
}

UidProcessor を使って UID を生成し、それをトレースIDとしてログに付与できるようにフォーマットを変更しました。
期待通りのログが出力できるか確認してみると、同一プロセス内であれば同じ値が付与され、再度実行した際には別の値が付与されていることが分かります。

# 1回目
$ php artisan something:do
$ storage/logs/laravel-YYYY-MM-DD.log
[2023-12-03 09:14:38] dev.INFO: [86f24ea461ef] 処理開始 
[2023-12-03 09:14:38] dev.INFO: [86f24ea461ef] 処理の経過状況を表す何かしらのメッセージ {"hoge":"fuga"}
[2023-12-03 09:14:38] dev.INFO: [86f24ea461ef] 処理終了

# 2回目
$ php artisan something:do
$ storage/logs/laravel-YYYY-MM-DD.log
[2023-12-03 09:19:53] dev.INFO: [3ed265265028] 処理開始 
[2023-12-03 09:19:53] dev.INFO: [3ed265265028] 処理の経過状況を表す何かしらのメッセージ {"hoge":"fuga"}
[2023-12-03 09:19:53] dev.INFO: [3ed265265028] 処理終了

# 3回目
$ php artisan something:do
$ storage/logs/laravel-YYYY-MM-DD.log
[2023-12-03 09:20:08] dev.INFO: [bb96fee63619] 処理開始 
[2023-12-03 09:20:08] dev.INFO: [bb96fee63619] 処理の経過状況を表す何かしらのメッセージ {"hoge":"fuga"}
[2023-12-03 09:20:08] dev.INFO: [bb96fee63619] 処理終了

実行コマンド名を付与する

続けて実行コマンド名を付与します。
実行コマンド名を取得できるような Processor が見つからなかったため、別の手段で CustomLineFormatter に情報を引き渡す必要があります。⁵

今回は実行コマンド名を Singleton に登録して、それを別クラスで参照するという方法にしました。
Signletonパターンであれば、コマンドラインアプリケーションの実行中に一度登録した実行コマンド名が不当に置き換わる心配がないと考えたためです。

app/Listeners/CommandStartingListener

<?php

namespace App\Listeners;

class CommandStartingListener
{
    /**
     * Handle the event.
     *
     * @param  object  $event
     * @return void
     */
    public function handle($event)
    {
        // コマンド実行時にログチャンネルを`command_log`に変更する。
        config(['logging.default' => 'command_log']);

+       // 実行コマンド名をSingletonで保持する。
+       app()->singleton('command_name', function () use ($event) {
+           return $event->command;
+       });
    }
}

app/Logging/Formatters/CustomLineFormatter.php

<?php

namespace App\Logging\Formatters;

use Monolog\Formatter\LineFormatter;

// LineFormatterを継承したカスタムクラスを実装します
class CustomLineFormatter extends LineFormatter
{
-   const LINE_FORMAT = "[%datetime%] %channel%.%level_name%: [%extra.trace_id%] %message% %context%\n";
+   const LINE_FORMAT = "[%datetime%] %channel%.%level_name%: [%extra.command%][%extra.trace_id%] %message% %context%\n";
    const DATE_FORMAT = "Y-m-d H:i:s";

    public function __construct()
    {
        parent::__construct(self::LINE_FORMAT, self::DATE_FORMAT, true, true);
    }

    public function format(array $record): string
    {
        // 変数 $record に出力するログの各種情報が格納されています。
        // UidProcessor を利用すると $record['extra']['uid'] が追加されるので、
        // トレースIDのプレースホルダである %extra.trace_id% を置換できるように $record['extra']['trace_id'] に値を格納します。
        //
        // ちなみにサービス要件に合ったトレースIDを生成する必要がある場合は、ここで代入する値を変更してあげれば良いです。
        // その場合は CommandFormatter における UidProcessor のインスタンス化および pushProcessor() は必要ありません。
        $record['extra']['trace_id'] = $record['extra']['uid'] ?? 'null';
+
+       // CommandStartingListener で Singleton に登録した実行コマンド名を取得します。
+       // 実行コマンド名のプレースホルダである %extra.command% を置換できるように $record['extra']['command']　に取得した値を格納します。
+       $record['extra']['command'] = app()->bound('command_name') ? app('command_name') : 'UNKNOWN';
+
        return parent::format($record);
    }
}

実行コマンド名を Singleton に格納し、それをログに付与できるようにフォーマットを変更しました。
期待通りのログが出力できるか確認してみると、実行コマンド名が付与されていることが分かります。

$ php artisan something:do
$ storage/logs/laravel-YYYY-MM-DD.log
[2023-12-03 09:45:47] dev.INFO: [something:do][670d75ff6b0e] 処理開始 
[2023-12-03 09:45:47] dev.INFO: [something:do][670d75ff6b0e] 処理の経過状況を表す何かしらのメッセージ {"hoge":"fuga"}
[2023-12-03 09:45:47] dev.INFO: [something:do][670d75ff6b0e] 処理終了

これで、コマンドラインアプリケーションが出力するログに、一律でトレースIDと実行コマンド名を付与したいという要望に応えることができました。

おわりに

今回の対応を通して以下の点で学びを得ることができました。

Monolog におけるログフォーマットのカスタマイズ方法
Monolog には Processor という機能がありログの付帯情報を拡張できるということ
Command の Before/After 処理の方法

ただし、本対応は Laravel 5.8 と、かなり古いバージョンの Laravel に対して施したものになるため、モダンなバージョンでは実装方法が変わっているかもしれません。
時間を作って「もっと新しいバージョンのLaravelの場合はどうなるか？」についても調査してみたいと思います。

余談

実はこの実装方法に辿り着く前に「BaseCommandなる抽象クラスを作り、各Commandはそれを継承することでBefore/After処理を行う」という方法での共通化を考えていました。

app/Console/Commands/BaseCommand.php

<?php

namespace App\Console\Commands;

use Illuminate\Console\Command;

abstract class BaseCommand extends Command
{
    public function __construct()
    {
        parent::__construct();

        // CommandStartingListenerでやってたことをここでやる。
    }

    public function __destruct()
    {
        // CommandFinishedListenerでやってたことをここでやる。

        parent::__destruct();
    }

    abstract public function handle();
}

結論として、Singletonパターンに違反するためエラーとなってしまいます。
理由としては php artisan を実行したタイミングで Command 群は全てインスタンス化されるため、複数回 __construct() が走った結果、Singleton に登録した実行コマンド名を上書きしようとするからです。
https://qiita.com/k-kurikuri/items/cec750ec3d21c6319253

とはいえ最初はこの仕様を知らずしばらくハマってました…
共通処理を入れたい時、安易に親クラスを作ってやればOK！みたいな考えは改めるべきだと感じた一件でした。

ログチャンネルの概念についてはこちらの記事が大変参考になりました。
https://tech.quartetcom.co.jp/2018/05/31/monolog/ ↩
Laravelのログ出力に関するより詳しい情報については公式リファレンスを参照してください。
https://readouble.com/laravel/5.8/ja/logging.html ↩
コマンドラインアプリケーションのbefore/after処理はについてはこちらの記事が大変参考になりました。
https://www.larajapan.com/2022/05/16/command%E3%81%ABbefore-after%E5%87%A6%E7%90%86%E3%82%92%E8%BF%BD%E5%8A%A0%E3%81%99%E3%82%8B/ ↩
Processorの全容は公式リファレンスを参照してください。
https://github.com/Seldaek/monolog/blob/main/doc/02-handlers-formatters-processors.md#processors ↩
一応ntrospectionProcessorというものを使えばファイル名やクラス名などは取得できるので、仕様的に問題なければこちらを使うもの良いと思います。
https://github.com/Seldaek/monolog/blob/main/src/Monolog/Processor/IntrospectionProcessor.php ↩