【laravel 8.x】Logging の設定とログフォーマットの実装方法【基本編】

laravel のログにはPHPでよく使われているらしい Monolog が実装されている。
こいつをごにょごにょしていい感じにしたいのが本記事。
（簡潔に書きたかったがソースも書くと長くなるねぇ…）

Laravel は ver8.9.0。（v6くらいから同じだと思う）
目的はログのフォーマットの変更とカラーリング。

• ソース：ログ 8.x Laravel
• monolog：Seldaek/monolog: Sends your logs to files, sockets, inboxes, databases and various web services
• カラーリング： bramus/monolog-colored-line-formatter: Colored/ANSI Line Formatter for Monolog
• 大いに参考：Laravelでログのフォーマットを変えたい - Qiita

1. ログの出力方法

Laravel のログは RFC5424 ってので定義されている8つのレベルが扱える。
emergency > alert > critical > error > warning > notice > info > debug

ログを出力する方法は facade を使う方法と helper を使う方法の2種類（たぶん）。
デフォルトでは storage/logs/laravel.log に出力される。

Log Facade でログを出力する。

use Illuminate\Support\Facades\Log;

$name = 'sample kunn';
Log::info('Showing user: '.$name);
// => [2020-10-13 19:27:04] local.INFO Showing user: sample kunn

Log::notice('User failed to login.', ['id' => 3]);
// => [2020-10-13 19:32:38] local.INFO User failed to login. {"id":3}

第２引数(context) に渡したデータはシリアライズされて出力される（デフォルト）。

Logger Helper でログを出力する

logger()->info('sample text');
// => [2020-10-13 19:35:43] local.INFO sample text

どちらとも LogManager を内部で呼び出しているので使い方は同じっぽい。
RFC5424 の 8 つのレベルの関数が定義されているので使い分けるべし。
Facade と Helper、決めた方に統一して使うのが賢そう。
参考：Illuminate\Log\LogManager | Laravel API

local.xxx は .env の APP_ENV の値かな？
production とか local といった実行環境の値となる。

他のロガーでいうカテゴリやタイプといった塊は存在しない。（ほんとぉ？）
必要ならラッパーを作るなりする必要がありそう。

• Laravel ConsoleとHttpのログファイルを分ける - Qiita
  • この辺りを参考に processor にフィールドを追加させるのが最適解だと思う。

Exception ログ

use Exception;

logger()->error(new Exception('Reigai'));

Exception 系列を渡せば stackTrace も出力される。

2. ログの設定ファイル

基本的には app/config/logging.php に設定を書き込むだけで使える。

app/config/logging.php

'default' => env('LOG_CHANNEL', 'stack'),

'channels' => [
    'stack' => [
        'driver' => 'stack',
        'channels' => ['single'],
        'ignore_exceptions' => false,
    ],

    'single' => [
        'driver' => 'single',
        'path' => storage_path('logs/laravel.log'),
        'level' => 'debug',
    ],

    'daily' => [
        'driver' => 'daily',
        'path' => storage_path('logs/laravel.log'),
        'level' => 'debug',
        'days' => 14,
    ],

    'stderr' => [
        'driver' => 'monolog',
        'handler' => StreamHandler::class,
        'formatter' => env('LOG_STDERR_FORMATTER'),
        'with' => [
            'stream' => 'php://stderr',
        ],
    ],

    ...
]

channel というのはログの出力方法を指したもので、これを使ってログを出力する。
TVのチャンネルみたいに電波を分ける役割（でいいのかな？）。
デフォルトでは stack というものが指定されている。

stack だけは特殊で、プロパティの channels で指定した複数のチャンネルに処理を渡すことができる。
TVでいう多チャンネル同時視聴。
デフォルトでは ['single'] が指定されているので、single というチャンネル1つにログの出力を渡している。
single は logs/laravel.log に書き込むチャンネルなので、logファイルに追記されるわけだ。

初めから定義されていたチャンネルを以下にまとめる。

channel名	説明
stack	複数のチャンネルへログを渡す
single	指定したファイルにログを書き出す
daily	指定したファイルにログを書き出す（所謂ローテート） 一日ごとにファイルを区切り、一定の日数が経過したら削除する(任意)
slack	Slack に出力する
papertrail	Papertrail に出力する
stderr	標準エラー出力に出力する
syslog	Linux 等の syslog に出力する
errorlog	PHPの error_log() に出力する
null	何もしない
emergency	（emergency ログだけ出力？）

他にも SNS に送ったり DB に送ったりと、大抵のやりたいことは誰かがライブラリを実装してくれてる。

3. stdout channel の追加

log を使ってて思ったのが、cli を操作している時は標準出力にも出力して欲しい点。
stderr チャンネルは存在するので、それをベースに stdout チャンネルを作成してみる。

app/config/logging.php

'stdout' => [
    'driver' => 'monolog',
    'handler' => StreamHandler::class,
    'with' => [
        'stream' => 'php://stdout',
    ],
    'level' => 'debug', // all log
],

