Log4js on express でcssとかjsとか画像とかのログが落ちないようにする

本文

この記事はJavaScript Advent Calendar 2011 (Node.js/WebSocketsコース) : ATNDの5日目の記事です。

Expressでサービスをリリースしたりするとログとかちゃんと取る必要があるのですが、既存の404 · GitHubだと、.cssとか.jsとか.gifとか.pngとか.jpe?gとかたくさんログを出して、うざいのです。

で、それを回避するパッチを送って取り込まれたのでそのへんのことを書きます。

そもそもlog4js-nodeの機能

githubの例にもありますが

var log4js = require('log4js'); //note the need to call the function
log4js.addAppender(log4js.consoleAppender());
log4js.addAppender(log4js.fileAppender('logs/cheese.log'), 'cheese');

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

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.');

requireして(どこかのバージョンから「require('log4js')()」の最後のカッコがなくなりました)、appenderして、getLoggerすれば、ログが履けるシロモノです。

参考:moe-project.com

connect/expressにフックさせることも簡単で

var app = require('express').createServer();
app.configure(function() {
    app.use(log4js.connectLogger(logger, { level: log4js.levels.INFO }));
});

とすればそのままmiddlewareとして適用されるのでログが落ちます

※ express場合、app.use(app.router)の前に読み込まないと、適用されません

その他の機能1 logrotate

githubではゾンザイな扱いですが(404 · GitHub)、logrotateもあります。
上記リンクのようにlog4jsのconfigureで設定することも出来ますが、次のようにする方が手軽です。

var log4js = require('log4js');
log4js.addAppender(log4js.fileAppender('log/access.log', undefined, 1024*1024, 5), 'access');
var log = log4js.getLogger('access');

var express = require('express')
    , app = module.exports = express.createServer();
app.configure(function(){
  app.use(log4js.connectLogger(log, {level: log4js.levels.INFO}));
  app.use(app.router);
});

log4js.fileAppender()の引数は

  1. ファイル名
  2. フォーマット
  3. ログファイルのサイズ
  4. ローテートで保持しておく数
  5. ファイルサイズのチェック間隔(この間隔でファイルサイズが超えた場合にローテートが起こります)

となっています。

その他の機能2 format

システムログやコンソールログの場合は、デフォルトだけではなく、(たいしてないですが・・・)幾つかのパターンのフォーマットを選ぶことができます(404 · GitHub)

※ expressのappにぶら下げる際には、fileAppenderでのフォーマットなど華麗にスルーされ、app.useで指定したフォーマットが適用されます。この場合、「IP, method, url, HTTP version, status, content-length, referrer, ua」がいつものパースし辛いフォーマットで出力されます。

':remote-addr - - ":method :url HTTP/:http-version" :status :content-length ":referrer" ":user-agent"'

データ解析部門でもあるので、僕はこれを弄りたくて仕方がありません。

基本的に使えるデータのリスト

  • `:req[header]` ex: `:req[Accept]`
  • `:res[header]` ex: `:res[Content-Length]`
  • `:http-version`
  • `:response-time`
  • `:remote-addr`
  • `:date`
  • `:method`
  • `:url`
  • `:referrer`
  • `:user-agent`
  • `:status`

ですが、console.log(request)などとして、出力できるデータは全部、:req[XXX]として捕捉できます。X-Forwarding-ForのようなプロキシされたIPでもなんでも。

あと、データの整形も例えばJSONなら、

JSON.stringify({ip: ':remote-addr', url: ':url', ref: ':referrer', ua: ':user-agent'});

すれば、構造化された形を作った上でそのままlog4jsに渡すことができます。

本題

こんなに便利な機能のあるlog4jsですが、apacheにもあるような「この拡張子は省きたい」とかの設定ができませんでした。
使ったことのある人はみんな「.jsが死ぬほど出る」「jqueryのプラグインとか使うと1リクエストだけでjsが6個も7個もでる」とかうざい状況になっていると思います。

で、拡張したのが、前述したapp.useのところのoptionで「nolog」をセットできるようにしました。
syntaxはこちら

/**
 * syntax
 *  1. String
 *   1.1 "\\.gif"
 *         NOT LOGGING http://example.com/hoge.gif and http://example.com/hoge.gif?fuga
 *         LOGGING http://example.com/hoge.agif
 *   1.2 in "\\.gif|\\.jpg$"
 *         NOT LOGGING http://example.com/hoge.gif and http://example.com/hoge.gif?fuga and http://example.com/hoge.jpg?fuga
 *         LOGGING http://example.com/hoge.agif, http://example.com/hoge.ajpg and http://example.com/hoge.jpg?hoge
 *   1.3 in "\\.(gif|jpe?g|png)$"
 *         NOT LOGGING http://example.com/hoge.gif and http://example.com/hoge.jpeg
 *         LOGGING http://example.com/hoge.gif?uid=2 and http://example.com/hoge.jpg?pid=3
 *  2. RegExp
 *   2.1 in /\.(gif|jpe?g|png)$/
 *         SAME AS 1.3
 *  3. Array
 *   3.1 ["\\.jpg$", "\\.png", "\\.gif"]
 *         SAME AS "\\.jpg|\\.png|\\.gif"
 */

平たくいうと、文字列または正規表現のスカラないしは配列を渡すことができます。それにより最終的に文字列は正規表現になり、それにマッチするパターンはログに落ちなくなります。

例えば、「{nolog: "\\.gif"}」とすると、hoge.gifはログに落ちなくなり、hoge.agifはログに落ちます。

var log4js = require('log4js');
log4js.addAppender(log4js.fileAppender('log/access.log', undefined, 1024*1024, 5), 'access');
var log = log4js.getLogger('access');

var express = require('express')
    , app = module.exports = express.createServer();
app.configure(function(){
  app.use(log4js.connectLogger(log, {level: log4js.levels.INFO, nolog: ["\\.css", "\\.js"]}));
  app.use(app.router);
});

まとめ

本題がすごく小さくなりましたが、これからexpressを使ったWebアプリケーションが増えていく中で、それのログも通常のログ解析に回ることが多いとは思います。
そうなったときにlog4jsを適切に利用して、fluentに流し込んだりとか、そういったことを気持ちよくできるといいかと思います。

追記

スペース区切りとかのログはマジで世の中から消えたらいい