log4jsでログレベルによってログフォーマットを変える

はじめに

node.jsのアプリケーションでログを出すとき、console.logだけで、デバッグログをON/OFFしたいとか、出力先を変更したい、フォーマットを整えたいなどの要求に応えるのは少し面倒なのでlog用に作られたライブラリを使うと便利です。そういうライブラリの一つであるlog4jsは、Javaで使われているlog4jというlogging frameworkをnode.jsに持ってきたもので、高機能で使いこなすと便利です。
今回ログレベルによってログのフォーマットを変えるようにしたのですが、適切なドキュメントが見つからなかったので、試した結果をまとめます。

ログレベルと優先順位

log4jsには6つのレベルが用意されています。レベルには優先順位があって、重大な順から

順位	level	意味
1	FATAL	致命的なエラー。プログラムの異常終了を伴うようなもの。コンソール等に即時出力することを想定
2	ERROR	エラー。予期しないその他の実行時エラー。コンソール等に即時出力することを想定
3	WARN	警告。廃要素となったAPIの使用、APIの不適切な使用、エラーに近い事象など、実行時に生じた異常とは言い切れないが正常とも異なる何らかの予期しない問題。コンソール等に即時出力することを想定
4	INFO	情報。実行時の何らかの注目すべき事象（開始や終了など）。コンソール等に即時出力することを想定。従ってメッセージ内容は簡潔に止めるべき
5	DEBUG	デバッグ用の情報。システムの動作状況に関する詳細な情報。コンソールではなくログ上にだけ出力することを想定
6	TRACE	トレース情報。更に詳細な情報。コンソールではなくログ上にだけ出力することを想定

となります。それぞれの意味はlog4jsのドキュメントには載ってなかったので、log4jのwikipediaから引用しました。

ログフォーマットの指定

ログフォーマットの設定にはappendersにlayoutを追加して指定します。log4jsには幾つかのフォーマットが用意されています。以下は独自のログフォーマットを指定する例です。

const log4js = require('log4js');

log4js.configure({
    "appenders": [{
        "type": "console",
        "layout": {
            "type": "pattern",
            "pattern": "[%d{ISO8601_WITH_TZ_OFFSET}] %h %p %c: %m"
        }
    }]
});

var logger = log4js.getLogger('cheese');
logger.setLevel('TRACE');

logger.trace('Entering cheese testing');
logger.debug('Got cheese.');
logger.info('Cheese is Gouda.');
logger.warn('Cheese is quite smelly.');
logger.error('Cheese is too ripe!');
logger.fatal('Cheese was breeding ground for listeria.');

これを実行すると以下のように指定したフォーマットで表示されます。

[2017-01-01T22:49:13+0900] local TRACE cheese: Entering cheese testing
[2017-01-01T22:49:13+0900] local DEBUG cheese: Got cheese.
[2017-01-01T22:49:13+0900] local INFO cheese: Cheese is Gouda.
[2017-01-01T22:49:13+0900] local WARN cheese: Cheese is quite smelly.
[2017-01-01T22:49:13+0900] local ERROR cheese: Cheese is too ripe!
[2017-01-01T22:49:13+0900] local FATAL cheese: Cheese was breeding ground for listeria.

ログレベルによるフォーマットの指定

ログレベルによってフォーマットを変更するには、logLevelFilterフィルタを使用します。使用方法は以下のとおりです。
"logLevelFilter"をappendersに追加し、その中のappenderにログフォーマットを指定します。そして、表示したい最低レベルを"level"属性で指定します。これでlevelに指定した以上のレベルのログが表示されます。

// const config = require('config');
const log4js = require('log4js');

log4js.configure({
    "appenders": [{
        "type": "logLevelFilter",
        "level": "INFO",
        "appender": {
            "type": "console",
            "layout": {
                "type": "pattern",
                "pattern": "[%d{ISO8601_WITH_TZ_OFFSET}] %h %p %c: %m"
            }
        }
    }]
});

var logger = log4js.getLogger('cheese');
logger.setLevel('TRACE');

logger.trace('Entering cheese testing');
logger.debug('Got cheese.');
logger.info('Cheese is Gouda.');
logger.warn('Cheese is quite smelly.');
logger.error('Cheese is too ripe!');
logger.fatal('Cheese was breeding ground for listeria.');

