ログって結構大事ですよね。
手軽にちゃんと情報がだせるLoggerを定義しておいて、いい開発・運用環境作りたいです。

この記事では、ElasticSearch等に突っ込んでログを検索可能にすることを前提に、いい感じにログ出力することを目指します。

環境

Laravel 5.8

やりたいこと

Laravelのログをカスタマイズして、いい感じにする。

いい感じとは

Laravel上で生じたイベントを記録し、問題が生じた際に、原因の究明と対応を迅速に行えるようにする。

この辺はログ指針を立てることで、目的を明文化します。

(参考)
ログ出力指針の書き方 - White Box技術部
https://seri.hatenablog.com/entry/2018/10/20/172656

どうするか

この記事ではログ出力にフォーカスします

ロギングに関しては、二つの段階があると思います。

ログ出力
ログ検索

ここでは、ログ出力に際して、実装者が考えることを最小限にし、ログ出力のたびに毎度考えることを減らすための方策を書きます。検索に関しては、ElasticSearchに突っ込む想定だけしておいて、詳細についてはまた別の機会に書きます。

何を出力するか

そのためには、

アプリケーションの操作者
いつそのイベントが起きたか
どこでイベントが起きたか
何が起きたか
そのイベントはそれくらい重大か/すぐに対応が必要か

を適切に伝える必要があります。

そして、これを、なるべく実装者が余計なことを考えないで実装するようにしたい。

理想は、以下くらい書いたら必要なこと全部わかるくらいにしたい。

\Log::info('Fail to get user own posts.');

すると、以下の内容は、自動で出力したいなってところです。

操作者情報
いつイベントが起きたか
どこで起きたか

まとめ

操作者情報といつ・どこで起きたかに関して、ロガーに実装者が情報を渡さなくてもよしなに出力される。

ことを目標にして、Laravelの実装を以下で進めようと思います。

やること

以下の二つのログ出力を実装します。

イベントログ

実装者によって、Loggerを使って出力するように実装するログです。
ログインの実装をしていればログインのログを、
APIとのやり取りではパラメータの内容などを残すこともあるでしょう。

datetime:2020-01-08 14:48:23    channel:local   level_name:INFO message:fugafuga     uid:e86d557c07  file:/var/www/app/Http/Controllers/HomeController.php   line:30 class:App\Http\Controllers\HomeController       function:index

アクションログ

リクエストごとに生成されるログです。
ここに、ユーザーID、セッションID、リクエストIDを付与する事で、これらの関連づけをします。

※ （追記）セッションIDは、Laravelでは暗号化されて表向きに使われるとはいえ、そのまま残すとセキュリティ的に不安が残るという指摘をいただいたので、ハッシュ化することを推奨します。

datetime:2020-01-08 14:48:23    channel:local   level_name:INFO message:action_log      user_id:0       session_id:c00b8c1116c6958a66ad799b     uid:e86d5  url:/   ip:172.25.12.11   http_method:GET server:localhost   referrer:http://localhost/fuga

リクエストと各イベントの関連づけをしておけば、エラーログが検出された時にその前後の操作が追えます。

実装

共通

LTSVフォーマットライブラリ導入

解析の際に、LTSV形式だと簡単になりそうなのでLTSVで出力します。

Laravelのロガーで使われているMonologでLTSVを使うには、以下のライブラリが良さそうなので、これを入れます。

※Laravel5だとMonologのバージョンが1系で、Laravel6はバージョン2です。それに伴って、上記のライブラリもバージョンが1→2に変わっていますので、それぞれの環境に合わせて使うといいと思います。

イベントログ

ログのカスタマイズについては以下が参考になります。

Monologチャンネルの上級カスタマイズ | ログ 5.8 Laravel
https://readouble.com/laravel/5.8/ja/logging.html#customizing-monolog-for-channels

Laravelのログにファイル名やメソッド名を出力する
https://qiita.com/iakio/items/7b8539db928d2b419921

Laravelでログのフォーマット変更する方法 - ノーバグノーライフ
https://blog.nobug-nolife.com/entry/20181202/1543762300

Seldaek/monolog
https://github.com/Seldaek/monolog

ログの設定を追加

Laravel5.8だと、config/logging.php でログのチャンネルを設定できます。

デフォルトだとstack チャネルを使っていて、stackチャネルはdailyチャネルにその詳細が定義されてます。今回は、日付ごとにファイルを分けて出力されるようにしてOKなので、dailyチャネルのまま、フォーマットを変えていきます。

config/logging.php


   'daily' => [
       'driver' => 'daily',
       'path' => storage_path('logs/laravel.log'),
+      'tap' => ['App\Logging\CustomizeFormatter'],
       'level' => 'debug',
       'days' => 14,
   ],

