LaravelでリクエストのSTART/ENDログを出してみた

会社のTechBlogでCloudWatchにログファイルを表示させたのですが、その際にLaravelのログで開始、終了ログを出してみようとして、処理が長くなりそうだったので別記事にしてみました。

ログの目的としてはこんな感じです。

• 開始と終了のログ２つを出す
• 処理の結果をある程度分かるようにする(success,validate,exceptionとか)
• 処理時間をミリ秒で出す
• apacheのログと合わせて見られるようにIPを出す
• 開始と終了のログを出すので２つを繋げるIDを出す（リクエストID)
• 同じユーザ（同セッション）の操作は追えるようにする(セッションID)

と結構多い。
でもこれぐらいあれば、操作を追える、遅い処理を追えるので実装してみました。

---

環境

• Laravel v8.18.1 (PHP v7.3.20)

ログを出すミドルウェアを実装する

artisanでmiddlewareを作成し、処理を記述

php artisan make:middleware RequestMiddleware

<?php

namespace App\Http\Middleware;

use Closure;
use Exception;
use Illuminate\Http\Request;
use Illuminate\Support\Facades\Log;
use Str;

class RequestMiddleware
{
    public function handle(Request $request, Closure $next)
    {
        //開始終了ログを出したくない場合のコード
        //AWS ELBのHealthCheckerとか
        if ($this->isSkipLog($request)) {
            return $next($request);
        }

        $resultType = 'success';
        $start = microtime(true); //開始時間

        //requestのidとsessionのid。hashしてるのは単にログ表示を短くするため
        $rid = hash('crc32', Str::uuid()->toString());
        $sid = hash('crc32', session()->getId());

        $ip = $this->getIp();

        //startのログ. RIDとかSIDはhashが２つもあるのでわかりやすくしてる
        Log::info(implode(' ', [
            'path:', $request->path(), 'START', $request->method(),
            $ip,
            'RID' . $rid,
            'SID' . $sid,
        ]));

        $result = $next($request);

        if ($this->isValidate($request)) {
            //validateメッセージがあれば設定
            $resultType = 'validate';
        } else if ($this->isException($result)) {
            //Controllerでexceptionが発生していれば設定
            $resultType = 'exception';
        }
        //endログ
        Log::info(implode(' ', [
            'path:', $request->path(), 'END',
            $resultType,
            $ip,
            explode('.', ((microtime(true) - $start) * 1000))[0], //ミリ秒表示
            'RID' . $rid,
            'SID' . $sid,
        ]));
        return $result;
    }

    private function getIp(): string
    {
        //ALB経由とかの場合はX_FORWARDED_FORを出す
        if (isset($_SERVER['HTTP_X_FORWARDED_FOR'])) {
            return $_SERVER['HTTP_X_FORWARDED_FOR'];
        }
        return $_SERVER['REMOTE_ADDR'];
    }

    private function isValidate(Request $request): bool
    {
        return !is_null($request->session()->get('errors'));
    }

    private function isException($result): bool
    {
        return !empty($result->exception);
    }

    private function isSkipLog(Request $request): bool
    {
        $isSkip = Str::startsWith($request->header('User-Agent'), 'ELB-HealthChecker');

        return $isSkip;
    }
}

App\Http\Kernel.phpに作ったミドルウェアを設定する

webのミドルウェアグループに追加する

    ...
    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,
            \App\Http\Middleware\RequestMiddleware::class, //ADD
        ],
    ...

ログを確認する

適当に作ったHelloControllerで確認

[2020-12-15 09:17:25] local.INFO: path: hello START GET 192.168.33.1 RIDe6fe0217 SID0a1be91a  
[2020-12-15 09:17:25] local.INFO: path: hello END success 192.168.33.1 46 RIDe6fe0217 SID0a1be91a  

[2020-12-15 09:17:48] local.INFO: path: hello/edit START POST 192.168.33.1 RIDc24c6515 SID0a1be91a  
[2020-12-15 09:17:48] local.INFO: path: hello/edit END validate 192.168.33.1 50 RIDc24c6515 SID0a1be91a  

[2020-12-15 09:18:50] local.INFO: path: hello/edit START POST 192.168.33.1 RID8b780f08 SID0a1be91a  
[2020-12-15 09:18:50] local.ERROR: test throw {"exception":"[object] (Exception(code: 0): test throw at /var/www/html/laravel8/app/Http/Controllers/HelloController.php:37)
[stacktrace]
...略
[2020-12-15 09:18:50] local.INFO: path: hello/edit END exception 192.168.33.1 98 RID8b780f08 SID0a1be91a  

出てますね！
ただこのmiddleware通る前に失敗すると当然ながらログ出ません。(csrfエラーとか)

感想

とりあえずこれで目的のログを出す１例にはなったと思います。

結構手間だったのと、もっと綺麗にコードかけないかなー？ってところは所々あります...まだphper歴低いので指摘あれば是非に。

ちなみに失敗談として、最初間違えてRequestMiddlewareをwebのmiddlewareGroupsではなく共通のmiddlewareに追加してしまい、sessionidが毎回変わってました。