Expressのエラーハンドリングでエラーのロギングをcentralizeに行い、且つアプリケーションコード側ではログを吐くことだけに集中させて実際にログをどう処理するかー基本MongoDBに書きこむがseverityが高い場合はメール通知する等はFluentdに任せられると理想的と思い、実践して見ました。

サンプルコードは以下にあります

ExpressからFluentdを利用する

fluent-logger-nodeを利用します

$ npm install fluent-logger-node --save

トップレベルのapp.jsで初期化を行います

var fluentLogger = require('fluent-logger').configure('express-fluent-sample', {
  host: "localhost",
  port: 24224,
  timeout: 3.0
});

どうやらfluent-logger-nodeはコネクションをシングルトンに保持してくれているらしいので、アプリのエントリーポイントで一度この初期化をおこなっておけば、他のモジュールからは単にrequire('fluent-logger-node')で呼び出せるようです。

システムログ

エラー、デバッグ…等レベルのロギングを担うモジュールを設けます(lib/system-logger.js)

var fluentLogger = require('fluent-logger');

var levels = [
  'info',
  'debug',
  'warn',
  'error'
];

levels.forEach(function(level) {
  module.exports[level] = function(msg) {
    fluentLogger.emit('syslog.' + level, { message: msg });
  };
});

こんな感じで使います

var logger = require('./system-logger');
logger.info('hoge');

上記コードでexpress-fluent-sample.syslog.infoタグでFluentに送信されます。

エラーハンドラ

肝心のエラーハンドラは以下のような感じです(lib/error-handler.js)

var logger = require('./system-logger');

module.exports = function() {
  return function(err, req, res, next) {
    if (err instanceof EmptyResponse) { res.status(404); }

    logger.error(err.message);

    res.send(('' + res.statusCode).match(/2\d{2}/) ? 500 : res.statusCode,
             'Something broken!');
  };
};

5行目でerrがEmptyResponseのインスタンスの場合にステータスコードを404にしてみています。EmptyResponseは例えばモデル層で対象となるレコードが発生しない場合に発生する例外などです。

app.jsに以下を追加します

// ...
app.use(app.router);
app.use(errorHandler());
// ...

サンプルコントローラ

同期、非同期に発生するエラーを試すためのサンプルコントローラです(lib/routes/post.js)

var logger = require('../system-logger');
var EmptyResponse = require('../error-handler').EmptyResponse;

exports.index = function(req, res) {
  logger.info('this is info');
  res.send('Hello, world');
};

exports.create = function(req, res) {
  throw new Error('error is thrown!');
};

exports.show = function(req, res, next) {
  findPost(req.params.post, function(err, post) {
    if (err) { next(err); }
  });
};

function findPost(id, cb) {
  cb(new EmptyResponse('not found post: %d', id));
}

Fluentの設定

Fluentはあまり詳しくないので、もっと効率の良い記述があったら教えてください、エラーレベルのシステムログの場合はMongoDBに書きこんで且つエラー通知、それ以外のレベルではMongoDBにのみ書きこんでいます(etc/td-agent/td-agent.conf)。

<match express-fluent-sample.syslog.*>
  type record_reformer
  output_tag reformed.${tag}

  level ${tag_parts.last}
  message ${message}
</match>

<match reformed.express-fluent-sample.syslog.error>
  type copy
  <store>
    type mongo
    database express-fluent-sample
    collection syslog
    capped
    capped_size 100m
  </store>
  <store>
    type mail
    host localhost
    port 25
    from noreply@example.com
    to hoge@gmail.com
    subject express-fluent-sample error!!
    message %s\n%s
    message_out_keys level,message
  </store>
</match>

<match reformed.express-fluent-sample.syslog.**>
  type mongo
  database express-fluent-sample
  collection syslog
  capped
  capped_size 100m
</match>

動かすには以下プラグインが必要です

試してみる

$ curl -X GET http://localhost:3000/posts

MongoDBのexpress-fluent-sampleデータベースのsyslogコレクションとaccessコレクションに書き込みが在るはずです。

$ curl -X POST http://localhost:3000/posts

POSTのルーティングではわざとエラーを発生させているのでMongoDBへの書き込みに加えてメールが飛びます。

おまけ、アクセスログ

以下ミドルウェアを(lib/access-logger.js)

var fluentLogger = require('fluent-logger');
var format = require('util').format;

/**
 * Emit `access` event to fluent.
 */

module.exports = function() {
  return function(req, res, next) {
    var sock = req.socket;
    var remoteAddress = sock.socket ? sock.socket.remoteAddress : sock.remoteAddress;
    var method = req.method;
    var url = req.url;
    var httpVersion = req.httpVersion;
    var startTime = Date.now();

    function logRequest() {
      res.removeListener('finish', logRequest);
      res.removeListener('close', logRequest);

      var len = parseInt(res.getHeader('Content-Length'), 10);

      fluentLogger.emit('access', {
        'remote-address': remoteAddress,
        'method': method,
        'url': url,
        'http-version': httpVersion,
        'status': res.statusCode,
        'res[content-length]': isNaN(len) ? '' : len,
        'response-time': Date.now() - startTime
      });
    }

    res.on('finish', logRequest);
    res.on('close', logRequest);

    next();
  };
};

app.jsから利用してあげるとアクセスログも取れます。

Express + Fluentdでエラーログ