Express + Fluentdでエラーログ

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

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

https://bitbucket.org/p_baleine/express-fluent-sample

# ExpressからFluentdを利用する

[fluent-logger-node](https://github.com/fluent/fluent-logger-node)を利用します

```bash
$ npm install fluent-logger-node --save
```

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

```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](https://bitbucket.org/p_baleine/express-fluent-sample/src/73ffbd239748203a8382bc3cfa8af80a8685cf1b/lib/access-logger.js?at=master))

```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 });
  };
});
```

こんな感じで使います

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

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

# エラーハンドラ

肝心のエラーハンドラは以下のような感じです([lib/error-handler.js](https://bitbucket.org/p_baleine/express-fluent-sample/src/73ffbd239748203a8382bc3cfa8af80a8685cf1b/lib/error-handler.js?at=master))

```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`に以下を追加します

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

# サンプルコントローラ

同期、非同期に発生するエラーを試すためのサンプルコントローラです([lib/routes/post.js](https://bitbucket.org/p_baleine/express-fluent-sample/src/73ffbd239748203a8382bc3cfa8af80a8685cf1b/lib/routes/post.js?at=master))

```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](https://bitbucket.org/p_baleine/express-fluent-sample/src/73ffbd239748203a8382bc3cfa8af80a8685cf1b/td-agent.conf?at=master))。

```
<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>
```

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

* [fluent-plugin-record-reformer](https://github.com/sonots/fluent-plugin-record-reformer)
* [fluent-plugin-mongo](https://github.com/fluent/fluent-plugin-mongo)
* [fluent-plugin-mail](https://github.com/u-ichi/fluent-plugin-mail)

# 試してみる

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

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

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

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

# おまけ、アクセスログ

以下ミドルウェアを([lib/access-logger.js](https://bitbucket.org/p_baleine/express-fluent-sample/src/73ffbd239748203a8382bc3cfa8af80a8685cf1b/lib/access-logger.js?at=master))

```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`から利用してあげるとアクセスログも取れます。