【CakePHP】ログ出力形式をカスタマイズしてデバッグ効率を上げる(2.x系)


はじめに

 CakePHPでプログラムするにあたり色々なところで同じ書きっぷりの出力方法で書いてたり、違うメンバーが出力形式を違う形で書いていてログが見づらかったりしたので、ある程度の共通化を図るために設定方法を調べてメモしてみたという投稿です。
 ネットを調べてもなかなか見つからなかったCakePHPのログ出力拡張クラスについて、そこそこまとめることが出来ていると思います。

想定読者

下記の方を想定した記事です。

  • CakePHPでログをいい感じに出したい方
  • CakePHPでログの拡張クラスを作ってみたい方
  • デバッグログで何を出したら良いか分からない方
  • CakePHPでWebアプリ作るにあたってログ設計したい方
  • チーム開発する上でベースとなるPHPフレームワーク拡張版を整えたい方

PHPやCakePHPでバリバリやってる方には向かないかもしれません。

前提条件

 本稿は下記の環境で動作確認しました。

  • OS : CentOS Linux release 7.1.1503 (Core)
  • PHP : 7.0.18
  • CakePHP : 2.9.8

カスタム手順

CakePHP に存在する既存ライブラリを流用する

Command
$ cd project_root/
$ mkdir app/Lib/Log/Engine/

// CakePHP 2.x の FileLogクラスをコピーする
$ cp -p lib/Cake/Log/Engine/FileLog.php app/Lib/Log/Engine/CustomFileLog.php

必要な箇所だけ書き換える

app/Lib/Log/Engine/CustomFileLog.php
// 作業-1
// 既存のApp::usesを削除して下記を追加
App::uses('FileLog', 'Log/Engine');


// 作業-2
// クラス名及びextendするクラス名を変更
class FileLog extends BaseLog {
// ↓
class CustomFileLog extends FileLog {


// 作業-3
// 下記のメソッド以外のメソッド削除
public function write($type, $message)


// 作業-4
// public function write($type, $message) 関数内にある
// $output = date('Y-m-d H:i:s') . ' ' . ucfirst($type) . ': ' . $message . "\n";
// を、出力したフォーマットに変更する。
// 今回はアクセス元のIPを取得したりしたいので、$outputより前に必要な情報も捕獲しておく。

// 例)
$ip = "-";
$sessionid = "-";

// 接続元のIPアドレスを取得する.
if (!empty($_SERVER['HTTP_X_FORWARDED_FOR'])) {
    $ip = $_SERVER['HTTP_X_FORWARDED_FOR'];
    $ip_array = explode(,, $ip);
    $ip = $ip_array[0];
} else {
    $ip = $_SERVER['REMOTE_ADDR'];
}

// セッションIDを取得する.
if (session_id() != "") {
        $sessionid = session_id();
}
$dbg = debug_backtrace();


// 例1.) ltsv形式の場合
$output = "host:".$ip."\tpid:".getmypid()."\tsessionid:".$sessionid."\ttime:[".date("d/M/Y:H:i:s O")."]\ttype:".ucfirst($type)."\tclass:".$dbg[2]['class']."\tfunc:".$dbg[2]['function']."\tline:".$dbg[1]['line']."\tmessage:" . $message . "\n";

// 例1.) 出力結果の例
// host:10.0.2.2   pid:4542        sessionid:-     time:[02/May/2017:16:07:07 +0900]       type:Custom     class:PagesController   func:display   line:50 message:ログのテスト出力


// 例2.) シンプルな出力形式
$output = "$ip [".getmypid()."] [".$sessionid."] [".date("d/M/Y:H:i:s O")."] ".ucfirst($type)." ".$dbg[2]['class']."#".$dbg[2]['function']." [".$dbg[1]['line']."] " . $message . "\n";

// 例2.) 出力結果の例
// 10.0.2.2 [1156] [-] [02/May/2017:16:37:16 +0900] Custom PagesController#display [50] ログのテスト出力


/* 出力設定した情報

- 接続元IPアドレス
- プロセス番号
- セッション番号
- 日時
- ログタイプ
- クラス名
- メソッド名
- 行数
- メッセージ

*/

Gist : CakePHP 2.x 系におけるログ拡張クラスの例

bootstrap.php を編集して作成した拡張ログクラスを読み込む

app/Config/bootstrap.php
// 一番下に下記を追記する.
// custom以外の出力をする場合は、記載箇所を考慮する必要があるので注意
App::uses('CustomFileLog', 'Log/Engine');  // クラスを読み込む
define('LOG_CUSTOM', 'custom');   // 定数でログタイプを指定出来るように設定
CakeLog::config('custom', array(
    'engine' => 'CustomFile',     // 使用するクラス
    'types' => array('custom',),  // ログタイプ
    'file' => 'custom'            // 出力先ファイル名
));

Gist : CakePHP 2.x 系におけるログ拡張クラスの読み込み設定例

実際に使ってみる

 Controllerを作るところからやると面倒なので、デフォルトで存在する PagesController にログ出力行を追加して動作確認する。

Controller/PagesController.php

public function display() {
    CakeLog::write(LOG_CUSTOM, 'ログのテスト出力');  // この一行を追記

// app/tmp/logs/custom.log にログが出力されていることを確認する.

注意事項

今回のカスタム例では出力しているクラス名や関数名、行数を取得した為、下記のパターンのうち、 パターン 1 だと正確な情報が出力出来ない
その為、 パターン 2 の静的呼び出し にてログ出力する 必要がある。

CakePHPのログ出力方法:2パターン
// パターン 1
$this->log('ログのテスト出力', LOG_CUSTOM);

// パターン 2 : 静的呼び出し ←こちらを使用する
CakeLog::write(LOG_CUSTOM, 'ログのテスト出力'); 

// ※出力する LogFormat でクラス名などを使用しない場合は、どちらのパターンでもOK

運用を見据えて

 サーバ・アプリケーションを作成する上でログ設計は非常に重要である。
ただし、今回のログ出力をそのまま本番で使用すると、不必要な情報まで出力されてしまい、セキュリティ的な観点やストレージ容量への影響といった観点でリスクが残ることとなる。
 その為、ログレベルに応じたログ出力形式の変更し、環境に応じたログ情報の出し分けを行うことが出来るような設計が望ましい。

 その為には、拡張ログクラスを複数作成したり、bootstrapでのconfig設定を調整したりなどする必要があるが、それはまた別の投稿で。

参考