Laravel(monolog)で構造化ログを実装する

構造化ログ

JSON形式でログを出力しちゃおう、という話です。
構造化ロギング

例

人間にわかりやすいログ

[2019-05-23 10:42:51] local.ERROR: Division by zero in /var/www/hoge.jp/app/Dummy.php:81

構造化ログ

{"level":"ERROR","datetime":"2019-06-04 04:54:32","env":"local","message":"Division by zero","file":"\/var\/www\/hoge.jp\/app\/Dummy.php","line":81,"extra":[]}

なにがいいのか

例えば本番環境のログを調べたいときに、サーバ８台分のログ全部をgrepして、tailして、catして…とかは正直うんざりです。場合によってはawkが必要だったり、perlあたりでなにかコマンド書く必要があるかもしれません。

ならば最初からJSONで出力し、かつ大枠のフォーマットを決めておけばどうでしょう。
ログをElasticsearchなどに投入しておけば、あとでKIBANAを用いていくらでも検索が可能で、目的のログをいち早く分析できます。2019-01-01 00:00:00〜2019-03-31 23:59:59までのAWS S3に関するエラーコード「ERR-００１」のログ一覧を表示、なんてことも容易になります。

Laravelで構造化ログを出力する

Laravelで、と書いてますが Laravelはmonologを使っています ので、monolog で、ということになります。

monolog

詳細は省いて概要だけまとめます。

Handler

monologの物理的な出力を管理するのがHandlerです。
例えばRedisにログを吐き出すHandlerや、ログローテートをしてくれるHandlerなどがあります。

Formatter

読んで字のごとく、ログのフォーマットを管理します。Handlerに設定できます。

構造化ログに変換するには

上記から察するに Formatter でごにょごにょすればよさそうです。

受け渡す情報はどうするか

しかし、ログメッセージからどのように情報を取得すればいいでしょうか。
2019-01-01 00:00:00〜2019-03-31 23:59:59までのAWS S3に関するエラーコード「ERR-００１」のログ一覧を出すためには、少なくとも「AWS S3に関するログだよ」＆「エラーコードはERR-001だよ」を渡したいですが

Log::error('ERROR!');

上記のようなLaravelのログファサードを使って情報を詰めるにはちょっと限界がありそうです。

context

しかし、ログファサードには第２引数を記述することができます。配列で指定するcontextは、好きなものを詰めてログにわたすことができます。

Log::error('ERROR！', ['genre' => 'AWS-S3', 'code' => 'ERR-001']);

こんな感じで情報は引き渡せます。

Formatterの記述

じつに簡単です。サンプルプログラムを見てもらうと分かる通り、ただの配列操作です。最後にjsonにしてreturnします。
今回はNormalizerFormatterを継承し、それをオーバーライドする形で記述してみました。

<?php
declare(strict_types=1);

namespace App\Logging\Formatters;

use Carbon\Carbon;
use Illuminate\Hashing\HashManager;
use Monolog\Formatter\NormalizerFormatter;

/**
 * Class ApplicationLogFormatter
 * @package App\Logging\Formatters
 */
class ApplicationLogFormatter extends NormalizerFormatter
{
    /**
     * @var array
     */
    private $keys = [
        'code',
        'genre',
    ];

    /**
     * ログフォーマッタ
     * @param array $record
     * @return string
     */
    public function format(array $record): string
    {
        $formatted = parent::format($record);
        $segments = [
            'level' => $formatted['level_name'],
            'datetime' => $formatted['datetime'],
            'env' => $formatted['channel'],
            'message' => $formatted['message'],
            'extra' => $formatted['extra'],
        ];

        foreach ($this->keys as $key) {
            if (isset($formatted['context'][$key])) {
                $segments[$key] = $formatted['context'][$key];
            }
        }
        return json_encode($segments) . PHP_EOL;
    }
}

Formatterを設定する

Laravelのマニュアルにあるように、独自のFormatterを設定するには、ロガーインスタンスのカスタマイズが必要です。
しかし難しいことはなにひとつなく、なんとconfigに書くだけです。

'single' => [
    'driver' => 'single',
    'tap' => [App\Logging\Customizer::class],
    'path' => storage_path('logs/laravel.log'),
    'level' => 'debug',
],

<?php

namespace App\Logging;

use App\Logging\Formatters\ApplicationLogFormatter;

class Customizer
{
    /**
     * Customize the given logger instance.
     *
     * @param  \Illuminate\Log\Logger  $logger
     * @return void
     */
    public function __invoke($logger)
    {
        foreach ($logger->getHandlers() as $handler) {
            $handler->setFormatter(app()->make(ApplicationLogFormatter::class));
        }
    }
}

サンプル

{"level":"ERROR","datetime":"2019-06-04 04:54:32","env":"local","message":"ERROR!","genre":"AWS-S3","code":"ERR-001","extra":[]}

この形でElasticsearchなどに登録されていれば、ログは一気に見つけやすく、分析しやすくなります。

まとめ

上記は簡単なサンプルだけですので、例えばException発生時のtrace情報はどうしよう、とかいろいろ設定の余地があります。
しかし、大体は配列と文字列操作だけの話なので、特段難しいことはないと思います。

自分の環境ではlocal環境では通常のログ、dev環境以降は構造化ログにしてみたり、contextのキーをいちいち書くのが面倒なので、オリジナルのLoggerファサードを作り、

AppLog::genre('AWS-S3')->code('ERR-001')->error('ERROR!);

みたいな記述ができるようにしています。