PHP monologをカスタマイズしてみた - 端っこプログラマーの手帳

PHPでプログラムを書くときにログをファイルに出力したいこともあると思います。
ゼロベースで仕組みを作るのはしんどいので、monologというライブラリを試してみました。しかし、出力できる情報が足りなかったため思い切ってカスタマイズしてみました。主に、GitHubのmonologマニュアルを参考にしています。

Composerの導入

$ curl -s -S https://getcomposer.org/installer | php
$ mv composer.phar composer
$ composer --version
Composer version 1.0-dev (5ccaad92c19ac673435dbb2858ae20d14f34950d) …

まずはComposer本体（パッケージ管理ツール）をインストール。
後々楽なので、パスの通っているディレクトリで実行しました。
また、composer でコマンド実行したいため、リネームして.pharの部分を消します。
$ composer --version とコマンドを打ってみて確認。無事インストールできました。

プロジェクトにセットアップ

適当な場所にプロジェクトのディレクトリを作成し、composer.json というファイルを作成。このファイルに必要なライブラリをJSON形式で指定して、インストールします。

$ mkdir cstest
$ cd cstest
$ vim composer.json
{
    "require": {
        "monolog/monolog": "1.17.*"
    }
}
$ composer install

バージョンは、https://packagist.org/ からmonolog を探して、最新の1.17系を指定しました。（1.17.* で1.17系の最新版になるようです）
※ composer.json の内容を書き換えたときは、$ composer update で更新します。

monologを試してみる

ドキュメントを参考にしてmonologを試してみます。StreamHandler でログをファイルに出力し、LineFormatter でフォーマットを指定しています。

<?php
require_once('vendor/autoload.php');

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\LineFormatter;

$logging_path = 'log/error.log';
$log = new Logger('test');

// フォーマット
$output = "[%datetime%] %level_name%: %message% %context% %extra%\n";

// LineFormatterで出力フォーマット指定
$formatter = new LineFormatter($output);
// StreamHandlerでファイルにログを出力
$stream = new StreamHandler($logging_path, Logger::DEBUG);
$stream->setFormatter($formatter);
$log->pushHandler($stream);

// ログ出力 ex: [2015-10-03 18:35:29] INFO: debug message [] []
$log->addInfo('debug message!!');

monolog での不満点

さて、これで無事ファイルにログが出力されるのですが、「めでたしめでたし」という訳にはいきません。全く物足りないです。次のような情報もほしいです。

・配列やオブジェクトの内容の出力
・データ型の表示
・実行ファイルと行番号
・実行開始から経過時間

Processor 自由にフォーマットを作る

いろいろ調べてみたところ、Processor という付加情報を表示する仕組みがあるところに目を付けました。ユーザが自由に作成した関数を登録でき、その関数内で、$record['extra']という項目に値をセットすれば、フォーマットの %extra% の箇所にその値が出力されるようです。

<?php
$logger->pushProcessor(function ($record) {
    $record['extra']['dummy'] = 'Hello world!';

    return $record;
});

そして、$record の値をvar_dumpしてみた結果です。

array(7) {
  ["message"]=>
  string(13) "debug message"
  ["context"]=>
  array(0) {
  }
  ["level"]=>
  int(200)
  ["level_name"]=>
  string(4) "INFO"
  ["channel"]=>
  string(4) "test"
  ["datetime"]=>
  object(DateTime)#7 (3) {
    ["date"]=>
    string(26) "2015-10-03 19:03:59.766603"
    ["timezone_type"]=>
    int(3)
    ["timezone"]=>
    string(10) "Asia/Tokyo"
  }
  ["extra"]=>
  array(0) {
  }
}

最初の階層のキー名がすべてフォーマットのキー名と合致しているのがわかります。つまり、$record にキーを追加すればフォーマットを自由に増やすことができそうと予測できます。実際にやってみたところこれは当たっていました。

context を使い Processorに情報を渡す

あとは、Processorに登録した関数内に、ログに出力する情報を渡せればよいだけです。ログ出力メソッドの第２引数を配列で指定すると、$record['context'] にその配列が入ります。

<?php
$context = array(
    'file' => 'ファイル名',
    'line' => '行数'
);
$log->addInfo('debug message!!', $context);

やりました。これで解決です。以下のようにログ出力用のラッパー関数を作ることで、様々な値がログに出力出来そうです。
（若干乱暴な気もしますが....）

<?php
require_once('vendor/autoload.php');

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\LineFormatter;

$logging_path = 'log/error.log';
$log = new Logger('test');

// ★フォーマットに、file と line を追加
$output = "[%datetime%] %level_name% %message% %file% %line%\n";

$formatter = new LineFormatter($output);
$stream = new StreamHandler($logging_path, Logger::DEBUG);
$stream->setFormatter($formatter);
$log->pushHandler($stream);

$log->pushProcessor(function ($record) {
    $record['file'] = $record['context']['file'];
    $record['line'] = $record['context']['line'];
    return $record;
});

function debug($message, $depth=''){
    global $log;
    
    // 呼び出し元ファイルと行数
    $backtrace = debug_backtrace();
    // 指定の深さが存在しない場合は呼び出し元に
    $key = isset($backtrace[$depth]) ? $depth : 0;
    $file = $backtrace[$key]['file'];
    $line = $backtrace[$key]['line'];
    $context = array('file' => $file, 'line' => $line);
    // エラーレベルは一旦固定
    $log->addInfo($message, $context);
}

// ログ出力
debug('debug message!!');

他の情報も追加してみる

他の情報も追加してみます。例のごとくクラス化してみました。

PHP monologをカスタマイズ · GitHub

・配列やオブジェクトの内容の出力とデータ型の表示
受け取った値を var_dump を使い、ob_start()等を使い変数に格納させます。 var_dumpの値の改行が、ログ出力時有効にならないため焦りました。これは、以下の記事で解決できました。

http://hack.aipo.com/archives/12506/

・実行開始から経過時間
ミリ秒単位で出力します。開始はインスタンス生成のタイミングで、終了はデバックメソッド呼び出しです。

ログってただでさえ目がチカチカしてしまうので、綺麗に出るというのは結構大切なことだと思います。今後の開発で大いに役に立てたいと思います。