やりたいこと

アプリケーションの実行ログを出力したい
- タイムスタンプ
- リクエストURI
- セッションID
- UA
- コントローラー名
- アクション名
- HTTPステータスコード
- サーバー処理時間

Middlewareを使わずに実装しようとすると、各Controllerの親となるAppControllerというクラスを作って、そこで invokeAction() にて初期化、 beforeRender() でログ出力という実装する形でまかなっていました。

参考：CakePHP3のControllerクラスでのライフサイクル

このままだと、

$this->autoRender = false でレスポンスを返すAPIでは、 beforeRender() が実行されないためログ出力ができない
レンダリング前にサーバー処理時間を計測終了するため、CakePHP3でのテンプレートレンダリングにかかった所要時間を計測できない

という問題がありました。

今回、Middlewareの存在を知り、どんなリクエストも必ず通るという性質から、アプリケーションログの実装をMiddlewareで作ることが最適だと思い、取り掛かりました。

実装方法

1. Middlewareファイルを作成する

<?php
namespace App\Middleware;

use Cake\Filesystem\File;

class ApplicationlogMiddleware
{
    /**
     * ログ出力Middleware
     *
     * Controller処理前後でタイムスタンプを取得し、ログに出力する
     */
    public function __invoke($request, $response, $next)
    {
        $startTimestamp = microtime(true);

        // 次のミドルウェアキューへ
        $response = $next($request, $response);

        // 実行時間を計測する
        $procTime = ceil((microtime(true) - $startTimestamp) * 1000);

        $logElms = array(
            "time" => date('d/M/Y:H:i:s'),
            "host" => $request->clientIp(),
            "forwardedfor" => $request->hasHeader('X-Forwarded-For') ? $request->getHeaderLine('X-Forwarded-For') : '',
            "ua" => $request->getHeaderLine('User-Agent'),
            "session_id" => $request->getCookie('CAKEPHP', ''),
            "uri" => $request->here(),
            "referer" => $request->referer(),
            "controller" => $request->getParam('controller'),
            "action" => $request->getParam('action'),
            "runtime" => $procTime,
            "status" => $response->getStatusCode(),
            "user_id" => $request->session()->read('Auth.User.id')
        );

        $row = $this->arrayToLtsvRow($logElms);

        // ログ出力内容が取得できない場合はスキップ
        if (strlen($row) < 1) {
            return $response;
        }

        $log = new File(ROOT . "/logs/application.log", true);

        $log->append($row);
        $log->close();

        return $response;
    }

    // 連想配列をLTSV形式に変換
    private function arrayToLtsvRow($arr = [])
    {
        if (empty($arr)) {
            return "";
        }
        $row = "";
        foreach ($arr as $k => $v) {
            strlen($row) > 0 ?$row .= "\t" . $k . ":" . $v : $row .= $k . ":" . $v;
        }
        return $row . "\n";
    }
}

CakePHP3には便利なLoggerクラスがありましたが、色々試してみたところ１行全体を自由にフォーマットすることができない実装だったため、上記では無理やりファイルへ出力しています。

参考：https://book.cakephp.org/3/ja/core-libraries/logging.html

ポイントとしては、 $next の前後でMiddlewareキューの処理が進みますので、前で時間をメモっておいて、後で現在時刻との差分を処理時間として計測するところです。

2. Application.phpに追記する

    public function middleware($middlewareQueue)
    {
        $middlewareQueue

            ... 中略 ....

            // ログ出力
            ->add(new ApplicationlogMiddleware())

            ... 中略 ....

        return $middlewareQueue;
    }

注意点

この実装をすると１点問題が起こりました。

今回追加するMiddlewareと他の既存のMiddlewareの呼び出す順番による挙動の違いです。

キューをRoutingMiddleware->ApplicationlogMiddlewareの順番にしないと、 $request->getParam('controller') と $request->getParam('action') が取り出せない
キューをApplicationlogMiddleware->ErrorHandlerMiddlewareの順番にしないと、Exceptionが発生した時の $response->statusCode() が取り出せない
- ErrorHandlerMiddleware::handleException() で $responseを書き換えているため

要件次第とはなりますが、キューの順番に関して十分に注意しながら実装が必要だということがわかりました。