アクションの前後に開始・終了ログを自動で挟みたい

エラーなどでデバッグする時、どのアクションでコケているのか分かりにくいことがあります。
bladeとかControllerの中以外、Requestとかvendoerの中でコケているとどこまで通過しているのかわかりづらい。
そこでアクションの開始時と終了時にログを出しておくと、そもそも始まったのかどうかと、無事に通過したかどうかを判別できて問題の切り分けが楽になります。

コントローラでこれをやるとデメリットもあって悩みどころでした。

・コントローラで全てのアクションにログの出力コードを入れるのは結構大変な労力。
・コードが肥大化する。本文が　return viewの１行しかないのにログ出力が開始と終了で２行とか。
・クラス名とアクション名を書くのがめんどくさい。
・クライアントがログの出力を嫌がる場合がある。
・アクセス数が多い本番環境ではログだけでもサーバのディスク容量に負荷がかかる場合がある。別途cronなどで整理する処理が必要になる。

というわけでミドルウェアでなんとかならないか色々ググってたらできたのでメモ。

ミドルウェアを作成する

アクション開始前とアクション終了後に割り込む用のミドルウェアを作る。

php artisan make:middleware BeforeActionLog
php artisan make:middleware AfterActionLog

アクション開始前の処理を書く

handleメソッドに以下を記入する。
$request->route()->getActionName() で
[05:42:57] LOG.debug: App\Http\Controllers\Admin\TemplateController@show
のような文字列が返ってくる。

本番環境では出力させたくない場合、config('app.env')で .envのAPP_ENV= の値を拾ってきて分岐させればいいと思う。

app/Http/Middleware/BeforeActionLog.php

    public function handle(Request $request, Closure $next)
    {
        logger($request->route()->getActionName() . '[START]');

        return $next($request);
    }

アクション終了後の処理を書く

app/Http/Middleware/AfterActionLog.php

    public function handle(Request $request, Closure $next)
    {
        $response = $next($request);
        
        logger($request->route()->getActionName() . '[END]');

        return $response;
    }

ミドルウェアグループに登録する

app/Http/Kernel.php

    protected $middlewareGroups = [
        'web' => [
            \App\Http\Middleware\EncryptCookies::class,
            \Illuminate\Cookie\Middleware\AddQueuedCookiesToResponse::class,
            \Illuminate\Session\Middleware\StartSession::class,
            // \Illuminate\Session\Middleware\AuthenticateSession::class,
            \Illuminate\View\Middleware\ShareErrorsFromSession::class,
            \App\Http\Middleware\VerifyCsrfToken::class,
            \Illuminate\Routing\Middleware\SubstituteBindings::class,
        ],

        'api' => [
            // \Laravel\Sanctum\Http\Middleware\EnsureFrontendRequestsAreStateful::class,
            'throttle:api',
            \Illuminate\Routing\Middleware\SubstituteBindings::class,
        ],
// ここから追加 -------------------------------------------
        'log' => [
            \App\Http\Middleware\BeforeActionLog::class,
            \App\Http\Middleware\AfterActionLog::class,
        ]
// ここまで追加 -------------------------------------------
    ];

ルーティングに紐づける。

一番上の行の middleware('log') の部分でさっきのミドルウェアグループのキー名の'log' と紐づいています。
どこに書くかはご自身のアプリケーションに合わせてログを出力したいルート範囲に設定してください。

ちなみに、ミドルウェアグループを使わずにメソッドチェーンでBeforeActionLogとAfterActionLogを繋いだら後ろに書いた方しか適用されなくて失敗しました。
もしかするとですが前処理ミドルウェアと後処理ミドルウェアを同時に同じルートに適用するにはミドルウェアグループに登録しないと無理なのかもしれません。

routes/web.php

Route::prefix('admin')->name('admin.')->middleware('log')->group(function() {
    Route::get('login', [App\Http\Controllers\Admin\Auth\LoginController::class,'showLoginForm']);
    Route::post('login', [App\Http\Controllers\Admin\Auth\LoginController::class,'login'])->name('login');
    Route::post('logout', [App\Http\Controllers\Admin\Auth\LoginController::class,'logout'])->name('logout');

    Route::middleware('auth:admin')->group(function() {
        Route::get('/', [App\Http\Controllers\Admin\HomeController::class, 'index'])->name('home');
        Route::get('/home', [App\Http\Controllers\Admin\HomeController::class, 'index'])->name('home');
        Route::resource('/template', App\Http\Controllers\Admin\TemplateController::class);
        Route::resource('/template_item', App\Http\Controllers\Admin\TemplateItemController::class);
    });
});

出力結果

デバッグバーだとこんな感じになれば成功。

参考サイト

参考書

PHPフレームワーク Laravel入門 秀和システム