php ロギング機構を作ってみた

はじめに

phpでデベロッパ向けアプリケーションログ機構をつくってみたのでその説明をしてみます。

一般的にプログラミングにおいてデベロッパ向けロギングというのはコンポーネントを横断する概念です。アプリケーション上ある機能 X があり、別の機能 Y があったとして、それをモジュール X、モジュール Y として実装するとします。その時 X と Y は（設計上いろいろ考えなければならないことはあるでしょうが）一般的に機能の直交性が高ければ独立して実装できるものです。

あるアプリケーションでデベロッパに何か情報を残したい要求があり、何らかのロギング機構を使用したとします。その場合、デベロッパが何を残したいかは具体的状況によって異なるため、ロギング機能をできるだけ細やかに使ってログを残したくなるのは当然です。（抽象化されたログにはあんまり意味が無い。）そうすると X, Y の両者がロギングの詳細に依存しまうことになり、概念的には何のつながりもないはずの X と Y に、ロギングというものを通した概念的つながりができてしまうわけです。
さらにプログラミング言語の特性によっては、そのログを出力するために必要な機能にも依存性が生じてしまいます。

そういう問題があるので、こういったオレオレライブラリによるロギング機構を使用することはおススメできません。もっと依存するに値する信頼性の高いライブラリの機能を使用しましょう。（似たようなことが例外機構にも言えます。）

また、単純に私は php について深く知りません。
私などが考えつくことは、有名なライブラリの作成者さんならば必ず考えて、もっとよい決断を下しているはずです。なので、こんなものは私が個人で使用していれば十分で、別の人に使ってもらえるレベルではないと考えています。

ですが、自分が何を考えたか、そういったことが何かの参考になる部分があるのではないかと思い、実装時に考えたことをちょっと説明をしてみようかとおもいました。
そういう意図なので、ソースコードはその時に考えたことをバラバラに記述しています。

物理的出力

ログの出力先は、汎用的なロギング機構を作成するのであれば、LogWriter のようなオブジェクトを作りそれに移譲させるべきです。
ですが、ここではディレクトリを指定し、その中に日付からつくったファイルを作成しそこに出力すれば良いということにしましょう。
調べてみたところ、ログ出力は error_log 関数を使えばいいようです。マジックナンバー 3 が気になりますが、まぁ二度と触れないのでいいとしましょう。
ファイル名を何度も作るのはちょっとやなカンジですが、キャッシュしても良いことはあまりなさそうなので、必要経費と考えることにします。

class Log {
    private static $directory = './';
    
    public static function SetBaseDirectory( $dir ){
        Log::$directory = $dir;

        if( Text::Right( Log::$directory, 1) != '/' ){
            Log::$directory .= '/';
        }
    }

    public static function GetActualLogFileName(){
        $t = date('ymd');
        return Log::$directory . $t . '.log';
    }
    
    public static function WritePhysical( $text ){
        @error_log( $text, 3, Log::GetActualLogFileName() );
    }
}

この時点ですでに Text::Right とか使ってますが、これは substr でつくった文字列の末尾を返す関数です。

php のエラー時の出力を何とかしたい

php は予め準備しておかないとエラーが起こった時その場でエラーメッセージを表示します。その挙動は非常に鬱陶しいと感じるわけですが、出力しようとしている画面そのものにエラーメッセージが出てくれるということ自体は結構便利ではあります。問題は節操無く出力されるところにあるので、一度バッファリングして出力したいところに出力できるようにしましょう。

Log::$entries という変数に一度蓄えておき、Log::DisplayLogs 関数でテーブルとして出力させます。

class Log {
    private static $entries = array();
    private static $level_map = null;
    
    // php はスタティックイニシャライザって無いのかな？
    public static function InitStatic(){
        Log::$level_map = array(
        E_ERROR                 => 'FATAL ',
        E_WARNING               => 'WARN  ',
        E_PARSE                 => 'PARSE ',
        E_NOTICE                => 'NOTICE',
        E_CORE_ERROR            => 'CORE  ',
        E_CORE_WARNING          => 'CORE_W',
        E_COMPILE_ERROR         => 'C_ERR ',
        E_COMPILE_WARNING       => 'C_WARN',
        E_USER_ERROR            => 'fatal ',
        E_USER_WARNING          => 'warn  ',
        E_USER_NOTICE           => 'notice',
        E_STRICT                => 'STRICT',
        E_RECOVERABLE_ERROR     => 'ERROR ',
        E_DEPRECATED            => 'NOTICE',
        E_USER_DEPRECATED       => 'notice'
        );
    }
    
    private static function FomratLocate( $file, $line){
        $file = basename($file);
        return " (in {$file}({$line}))";
    }
    private static function GetCategoryString( $errno ){
        if( isset(Log::$level_map[$errno])){
            return Log::$level_map[$errno];
        }else{
            return "E($errno)";
        }
    }
    
    // 出力、ファイルに書き出しつつ変数に蓄える。
    public static function Write( $category, $message){
        $msg = date( "ymd H:i:s");
        $msg = "$msg $category $message\n";

        Log::$entries[]= array( 'category' => $category, 'message' => $message);
        Log::WritePhysical($msg);
    }
    