この実行結果は以下のようにINFO以上が表示されます。

[2017-01-01T22:59:18+0900] local INFO cheese: Cheese is Gouda.
[2017-01-01T22:59:18+0900] local WARN cheese: Cheese is quite smelly.
[2017-01-01T22:59:18+0900] local ERROR cheese: Cheese is too ripe!
[2017-01-01T22:59:18+0900] local FATAL cheese: Cheese was breeding ground for listeria.

TRACEとDEBUGも表示するように、レベルをTRACEに指定したlogLevelFilterをもう一つ追加します。

const log4js = require('log4js');

log4js.configure({
    "appenders": [{
        "type": "logLevelFilter",
        "level": "INFO",
        "appender": {
            "type": "console",
            "layout": {
                "type": "pattern",
                "pattern": "[%d{ISO8601_WITH_TZ_OFFSET}] %h %p %c: %m"
            }
        }
    },
    {
        "type": "logLevelFilter",
        "level": "TRACE",
        "appender": {
            "type": "console"
        }
    }]
});

var logger = log4js.getLogger('cheese');
logger.setLevel('TRACE');

logger.trace('Entering cheese testing');
logger.debug('Got cheese.');
logger.info('Cheese is Gouda.');
logger.warn('Cheese is quite smelly.');
logger.error('Cheese is too ripe!');
logger.fatal('Cheese was breeding ground for listeria.');

実行結果は以下のとおりですが、INFO以上は2回表示されてしまいます。

[2017-01-01 23:04:35.423] [TRACE] cheese - Entering cheese testing
[2017-01-01 23:04:35.427] [DEBUG] cheese - Got cheese.
[2017-01-01T23:04:35+0900] local INFO cheese: Cheese is Gouda.
[2017-01-01 23:04:35.428] [INFO] cheese - Cheese is Gouda.
[2017-01-01T23:04:35+0900] local WARN cheese: Cheese is quite smelly.
[2017-01-01 23:04:35.429] [WARN] cheese - Cheese is quite smelly.
[2017-01-01T23:04:35+0900] local ERROR cheese: Cheese is too ripe!
[2017-01-01 23:04:35.429] [ERROR] cheese - Cheese is too ripe!
[2017-01-01T23:04:35+0900] local FATAL cheese: Cheese was breeding ground for listeria.
[2017-01-01 23:04:35.429] [FATAL] cheese - Cheese was breeding ground for listeria.

2つ目のlogLevelFilterでINFO以上を表示しないようにするためにmaxLevelでレベルの上限を指定します。

const log4js = require('log4js');

log4js.configure({
    "appenders": [{
        "type": "logLevelFilter",
        "level": "INFO",
        "appender": {
            "type": "console",
            "layout": {
                "type": "pattern",
                "pattern": "[%d{ISO8601_WITH_TZ_OFFSET}] %h %p %c: %m"
            }
        }
    },
    {
        "type": "logLevelFilter",
        "level": "TRACE",
        "maxLevel": "DEBUG",
        "appender": {
            "type": "console"
        }
    }]
});

var logger = log4js.getLogger('cheese');
logger.setLevel('TRACE');

logger.trace('Entering cheese testing');
logger.debug('Got cheese.');
logger.info('Cheese is Gouda.');
logger.warn('Cheese is quite smelly.');
logger.error('Cheese is too ripe!');
logger.fatal('Cheese was breeding ground for listeria.');

これを実行すると以下のようにTRACEとDEBUGは2つ目のフォーマット、INFO以上は一つ目のフォーマットで表示されます。

[2017-01-01 23:14:56.918] [TRACE] cheese - Entering cheese testing
[2017-01-01 23:14:56.922] [DEBUG] cheese - Got cheese.
[2017-01-01T23:14:56+0900] Alis.local INFO cheese: Cheese is Gouda.
[2017-01-01T23:14:56+0900] Alis.local WARN cheese: Cheese is quite smelly.
[2017-01-01T23:14:56+0900] Alis.local ERROR cheese: Cheese is too ripe!
[2017-01-01T23:14:56+0900] Alis.local FATAL cheese: Cheese was breeding ground for listeria.