Node.jsでcluster環境でのlogging

概要

cluster環境では複数のプロセスが並列に動きます。
この状態で１つのログファイルにアクセスすると干渉が起きます。
かと言って各プロセス毎にログファイルを作成してしまうのは集約が面倒です。
今回はlog4jsを使ってその問題を解決します。

環境

• Node.js 5.1.0
• log4js 0.6.28

フォルダ構造

.
├── app.js
├── config.js
├── logger.js
├── master.js
├── package.json
├── public
├── routes
├── server.js
├── views
└── worker.js

cluster環境を用意

以下の3つのファイルを主に使用します。

ファイル	役割
server.js	masterとworkerを区別して起動
master.js	workerをspawnする
worker.js	/bin/wwwのような処理

server.js

masterかworkerかを判別して処理を分けます。

'use strict';

const cluster = require('cluster');
const Master = require('./master');
const Worker = require('./worker');

if (cluster.isMaster) {
  let master = new Master();

  master.run();
} else {
  let worker = new Worker();

  worker.run();
}

---

master.js

workerをCPUの分だけforkします。
またuncaughtExceptionなどでプロセスが死んだ場合はworkerをrespawnします。

#!/usr/bin/env node
'use strict';

const os = require('os');
const cluster = require('cluster');
const logger = require('./logger')();

class Master {
  constructor() {
  }

  run() {
    let cpuCount = os.cpus().length;
    for (let i = 0; i < cpuCount ; i++) {
        cluster.fork();
        logger.system.info("forked: " + i);
    }

    cluster.on('exit', (worker, code, signal) => {
      logger.system.info('worker exit', {
        worker: worker.id,
        pid: worker.process.pid,
        signal: signal,
        code: code
      });

      cluster.fork();
    });
  }
};

module.exports = Master;

---

worker.js

/bin/wwwを削ってES6に則って変更しただけです。

'use strict';

const app = require('./app');
const http = require('http');
const port = 3000;
app.set('port', port);

function onError(error) {
  if (error.syscall !== 'listen') {
    throw error;
  }

  var bind = typeof port === 'string'
    ? 'Pipe ' + port
    : 'Port ' + port;

  // handle specific listen errors with friendly messages
  switch (error.code) {
    case 'EACCES':
      console.error(bind + ' requires elevated privileges');
      process.exit(1);
      break;
    case 'EADDRINUSE':
      console.error(bind + ' is already in use');
      process.exit(1);
      break;
    default:
      throw error;
  }
}

class Worker {
  constructor() {
  }

  run() {
    let server = http.createServer(app);
    server.listen(port);
    server.on('error', onError);
  }
}

module.exports = Worker;

log4jsの設定

まずpackage.jsonでlog4jsを追加しておいてください。

clusteredタイプを使います。
これを使用するとworkerのログはmasterに送信され、ログファイルへの書き込みはmasterのみとなります。これにより前述の干渉問題を解決してます。

今回は以下の２つのファイルを使います。

ファイル	役割
config.js	log4jsの設定
logger.js	loggerの初期化

config.js

master側にlog4jsの設定を書きます。
worker側はtypeのみ書きます。

'use strict';

let config = {};

config.log4js = {
  master: {
    appenders: [
      {
        type: 'clustered',
        appenders: [
          {
            category: 'access',
            type: 'dateFile',
            filename: './access.log',
            pattern: '-yyyy-MM-dd',
            backups: 3
          },
          {
            category: 'error',
            type: 'dateFile',
            filename: './error.log',
            pattern: '-yyyy-MM-dd',
            backups: 3
          },
          {
            category: 'system',
            type: 'dateFile',
            filename: './system.log',
            pattern: '-yyyy-MM-dd',
            backups: 3
          },
          {
            type: 'console'
          }
        ],
        levels: {
          access: 'ALL',
          system: 'ALL',
          error: 'ALL'
        }
      }
    ]
  },
  worker: {
    appenders: [
      {
        type: 'clustered'
      }
    ]
  }
};

module.exports = config;

---

logger.js

masterとworkerを区別して設定を読み込みます。

'use strict';

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

module.exports = () => {
  if (cluster.isMaster) {
    log4js.configure(config.log4js.master);
  } else {
    log4js.configure(config.log4js.worker);
  }

  return {
    access: log4js.getLogger('access'),
    system: log4js.getLogger('system'),
    error: log4js.getLogger('error'),
    express: log4js.connectLogger(log4js.getLogger('access'), {
      level: log4js.levels.INFO,
      format: JSON.stringify({
        date: ':date',
        ip: ':remote-addr',
        status: ':status',
        path: ':url',
        method: ':method',
        contentLength: ':content-length',
        ua: ':user-agent',
        latency: ':response-time'
      })
    })
  };
};

その他設定

app.jsのデフォルトのloggerを変更しておきます。

// var logger = require('morgan');
const logger = require('./logger')();
~~~
// app.use(logger('dev'));
app.use(logger.express);

動作確認

起動してみます。

$ node server.js 
[2015-11-26 21:52:10.053] [INFO] system - forked: 0
[2015-11-26 21:52:10.061] [INFO] system - forked: 1
[2015-11-26 21:52:10.065] [INFO] system - forked: 2
[2015-11-26 21:52:10.068] [INFO] system - forked: 3
[2015-11-26 21:52:10.071] [INFO] system - forked: 4
[2015-11-26 21:52:10.074] [INFO] system - forked: 5
[2015-11-26 21:52:10.077] [INFO] system - forked: 6
[2015-11-26 21:52:10.080] [INFO] system - forked: 7

ちゃんとclusterで起動しますね。
アクセスしてみます。

[2015-11-26 21:52:18.083] [INFO] access - {"date":"Thu, 26 Nov 2015 12:52:18 GMT","ip":"::1","status":"200","path":"/","method":"GET","contentLength":"170","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36","latency":"325"}
[2015-11-26 21:52:18.287] [INFO] access - {"date":"Thu, 26 Nov 2015 12:52:18 GMT","ip":"::1","status":"200","path":"/stylesheets/style.css","method":"GET","contentLength":"111","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36","latency":"8"}
[2015-11-26 21:52:21.601] [INFO] access - {"date":"Thu, 26 Nov 2015 12:52:21 GMT","ip":"::1","status":"200","path":"/","method":"GET","contentLength":"170","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36","latency":"322"}
[2015-11-26 21:52:21.801] [INFO] access - {"date":"Thu, 26 Nov 2015 12:52:21 GMT","ip":"::1","status":"200","path":"/stylesheets/style.css","method":"GET","contentLength":"111","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36","latency":"8"}
[2015-11-26 21:52:22.259] [INFO] access - {"date":"Thu, 26 Nov 2015 12:52:22 GMT","ip":"::1","status":"404","path":"/favicon.ico","method":"GET","contentLength":"1365","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36","latency":"23"}

問題なく出力されます。
お疲れ様でした。

ソース

• Clustered