ユアマイスター株式会社エンジニアブログ

ユアマイスター株式会社のエンジニアが日々徒然。

CakePHP3 の Middleware 実装応用編 ログ出力Middlewareを作ってみた

f:id:yourmystar_engineer:20191218105844p:plain


この記事は、 ユアマイスター Advent Calender 2019 18日目の記事です。


どうも。ユアマイスター星(@inase17000)です。 過去2回にわたり、CakePHP3のMiddlewareについて紹介してきました。

yourmystar-engineer.hatenablog.jp

yourmystar-engineer.hatenablog.jp

馴染みのない方は、合わせてご覧いただけますと幸いです!

やりたいこと

  • アプリケーションの実行ログを出力したい

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クラスがありましたが、色々試してみたところ1行全体を自由にフォーマットすることができない実装だったため、上記では無理やりファイルへ出力しています。

参考: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;
    }

注意点

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

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

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

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

振り返り

事前に簡単なMiddlewareの実装を試していたため、今回の実装応用編もかなりスムーズに進みました。何事もエンジニアならまずはプロトタイプ作って動きを試してみるのって大事ですね。

これでMiddlewareシリーズの記事は一旦終了の予定です。また別のネタを探していきます!

ユアマイスター では一緒にはたらくエンジニアを募集しています。

▼お気軽にご連絡ください▼

https://corp.yourmystar.jp/recruit

お気軽にご連絡お待ちしてます!!