フォーマッタを実装

app/Logging/CustomizeFormatter.php

<?php

namespace App\Logging;
use Hikaeme\Monolog\Formatter\LtsvFormatter;
use Monolog\Logger;
use Monolog\Processor\IntrospectionProcessor;

class CustomizeFormatter
{
    public function __invoke($logger)
    {
        $uidprocessor = app()->make('Monolog\Processor\UidProcessor');
        $introprocessor = new IntrospectionProcessor(Logger::DEBUG, [
            'Monolog\\',
            'Illuminate\\',
        ]);
        $ltsvformatter = new LtsvFormatter(
            'Y-m-d H:i:s',
            [
                'datetime' => 'datetime',
                'channel' => 'channel',
                'level_name' => 'level_name',
                'message' => 'message',
            ]
        );
        foreach ($logger->getHandlers() as $handler) {
            $handler->setFormatter($ltsvformatter);
            $handler->pushProcessor($introprocessor);
            $handler->pushProcessor($uidprocessor);
        }
    }
}

    public function register()
    {
+        $this->app->singleton(UidProcessor::class, function ($app) {
+            return new UidProcessor(10);
+        });

    }

リクエストごとにuidを一意にするために、UidProcessorはsingletonとして登録しています。そうじゃないと、ログごとにuidが変わってしまいます。

アクションログ

ログ設定を追加

config/logging.php

+        'action' => [
+            'driver' => 'daily',
+            'path' => storage_path('logs/laravel.log'),
+            'tap' => ['App\Logging\ActionLogFormatter'],
+            'level' => 'debug',
+            'days' => 14,
+        ],

フォーマッタ実装

イベントログと共通のuidと、リクエスト情報が出力されるようにします。

app/Logging/ActionLogFormatter.php

<?php

namespace App\Logging;
use Hikaeme\Monolog\Formatter\LtsvFormatter;
use Monolog\Processor\WebProcessor;

class ActionLogFormatter
{
    public function __construct()
    {
    }
    public function __invoke($logger)
    {
        $uidprocessor = app()->make('Monolog\Processor\UidProcessor');
        $webprocessor = new WebProcessor();
        $ltsvformatter = new LtsvFormatter(
            'Y-m-d H:i:s',
            [
                'datetime' => 'datetime',
                'channel' => 'channel',
                'level_name' => 'level_name',
                'message' => 'message',
            ]
        );
        foreach ($logger->getHandlers() as $handler) {
            $handler->setFormatter($ltsvformatter);
            $handler->pushProcessor($webprocessor);
            $handler->pushProcessor($uidprocessor);
        }
    }
}

ミドルウェアに登録

ミドルウェアに登録し、アクションログを取得したいルーティングに設定します。

app/Http/Kernel.php

+        'action_log' => \App\Http\Middleware\ActionLogMiddleware::class,

route/web.php

Route::group(['middleware' => 'action_log'], function () {
   ...対象にしたいroute
});

app/Http/Middleware/ActionLogMiddleware.php

<?php

namespace App\Http\Middleware;
use Closure;
use Illuminate\Support\Facades\Auth;

class ActionLogMiddleware
{
    /**
     * Handle an incoming request.
     *
     * @param  \Illuminate\Http\Request  $request
     * @param  \Closure  $next
     * @return mixed
     */
    public function handle($request, Closure $next)
    {
        $user_id = Auth::id() ?? 0;  // 今回はLaravelのAuthの仕組みを使っているので、そこから取得されるidをuser_idとして使います。
        $session_id = session()->getId();
        \Log::channel('action')->info('action_log', [
            'user_id' => $user_id,
            'session_id' => $this->hash($session_id),
        ]);
        $response = $next($request);
        return $response;
    }

    private function hash($string)
    {
        return ハッシュ化ロジック($string);
    }
}

おまけ

以上の設定をすると、ログがLTSVで出力されるようになるのですが、stack traceの改行も半角スペースに置換されるので、デバッグの際にちょっと見づらいです。

そこで、デフォルトのログ設定をlocalチャネルとしておき、開発環境ではそちらを使うようにします。

config/logging.php

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

ローカルの.envは以下に書き換えます。

.env

- LOG_CHANNEL=stack
+ LOG_CHANNEL=local

まとめ・課題

とりあえずこれで操作を追うところまではできるようになったのではないでしょうか。おそらくまだ課題はある（ログイン前とログイン後の紐付け、POSTデータの取得とか）ので、その辺はこれから改善していきます。

検索のための仕組みもまた改めて書けたらいいなという感じです。