StreamHandler の stream パラメータにPHPの標準出力(stdout)を指定した。
level によって出力するログレベルを制限できるが、最低値の debug にすることにより、全てのログを対象としている。
試しに channels.stack.channels に stdout を追加すると標準出力にも出力されるようになるはず。

Handler は monolog 側のシステムなので今回は省く。
詳しくはこのあたり。

• ログ 8.x/ Laravel
  • の下の方の「Monologハンドラチャンネルの作成」
• monolog/02-handlers-formatters-processors.md at master · Seldaek/monolog
• Third Party Packages · Seldaek/monolog Wiki

[オプション] CLI実行時(php artisan)のみ標準出力にも出力する

このまま stack に追記でもいいのだが、CLIを操作していない時に標準出力に出力されるのはあまり好みではない。
（schedule 処理、http のアクセス時等にも出力されてしまう（握りつぶされるが））
なので CLI で実行したときに限って出力するようにしてみる。

App\Providers\AppServideProvider.php

class AppServiceProvider extends ServiceProvider
{
    public function boot()
    {
        ...
        // logger cli mode
        if(strpos(strtolower(php_sapi_name()), 'cli') !== false) {
            $path = 'logging.channels.stack.channels';
            $stacks = collect(config($path, []))
                ->push('stdout')
                ->unique();
            config([$path => $stacks]);
        }
    }
}

php_sapi_name() という関数を実行すると、apache や cli、cgi といった文字列が帰ってくる。
これを利用して、名前にCLIが含まれていたら stack に stdout を追加する仕組み。
collection の unique() を使うことで重複実装を防いでいる。

とりあえず AppServiceProvider に実装したが、 LoggerServideProvider とかを作って実装したほうが賢い。

参考：php - Detect if running from the command line in Laravel 5 - Stack Overflow

4. ログ文字列のフォーマット

さて本題。
デフォルトの出力文字列は以下のような形式だった。

