std.experimental.logger

D言語 Advent Calendar 2015の3日目の記事です．

いずれPhobosにstd.loggerとして入るであろう，std.experimental.loggerについて紹介します．std.experimental.loggerはその名前の通り，ロギングの機能を提供するモジュールです．APIを見る限り一般的なロガーで，他の言語のロガーを触ったことがあるのであれば，苦労せずに使えると思います．

モジュールのimport

std/experimental/logger/package.dが用意されているので，import std.experimental.loggerをするだけで，必要な機能が使えるようになります．

Logging API

log関数

一番基本的なAPIです．例えば以下のようにすると，

import std.experimental.logger;

void main()
{
    log("hello");
}

時間，ファイル，関数，行数，メッセージがstderr(stdoutではない)に出されます．

2015-12-07T08:52:21.385:log.d:main:5 hello

引数は文字列だけに限らなくて，例えば以下のように呼び出すことも出来ます．

log("hello : ", 42, " : ", ["a":1.5]);

結果は以下の通り

2015-12-07T09:11:20.728:log.d:main:6 hello : 42 : ["a":1.5]

後でもう少し深く説明しますが，このlog関数はグローバルに設定された共有のロガーを使ってロギングしています．

logf関数

std.formatを使って引数をフォーマットしつつ出力します．先ほどの例は，以下のようにも書けます．`

logf("hello : %d : %s", 42, ["a":1.5]);

複数の引数を扱う時や，整数の出力を細かく制御したい時に便利です．

条件付きロギング

log/logf関数は，第一引数にbooleanの値を渡すと，条件付きでロギングするようになります．第一引数がfalseの場合にはロギングは行われません．

log(true, "hello with true");
log(false, "hello with false");

例えば上の二行を実行すると，一つ目だけが出力されます．

2015-12-07T09:22:00.012:log.d:main:5 hello with true

log/logfの引数はlazyを使って処理されているので，falseの場合にはそもそも第2引数以降は評価されません．そのため，動的に文字列を作るなどを行っても，パフォーマンスに直接影響することはないです．これは条件付きロギングだけではなく，後で説明するログレベルの設定によりスキップされる時も同じです．

log(true, "a" ~ "b" ~ to!string(10));
log(false, "a" ~ "b" ~ to!string(10));

このコードを実行してプロファイルすると，falseの方ではメモリアロケーションが発生していないのが分かります．

% rdmd -profile=gc log.d
% cat profilegc.log
bytes allocated, allocations, type, function, file:line
              4               1 immutable(char)[] log.main.__dgliteral2 log.d:6

なんで予めログレベルをチェックして〜，みたいなことはしなくて良いです．

ログの階層構造

あとで必要になるので，ここでログがどうやって出力されているのかを説明しておきます．log関数のセクションで「グローバルに設定された共有のロガーを使って」と書きましたが，実は直接使っているわけではありません．以下のように，呼び出しは階層構造になっています．

log -> thread local logger -> global shared logger

なのでlog関数を呼び出した時には，まずはスレッドローカルに設定されているロガーに転送され，そのスレッドローカルのロガーが，さらにグローバルに共有されているロガーを呼び出すことでログが出力されています．もちろんこれらは個別に設定可能で，それについて説明します．

スレッドローカルロガー

log関数を呼び出した場合はまず最初にこのロガーにログが転送されます．デフォルトでStdForwardLoggerというロガーがセットされており，これは単にグローバルに共有されているロガーに転送するだけです．なので，ここを変更すれば，グローバルへの転送などをカスタマイズ出来ます．
このスレッドローカルロガーにアクセスするにはstdThreadLocalLogというプロパティを使います．

Logger l1 = stdThreadLocalLog; // スレッドローカルロガーを取得
stdThreadLocalLog = l2; // スレッドローカルロガーを新しく設定する

たとえば以下のように，stdThreadLocalLogに何もしないNullLoggerを設定すると，特定のスレッドだけログの転送を抑止し，出力をとめることが出来ます．

import core.thread;
import std.experimental.logger;

void f1()
{
    log("hello from f1");
}

void f2()
{
    stdThreadLocalLog = new NullLogger();
    log("hello from f2");
}

void main()
{
    auto t1 = new Thread(&f1).start().join();
    auto t2 = new Thread(&f2).start().join();
}

グローバルロガー

スレッド間で共有されているロガーです．デフォルトではstderrへログをはき出すFileLoggerが設定されています．これにもプロパティが用意されていて，sharedLog経由で設定出来ます．例えば以下のようにすると，すべてのログが出力されなくなります．

void f1()
{
    log("hello from f1");
}

void f2()
{
    log("hello from f2");
}

void main()
{
    sharedLog = new NullLogger();
    auto t1 = new Thread(&f1).start().join();
    auto t2 = new Thread(&f2).start().join();
}

sharedLogの実装

sharedLogはアトミックなLoad/Storeを用いて実装されていて，中途半端な状態でロガーにアクセスすることはないので，sharedLogへのアクセスにMutexなどを用いる必要はありません．

ログレベル

std.experimental.loggerにも，もちろんログレベルが予め提供されています．ログレベルを設定すると，その設定された値と同じもしくは高いレベルのログしか出力されなくなります．つまりフィルタリングに使えます．ログレベルはLogLevelというenumで提供されていて，以下がそのリストです．下になるにつれてレベルが高くなっています．

• all
• trace
• info
• warning
• error
• critical
• fatal
• off

allはデフォルトの設定レベルで，すべてのメッセージを出力し，offは名前の通りすべての出力を抑制します(NullLoggerをいちいち設定する必要がありません)．その他は名前の通りです．

ログレベルの設定とログレベルを伴うロギング

各ロガーにはlogLevelと呼ばれるプロパティがあるので，それを設定することでロガーのログレベルを変更可能です．また，log関数は第一引数にLogLevelを渡すことが出き，それを使ってログのレベルを指定出来ます．上で書いたスレッドローカルロガーの例を少し修正すれば，各スレッド毎にログレベルを設定出来ます．

void f1()
{
    stdThreadLocalLog.logLevel = LogLevel.info;
    log(LogLevel.info, "info log from f1");
    log(LogLevel.error, "error log from f1");
}

void f2()
{
    stdThreadLocalLog.logLevel = LogLevel.error;
    log(LogLevel.info, "info log from f2");
    log(LogLevel.error, "error log from f2");
}

結果は以下の通りで，ロガーのログレベルがerrorに設定されているf2では，infoレベルのログは出力されません．

2015-12-07T11:55:57.686:tls_log.d:f1:7 info log from f1
2015-12-07T11:55:57.686:tls_log.d:f1:8 error log from f1
2015-12-07T11:55:57.686:tls_log.d:f2:15 error log from f2

余談ですが，第一引数にLogLevelを受け取るlog関数は，第二引数にbooleanを指定することで，条件付きロギングに出来ます．

ログレベル毎のロギング関数

log関数で毎回LogLevelを指定するのが面倒な人向けに，trace，info，warning，critical，fatalのaliasが用意されています．使い方はlogと同じです．

info("info msg");
error(a > b, "error msg"); // 条件付きロギングももちろん可

fatalログレベル

fatalだけが少し特殊で，fatalでログを出力すると，その後Error例外が投げられます．fatalは「もうダメだ!」というレベルなので，以降を処理を続けずに例外を投げてなるべくアプリケーションを終わらせようとします．

fatal("Woooooooow!");

を実行すると，以下のように例外が飛んで来て，処理しなければスタックトレースを吐いて終了します．

015-12-07T12:32:55.218:log.d:main:6 Woooooooow!
object.Error@(0): A fatal log message was logged
----------------
... stacktrace here ...

この挙動はカスタマイズ出来て，ロガーのfatalHandlerを設定してやれば良いです．

sharedLog.fatalHandler = delegate() {
    writeln("fatal!!!");
};
fatal("Woooooooow!");

結果は以下のようにデフォルトの例外を投げる挙動から，メッセージを吐くだけになります．

2015-12-07T12:36:46.685:log.d:main:9 Woooooooow!
fatal!!!

ただ，単に重要度高くログを吐くならcriticalとかあるので，fatalの挙動はなるべくライブラリ側でカスタマイズしないほうが良いでしょう．

Logger API

今まではすでに定義されていた関数群を使ってロギングするAPIを見てきたので，次はその中で使われているLoggerオブジェクトを見ていきます．今まで紹介してきた関数群も，中では最終的にはLoggerオブジェクトを使っています(logやfatalHandlerなど)．

Loggerは抽象クラスになっていて，これを継承して新しいロガーを作ることになります．APIは以下のようになっていて，writeLogMsgだけが抽象メンバ関数で子クラスで実装する必要があります．LogEntryが保持している値はたくさんあってここでは書けないので，Logger.LogEntryを参照してください．

class AddPrefixLogger : Logger
{
    this(string prefix) @safe
    {
        super(LogLevel.all);
        _prefix = prefix;
    }

    override void writeLogMsg(ref LogEntry payload)
    {
        writeln(_prefix ~ payload.msg);
    }

    private string _prefix;
}

void main()
{
    auto logger = new AddPrefixLogger("hey ");
    logger.log("D-man"); // 出力結果は"hey D-man"になる
}

デフォルト実装では，beginLogMsgが呼ばれ，logMsgPartが呼ばれ，最後に呼ばれるfinishLogMsgの中でwriteLogMsgが呼ばれるようになっており，writeLogMsgだけを実装すればLogEntryの情報を使ってロギングが出来るようになっています．
もちろん，beginLogMsg，logMsgPart，finishLogMsgを子クラスで再実装すれば，よりきめ細かに制御することが出来ます．例えばLoggerのデフォルト実装ではlogMsgPartでAppenderクラスにどんどんログメッセージを追記した後，finishLogMsgで一括で書き込むようになっていますが，FileLoggerはlogMsgPartで直接ファイルに書き込むことで，メモリアロケーションを回避する実装になっています．

この辺気になる方は，std.experimental.loggerにある既存のロガー実装のソースを読むと良いと思います．

組み込みロガー

std.experimental.loggerに最初から入っているロガーを紹介します．

NullLogger

既に登場しましたが，何もしないロガーです．

auto logger = new NullLogger();
logger.info("hello");

FileLogger

グローバルロガーのデフォルトで使われているロガーで，ファイルに書き出すロガーです．コンストラクタが二つあり，ファイル名か既存のFileオブジェクトを渡すことで利用出来ます．

auto flogger1 = new FileLogger("foo.log");
auto flogger2 = new FileLogger(stdout);

MultiLogger

複数のロガーで同時にロギングを行うためのロガーです．ロガーを登録するAPIが追加されています．

auto logger = new MultiLogger();
logger.insertLogger("hey-prefix", new AddPrefixLogger("hey "));
logger.insertLogger("Wow-prefix", new AddPrefixLogger("Wow "));
logger.log("D-man");

結果は以下の通り．

hey D-man
Wow D-man

その他

すでに必要なことは書いたので，後はちょっとしたtips系の機能を紹介します．

コンパイル時のロギング無効設定

D言語のversion指定を使うことで，特定のログレベルを無効にすることが出来ます．

module log;
import std.experimental.logger;

void main()
{
    info("info");
    error("error");
    critical("critical");
}

上記のコードに対して，それぞれ-versionで指定した結果が以下です．

% dmd -run log.d
2015-12-07T13:38:07.595:log.d:main:6 info
2015-12-07T13:38:07.595:log.d:main:7 error
2015-12-07T13:38:07.595:log.d:main:8 critical

% dmd -version=StdLoggerDisableLogging -run log.d

% dmd -version=StdLoggerDisableInfo -run log.d
2015-12-07T13:38:19.170:log.d:main:7 error
2015-12-07T13:38:19.170:log.d:main:8 critical

% dmd -version=StdLoggerDisableError -run log.d
2015-12-07T13:38:25.478:log.d:main:6 info
2015-12-07T13:38:25.478:log.d:main:8 critical

まぁ使い方はなんとなく分かってもらえると思います．

モジュールレベルのログレベル設定

トリッキーなんですが，実はモジュールレベルでもロギングレベルを指定出来ます．方法としては，外部にモジュール名_loggerconfig.dというファイルを設定して，中でロギングレベルを設定するという方法です．例えばすぐ上のlogモジュールを例にすると，log_loggerconfig.dファイルに以下の内容を書いておいてくと，logモジュールの中はその設定が適用されます．

// log_loggerconfig.d                                                                                             import std.experimental.logger;
enum logLevel = LogLevel.error;

これを置いて上のコードを再度実行すると，以下のような結果になります．

% dmd -run log.d
2015-12-07T13:57:35.154:log.d:main:9 error
2015-12-07T13:57:35.154:log.d:main:10 critical

これは再帰的に適用されて，foo.bar.bazでbazのモジュールレベルの設定がなければ，foo.barが探索されます．すべての親を辿って見つからなければ，allになります．

実装

D言語には__MODULE__を使って今いるモジュールを文字列で取得できるのですが，この値を使ってコンパイル時に動的にシンボルをimportするD言語コードを生成し，そのコードがコンパイルが出来るのであればログレベルの設定がされていると判断する(ファイルが存在していなかったり，logLevelが設定されていなければコンパイルエラーになる)，という処理になっています．動的にD言語コードを生成して再度コンパイルするというのはよくありますが，importの成否で分岐するのはなかなか上手いな，と思いました．

template moduleLogLevel(string moduleName) if (moduleName.length)
{
    import std.string : format;
    mixin(q{
        static if (__traits(compiles, {import %1$s : logLevel;}))
        {
            import %1$s : logLevel;
            static assert(is(typeof(logLevel) : LogLevel),
                          "Expect 'logLevel' to be of Type 'LogLevel'.");
            // don't enforce enum here                                                                                                                        
            alias moduleLogLevel = logLevel;
        }
        else
            // use logLevel of package or default                                                                                                             
            alias moduleLogLevel = moduleLogLevel!(parentOf(moduleName));
    }.format(moduleName ~ "_loggerconfig"));
}

まとめ

std.experimental.loggerの機能を一通り紹介しました！experimentalなのでAPIに今後変更が加わる可能性はありますが，基本的なアプローチはそんなに変わらないと思います．皆さんも使ってみて，気になるところがあったらフィードバックしましょう．
ロガーの出力を文字をつけたりとかのロガーは書いてもいいかなぁと今思っているところです．