2013/09/04更新

[Nodejs] Express+Log4jsで実践的なログ出力を行う

こんにちは、@yoheiMuneです。
本日は、Log4jsを使ったログの出力やログローテーションをExpressで行う方法をブログに書きたいと思います。

Expressで一番簡単なログファイルの作成

Expressで出力しているコンソールログを一番簡単にログファイルに保存するには、以下のコマンドで実現で来ます。

$ node app.js >> app.log

こうすればコンソール出力されてる内容が、app.logというファイルに書き込まれます。
ただ、開発中はこれくらいで良いのですが、リリースして運用する為にはログファイルを分けたり、フォーマットを指定したりしたいので、ちょっと不十分です。そこでlog4jsというログ出力モジュールを使って、ログ出力を行いたいと思います。

Log4jsの紹介

Log4jsは、JavaのLog4jのJavaScriptバージョンのモジュールで、柔軟なログ出力を行うことが出来ます。
例えば以下のようなことを行うことが出来、運用しやすいログを出力することが簡単に出来ます。

ログの種類（requestログやqueryログなど）毎に、出力するファイルを分ける
ログファイルを日付毎に分ける（＝ログローテーション）
ログ出力レベルを設定する
ログ出力の設定を外部ファイル化、設定ファイルの定期的な読み込み
Expressログとの結合

それではさっそく、Log4jsを使ってみます。

Log4jsの導入と簡単な使い方

Log4jsの導入は簡単で、npmでインストールします。

$ npm install log4js --save

これでインストールが成功したら完了です。

インストールが出来たらさっそく使ってみます。便利に使うには設定を書く必要もありますが、とりあえず使う為には設定とか無く、以下のように使うことが出来ます。

var log4js = require('log4js');
var logger = log4js.getLogger();
logger.info('sample log.');

上記の出力結果は、以下のようにコンソールに出力されます。

$ node app.js
[2013-09-12 14:04:49.197] [INFO] [default] - sample log.

これでlog4jsの導入＆簡単な使い方が完了です。続いて以下では、上述したログへの要件毎にLog4jsの使い方を書きたいと思います。

ログの種類毎に、出力するファイルを分ける

まずは目的別に出力するファイルを設定する方法です。 Log4jsでは、カテゴリ毎に出力内容を分けることが出来ます。Log4jsで以下のように設定を行うことで、目的毎に出力を分けます。

// モジュールをインポートします
var log4js = require('log4js');

// 設定を行います
log4js.configure({
    appenders: [

        // リクエストログ用設定
        {
            "type": "file",
            "category": "request",
            "filename": "logs/request.log",
            "pattern": "-yyyy-MM-dd"            
        },

        // ユーザーアクションログ用
        {
            "type": "file",
            "category": "action",
            "filename": "logs/action.log",
            "pattern": "-yyyy-MM-dd"
        },
    ]
});

// リクエストログ用のLoggerを取得して、ログ出力します。
var loggerRequest = log4js.getLogger('request');
loggerRequest.info('this is request log');

// アクションログ用のLoggerを取得して、ログ出力します。
var loggerAction = log4js.getLogger('action');
loggerAction.info('this is action log');

log4jsの設定をconfigureメソッドを使って行うことが出来ます。ログの設定で、カテゴリを分けることで複数のログ設定を行うことが出来ます。
今回はカテゴリをリクエストログとアクションログで分けて、出力するファイルrequest.logとaction.logに分けるようにしました。

ログファイルを日付毎に分ける

log4jsの設定を行うことで、日付毎にログローテーションを行うことが出来ます。
以下のように実装します。

// モジュールをインポートします
var log4js = require('log4js');

// 設定を行います
log4js.configure({
    appenders: [
        {
            "type": "dateFile",
            "category": "request",
            "filename": "logs/request.log",
            "pattern": "-yyyy-MM-dd"            
        },

    ]
});

// ログ出力 
var logger = log4js.getLogger('request');
loggerRequest.info('this is request log');

ポイントは、設定のtypeを「dateFile」にして、patternを日付毎に変わるように設定することです。これで日付の切り替わり時に自動的にログローテーションを行うことが出来ます。

ログの出力レベルを設定する

今までのサンプルでは、infoレベルのログ出力のみでしたが、log4jsでは以下の種類のレベルでログを出力することが出来ます。

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レベル以上のログのみを表示して、ログを見やすくしたりログファイルサイズの抑制を行うことが出来ます。
以下のように設定します。

var log4js = require('log4js'); 
var logger = log4js.getLogger('request');
logger.setLevel('ERROR');

この設定だと、ErrorログとFatalログの２種類のみ表示されるようになります。

ログ出力設定を外部ファイル化、そのファイルを定期的に読み込み

上記までの実装ではログの実装をプログラム内に記述していましたが、JSON形式で外部ファイルに指定することが可能です。
以下のようなJSONファイルを作成します。
（log4js_setting.json）

{
    "appenders": [
        {
            "type": "dateFile",
            "category": "request",
            "filename": "logs/request.log",
            "pattern": "-yyyy-MM-dd"
        },
        {
            "type": "dateFile",
            "category": "action",
            "filename": "logs/action.log",
            "pattern": "-yyyy-MM-dd"
        }
    ]
}

そして以下のように利用します。

// モジュールをインポートします
var log4js = require('log4js');

// 設定を行います
log4js.configure('log4js_setting.json');

// ログ出力 
var logger = log4js.getLogger('request');
loggerRequest.info('this is request log');

そしてGithub: lo4js-nodeのページによれば、デフォルトで60秒毎に、設定ファイルがリロードされるようです。リロードの感覚を指定する場合には、以下のように実装します。

log4js.configure('log4js_setting.json', { reloadSecs: 300 });

設定ファイルを外部化出来ると、ログの設定を変更する際にもアプリを壊す心配が減っていいですね。

Expressログとの結合

Github: lo4js-node：wikiの内容を実装すると、Expressの出力するログをlog4jsで出力することが出来ます。

// モジュールロード
var express = require('express');
var log4js = require('log4js');

// log4jsの設定
log4js.configure('log4js_setting.json');
var logger = log4js.getLogger();

// Expressの設定
var app = require('express').createServer();

// Log4jsとExpressの結合
app.configure(function() {
  app.use(log4js.connectLogger(logger, { level: log4js.levels.INFO }));
});

これでExpressで出力するログがlog4jsで出力できるようになります。

最後に

今回はExpress+Log4jsによる、実践的なログ出力でした。
Node.jsのExpressでのサーバー構築は色々と不安な点が合ったのですが、ログ部分は実用できそうな実装が出来て良かったです。

最後までご覧頂きましてありがとうございました。