これは monolog のデフォルトの Formatter\LineFormatter で以下が適用されているためである。
[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n
参照：monolog/LineFormatter.php at master · Seldaek/monolog

こいつを変更したいので LineFormatter を拡張した class を作成する。

App\Logging\Formatters\CustomLineFormatter.php

<?php

namespace App\Logging\Formatters;

use Monolog\Formatter\LineFormatter;

class CustomLineFormatter extends LineFormatter
{
    public function __construct()
    {
        // 2020-10-13 17:12:15.375 [local.INFO] log message という形式で出力
        $lineFormat = "%datetime% [%channel%.%level_name%] %message%" . PHP_EOL;
        $dateFormat = "Y-m-d H:i:s.v"; // PHP: DateTime::format

        parent::__construct($lineFormat, $dateFormat, true, true);
    }

    public function format(array $record): string
    {
        // var_dump($record);
        $output = parent::format($record);
        // var_dump($output);

        return $output;
    }
}

LineFormatter のコンストラクタは以下を引数に取る。

引数	説明
$format	フォーマット文字列
$dateFormat	日付(%datetime%)のフォーマット文字列 参考：PHP: DateTime::format - Manual
$allowInlineLineBreaks	ログの改行を許すか
$ignoreEmptyContextAndExtra	context と extra の値が空のときに [] を削除するかどうか

参照：monolog/LineFormatter.php at master · Seldaek/monolog

format() は今回は親のものを呼び出しているだけだが、ここでフォーマットのやり方を定義することができる。
引数の record 配列は以下の通り。

$record = [
    'message' => $message,
    'context' => $context,
    'level' => $level,
    'level_name' => $levelName,
    'channel' => $this->name,
    'datetime' => new DateTimeImmutable($this->microsecondTimestamps, $this->timezone),
    'extra' => [],
];

参照：monolog/Logger.php at master · Seldaek/monolog

ここで level や message を加工して parent::format($record) を呼べば、かなり自由度の高いことが可能だ。
context はログ関数実行時の第２引数（配列？オブジェクト？）。
今のままだと context は握りつぶされているので、
$record['message] .= json_encode($record['context']);みたいな実装が要るかも。

ここで DB に保存をかけたりしても面白そう。
参考にした文献だと context を vsprintf() に突っ込むことで printf() like な実装を示してた。
Levelに応じた絵文字とかタイマーとか実装できたら楽しそう。

extra は実行された行番号やIPアドレスなどを取得できるが、今回は扱わない。
processor という仕組みを使うのだが、この辺りが参考になるかも。

• Laravelのログにファイル名やメソッド名を出力する - Qiita
• Laravelでログのフォーマットを変えたい - Qiita

Laravel にフォーマットを適用する

laravel に適用するには tap という配列パラメータに __invoke() が実装されているクラスを指定してあげる必要がある。

参考：ログ 8.x/ Laravel
　　　の下の方の「チャンネル用Monologカスタマイズ」

App\Logging\LineFormatterApply.php

<?php

namespace App\Logging;

use App\Logging\Formatters\CustomLineFormatter;

class LineFormatterApply
{
    public function __invoke($logging)
    {
        $customLineFormatter = new CustomLineFormatter();

        foreach($logging->getHandlers() as $handler) {
            $handler->setFormatter($customLineFormatter);
        }
    }
}

おそらく CustomLineFormatter を指定があった handler 全てに渡すのだと思う。
（extend とか implements とかが無い暗黙実装は嫌いだぁ…）

これを config/logging の使わせたいチャンネルに指定してあげる。
今は stdout と single に。
（stack に渡すと全チャンネルに適用できるが、子で指定していた場合上書きされた）
（formatter は一つしか追加できない？）

app/config/logging.php

use App\Logging\LineFormatterApply;

'stdout' => [
    'driver' => 'monolog',
    'handler' => StreamHandler::class,
    'with' => [
        'stream' => 'php://stdout',
    ],
    'level' => 'debug',
    'tap' => [ColorFormatterApply::class], // <-- これ
],

こんな感じの出力に変えられた。

5. ログをカラフルに出力する

標準出力のログはやっぱり色が欲しい。
視認性も上がるし、なによりログの把握速度が圧倒的である。

調べると monolog 側に良さそうなライブラリがあった。
bramus/monolog-colored-line-formatter: Colored/ANSI Line Formatter for Monolog

console

composer require bramus/monolog-colored-line-formatter ~3.0

これをそのまま formatter 扱いで定義すると色が付くのだが、それでは先程作成した文字列のフォーマットが適用されない。
なので、CustomLineFormatter を拡張して色を付けることにする。

App\Logging\Formatters\ColorLineFormatter.php

<?php

namespace App\Logging\Formatters;

use Bramus\Monolog\Formatter\ColorSchemes\DefaultScheme;

// quote by:
// https://github.com/bramus/monolog-colored-line-formatter/blob/master/src/Formatter/ColoredLineFormatter.php
class ColorLineFormatter extends CustomLineFormatter
{
    private $colorScheme = null;

    public function getColorScheme()
    {
        if (!$this->colorScheme) {
            $this->colorScheme = new DefaultScheme();
        }

        return $this->colorScheme;
    }

    public function format(array $record) : string
    {
        $output = parent::format($record);

        $colorScheme = $this->getColorScheme();
        return $colorScheme->getColorizeString($record['level']).trim($output).$colorScheme->getResetString()."\n";
    }
}

parent::format($record) した後に、その文字列に level に応じた色を付ける。
ライブラリのフォーマット部分を参考に必要な処理を移植した形だ。
参考：monolog-colored-line-formatter/ColoredLineFormatter.php at master · bramus/monolog-colored-line-formatter

App\Logging\ColorFormatterApply.php

<?php

namespace App\Logging;

use App\Logging\Formatters\ColorLineFormatter;

class ColorFormatterApply
{
    public function __invoke($logging)
    {
        $coloredLineFormattetr = new ColorLineFormatter();

        foreach($logging->getHandlers() as $handler) {
            $handler->setFormatter($coloredLineFormattetr);
        }
    }
}

で、これを stdout のチャンネルの tap に指定すればOK。
※制御文字を使用しているので、ファイル出力には使わないように。

とてもいい感じになった。
ログのメッセージ部は白のままにしたい時は、正規表現でその部分だけ抜き取って色を付けると良いかも。

6. サンプル

自分が使用したいログの仕様をまとめて、それを実装したサンプルを置いておく。

• NOTICE 以上のログが1日毎に別のファイルに保存される daily チャンネル
  • 保存期間（days）は7日
• ERROR 以上のログが1つのファイルに保存される singleError チャンネル
• CLIで実行した際、全てのログが標準出力に色付きで出力される stdout チャンネル
  • これは AppServiceProvide で追加するので stack では触らない

App\Config\logging.php

use Monolog\Handler\StreamHandler;
use App\Logging\LineFormatterApply;
use App\Logging\ColorFormatterApply;

...

'channels' => [
    'stack' => [
        'driver' => 'stack',
        'channels' => ['dailyNotice', 'singleError'],
        'ignore_exceptions' => false,
    ],

    'singleError' => [
        'driver' => 'single',
        'path' => storage_path('logs/laravel_error.log'),
        'level' => 'error', // upper error log
        'tap' => [LineFormatterApply::class],
    ],

    'dailyNotice' => [
        'driver' => 'daily',
        'path' => storage_path('logs/laravel.log'),
        'level' => 'notice', // upper notice log
        'days' => 7,
        'tap' => [LineFormatterApply::class],
    ],

    'stdout' => [
        'driver' => 'monolog',
        'handler' => StreamHandler::class,
        'with' => [
            'stream' => 'php://stdout',
        ],
        'level' => 'debug', // all log
        'tap' => [ColorFormatterApply::class],
    ],
],

出力は以下の感じ。
log ファイルのカラーリングは VSCode の Log File Highlighter を使用している。

おわりに

monolog の handlerとprocessor 周りをまだ理解しきれてないので、とりあえず基本をまとめた。
あと laravel の Exception 周りも知らないといけないかも。

これ node-log4js より楽かもしれぬ。
個人的にタイマーは実装してみたい。
綺麗なログを吐けると開発が捗る捗る…。

続きは、今のログに手を入れるとき（書くとは言っていない）。