【Laravel】JSON形式でロギングして、ログに対してクエリをかける

　Laravel のロギング機能は Monolog を使用しており十分な拡張が可能です。
Seldaek/monolog： Sends your logs to files, sockets, inboxes, databases and various web services
【PHP】【Laravel】Monolog のログフォーマットを操作する – 株式会社シーポイントラボ ｜ 浜松のシステム・RTK-GNSS開発
　このロギング機能では多くの情報をログに残すことができます。可能な限り多くの情報を残したくもありますが、デフォルトの文字列ログのまま多くの情報を詰め込むと次の様にわけのわからないことになります。画像はクエリログのみなのでまだどうにかなりますが、形式や目的の違うログが混じり出すと悲惨なことになります。特に改行コードやエスケープすべき対象の扱いを間違えた時は awk や grep でどうにかしようとするとかなり辛いです。

　これの解決としてあらかじめ構造化された状態である JSON としてログを残すことが考えられます。これは次でできます。

<?php
 
namespace App\Logging;
 
use Monolog\Formatter\JsonFormatter;
use Monolog\Handler\FormattableHandlerInterface;
use Monolog\Handler\ProcessableHandlerInterface;
use Monolog\Logger;
use Monolog\Processor\IntrospectionProcessor;
use Monolog\Processor\ProcessIdProcessor;
use Monolog\Processor\UidProcessor;
use Monolog\Processor\WebProcessor;
 
class DetailFormatter
{
    /**
     * 渡されたロガーインスタンス（Monolog インスタンス）のカスタマイズ
     *
     * @param  Logger $monolog
     * @return void
     */
    public function __invoke($monolog)
    {
        // JSON 形式のフォーマッターを使用すると宣言
        $formatter = new JsonFormatter();
        
 
        $uidProcessor = new UidProcessor(); // プロセッサー単位のユニーク ID を発行する. handlers ループ外でインスタンス化しないと同じログがハンドラー毎に異なる UID を持つことになる
        // 出力先単位で foreach
        foreach ($monolog->getHandlers() as $handler) {
            if ($handler instanceof FormattableHandlerInterface) {
                // メッセージの形式が指定可能ならば JSON フォーマットを適用
                $handler->setFormatter($formatter);
            }
            if ($handler instanceof ProcessableHandlerInterface) {
                // Processor を扱えるならば各実行環境情報を持つ Processor を追加
                // コメントを書きやすいのでほぼ全てここで new
                // 同じ対象のログなのにハンドラーによってユニークIDが違うことになり惨事を招く UidProcessor のみループの外に記述
                $handler->pushProcessor(new IntrospectionProcessor(Logger::DEBUG, ['Illuminate\\'])); //  ログメッセージの発生源となった行/ファイル:クラス/関数
                $handler->pushProcessor(new WebProcessor()); // 現在のウェブリクエストの url/method とリモート IP
                $handler->pushProcessor(new ProcessIdProcessor()); // プロセスID
                $handler->pushProcessor($uidProcessor);
            }
        }
    }
}


// 次の様に第二引数にログに残す json_encode 対象を渡します
DB::connection()->listen(static function (QueryExecuted $query) {
    // Laravel のデータベースコネクションにクエリが実行されたらロギングを実行するように待ち受けを設定します
    Log::debug('query_log', [
        'sql'     => $query->sql,
        'params'  => $query->bindings,
        'time_ms' => $query->time
    ]);
});

　こうすると次の様に JSON 形式でログが残せます。

　このままでは結局読みにくいので JSON を取り扱うコマンドラインツールである jq を使います。単に

jq -s "." storage/logs/laravel-root-2020-12-02.log | less -F

とするだけで次の様になり読みやすくなります。

　この状態で less コマンド実行中の / による検索をつかっても良いのですが jq を使うことで更に扱いやすくなります。例えば、次の様に、 uid で検索してクエリログ部分だけ表示する、なんてこともできます。

 jq -s '.[] | select(.extra.uid == "53b6306") | {uid: .extra.uid, sql: .context}' storage/logs/laravel-root-2020-12-02.log | less -F

　例には入れていませんが、アクセスされたURLなども残すとデバッグの助けになりやすいです。