この記事は、 ユアマイスター Advent Calender 2019 18日目の記事です。
どうも。ユアマイスター星(@inase17000)です。 過去2回にわたり、CakePHP3のMiddlewareについて紹介してきました。
yourmystar-engineer.hatenablog.jp
yourmystar-engineer.hatenablog.jp
馴染みのない方は、合わせてご覧いただけますと幸いです!
やりたいこと
- アプリケーションの実行ログを出力したい
- タイムスタンプ
- リクエスト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クラスがありましたが、色々試してみたところ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
お気軽にご連絡お待ちしてます!!