    // HTMLとしてのログ出力
    public static function DisplayLogs(){
        if( XArray::Length(Log::$entries) == 0 ){
            return;
        }
        $old_level = error_reporting(0);

        echo "<div class='log_display' id='log'><table>\n";
        foreach (Log::$entries as $entry) {
            $c = Text::EscapeHTML($entry['category']);
            $m = Text::EscapeHTMLwithBreak($entry['message']);
            echo("<tr>");
            echo("<td>{$c}</td><td>{$m}</td>");
            echo("</tr>\n");
        }
        echo "</table></div>\n";

        error_reporting( $old_level );
    }
    
    // エラーハンドラ
    public static function ErrorHandlerAdapter( $errno, $errstr, $errfile, $errline ){
        $category = Log::GetCategoryString( $errno );
        Log::Write($category, $errstr . Log::FormatLocate($errfile, $errline));
    }
}

// 初期化
Log::InitStatic();

// エラーハンドラ
function g_ErrorHandler( $errno, $errstr, $errfile, $errline ){
    Log::ErrorHandlerAdapter( $errno, $errstr, $errfile, $errline);
    return TRUE;
}

set_error_handler('g_ErrorHandler');
error_reporting(E_ALL);

XArray とか、Text::EscapeHTML とかの内容は「お察し下さい」ということで。
で、地の文でどこかで

<?php Log::DisplayLogs(); ?>

とする必要が出てきましたが、本番ではすべきではないですし、忘れてもファイルには出力できるのでこれで良いものとします。

致命的エラー

これで良いかと思ったのですが、致命的エラーの場合は set_error_handler は無視され、いきなり落ちるようです。
いろいろ調べていくと register_shutdown_function という関数が使えそうなので、これで対応します。

function g_ShutdownHandler(){
    $error = error_get_last();
    if( ! $error ){
        return;
    }
    switch($error['type']){
        case E_ERROR:
        case E_PARSE:
        case E_CORE_ERROR:
        case E_CORE_WARNING:
        case E_COMPILE_ERROR:
        case E_COMPILE_WARNING:
            Log::ErrorHandlerAdapter( $error['type'], $error['message'], $error['file'], $error['line'] );
            Log::DisplayLogs();
            break;
        default:
            break;
    }
    return;
}

register_shutdown_function('g_ShutdownHandler');

これでいきなり落ちても一応ログは出力されるようです。

ログ出力関数

ここまでで set_error_handlerに対応しているので、trigger_error で E_USER_NOTICE とか　E_USER_ERROR とかを挙げればログは出力できるようになってたりします。

    trigger_error("こうやって notice ログが書ける。", E_USER_NOTICE);

ですが、これではあまりに非直感的なので Log::Debug という関数を作ります。

class Log{
    public static function Debug( $msg ){
        // ホントはここで出力レベル判定をやってるけど煩雑なので省略
        // if( ... ) { return; }
        
        if( func_num_args() == 1 ){
            Log::Write( 'debug', Cast::ToString($msg));
            return;
        }
        
        $args = func_get_args();
        $t = array();
        foreach ( $args as $arg){
            $t[] = Cast::ToString($arg);
        }
        Log::Write( 'debug', Text::Join($t, ", "));
    }
}

まず、ログは文字列を出力したいものですが、デベロッパが『ちょっとこの値を残しておきたい』と思ったときにそれが文字列であるかどうかはわからないものです。
かといって、デバッグ中に変数の内容をログ出力するとき、デベロッパは『変数なら変数を出力したい』のであって、『変数を文字列に変換してその結果を出力したい』とは考えません。『文字列に変換して・・・』というのは思考のオーバーヘッドでしかないのです。なので、どんな値でも受け付けることができるように Cast::ToString(内容はお察しください)をかましています。

次に func_get_args ですが、これは、実際の開発において複数の変数の値をとりあえず表示したい、ということが意外に多い（受けた引数をとりあえず表示、とか）ためこのような処理を入れています。
Log::Debug( "$a, $b" );
と書けば良いのですけど、
Log::Debug( $a, $b );
のほうが手軽です。
出力のフォーマットはいろいろ思うところはあるのですが、デバッグ用途なので、多少おかしかろうが出力できれば良いと考えてこうしました。

ここで注意しなければならないのは、デバッグログに関してはどこまででも詳細に情報が表示されれば良いということでもないことです。あまりに詳細な情報が勝手に出力されてしまうとログ出力が（実際に重いかどうかとはあまり関係なく）『心理的に重い行為』になってしまいますし、出力結果が多くの情報に埋もれて逆にみづらくなり、手軽に書くことを躊躇する意識が働きます。（print_r とか、 var_dump とかははっきりいってやり過ぎです。）
なので、Cast::ToString は入れ子配列を再帰しませんし、改行もしません。更に行番号を付加するようなこともしていません。そのような情報が欲しければ自分でそう書けば良い、とします。

で、エラーログ出力 Log::Error も作ります。（同様に Warn, Info もつくってあげます。）

class Log{
    public static function Error( $msg ){

        $entris = debug_backtrace();
        if( XArray::Length($entris) == 0 ){
            Log::Write( 'error', Cast::ToString($msg));
            return;
        }

        $entry = $entris[1];
        $file = $entry['file'];
        $line = $entry['line'];
        Log::WriteA('error', Cast::ToString($msg) . Log::FormatLocate($file, $line));
    }
}

こっちは出力するログの内容は十分吟味して呼ぶでしょうから、可変長引数に対応するようなことはしません。
あと、printf 形式の DebugF、var_dump の結果をログ出力する DumpVar などを作ってあげてロギング機構をしては一応の完成というところでしょうか。