2014-07-18

片手間でJavaScript書いてる Yuumi3 です。

時間が出来たので、今さらながら Node.js や流行の Angula.js を学んでました。学ぶためには何かアプリを作るのが一番ということで、簡単なWebアプリの状態監視ツールを Node.js, Socket.IO, Koa, Angula.js, Mocha を使い作ってみました。

作るアプリについて

サーバー1台で運用しているサービスで、ソフトの更新などでアプリケーションサーバーをリスタートするタイミングは、今までは tail -f production.log でアクセス状況を見ながら行ってきました。しかし、面倒なので、ログをチェックしながらアプリのステータスを教えてくれるアプリを作ってみました。

ステータスは3つあって

Red

ユーザーが重要な事を行っている、例えばネットショップでは注文手続きを行っている(注文手続のURLをアクセスしてからの一定時間)。この状態ではアプリをリスタートしてはいけない。

Green

検索エンジンのクローラーや監視ツール以外のアクセスが無い、この状態ならリスタートOK。

Yellow

ユーザーからアクセスはあるけど見てるだけなので、まあ一瞬なら止めても良いかなという状況。急ぎならリスタートしても良い ^^;

構成

サーバー側は Node.js
クライアントは Angula.js
サーバーから情報を Socket.IO を使いクライアントに push
クライアントから最初のアクセスは http
サーバー側のフレームワークは Koa
サーバー側のテンプレートは Jade
サーバー側ロジックのテストを Mocha で記述
判定に使うログは Ruby on Railsのログに UserAgentを追加したもの UserAgenのログ追加に付いては、こちら

クライアント側のAngula.js や Koa などこの程度のアプリではオーバースペックですが勉強のために使ってみました。

設定ファイル

  "log_path" : "/home/rails_apps/sample/current/log/production.log",
  "effective_time" : 120,
  "crucial_condition" : {"path" : "^/orders"},
  "pointless_condition" : {"user_agent" : "Googlebot|Yahoo!|Y!J|msnbot|bingbot|Baidu|Wget|Pingdom"}
}

ログファイルのパス
アクセスの有効時間：例えば注文関連のURLのアクセスが在ってから指定時間はユーザーが処理を行ってると判断する時間
重要(Red)条件：ユーザーが重要な作業をしてる判断条件、パスやUserAgentなどの正規表現文字列を指定します
無視(Green)条件：クローラーや監視ツールなどの判断条件、パスやUserAgentなどの正規表現文字列を指定します

サーバー側

全てのコードはGitHub https://github.com/yuumi3/app_status に置きました。

メインのコード(Koa)

行っている事は

Koaの設定
/ へのアクセスがあるとログファイルの最後8Kbyteを読み込み、サーバーにindex.htmlを配信
クライアントとの間にSocketが繋がると、現在の状態、最新のログをpush
ログファイルを file-tail を使い監視、変更があったら読み込み、現在の状態、最新のログをpush
アクセスの有効時間以上なにもなかったら、現在の状態、最新のログをpush
CSS, JS等の配信 koa-static

use strict';

var app = require('koa')();
var router = require('koa-router');
var serve = require('koa-static');
var views = require('koa-views');

var fileTailer = require('file-tail');
var railsLog = require('./rails-log');

app.use(serve('./public'));
app.use(views('views', {default: 'jade'}));
app.use(router(app));

app.get('/', function *(next) {
  yield log.readTail(8 * 1024);
  yield this.render('index', {});
});

var server = require('http').Server(app.callback());
var io     = require('socket.io')(server);
var refreshTimeout;

if (process.argv.length < 3) {
  console.log("Usage: " + process.argv[0] + " --harmony " + process.argv[1] + " CONFIG_PATH");
  process.exit(1);
}
var config = require(process.argv[2]);
var log = railsLog(config);
var tail = fileTailer.startTailing(config.log_path);

function sendStatus(log) {
  var status = log.isCrucial() ? 'red' : (log.isIdle() ?  'green' : 'yellow'); 

  if (log.logs.length == 0) {
    console.log(" - status: " + status);
  } else {
    var lastLog = log.logs[log.logs.length - 1];
    console.log(" - status: " + status + " log: " + lastLog.path + " " + lastLog.time.toISOString());
  }

  io.sockets.emit('update', {status: status, logs: log.logs});
  setAutoRefresh();
}

function setAutoRefresh() {
  if (refreshTimeout) clearTimeout(refreshTimeout);
  refreshTimeout = setTimeout(sendStatus, config.effective_time * 1000, log);
}

io.on('connection', function(socket){
  sendStatus(log);

  tail.on('line', function(line) {
    if (log.addOneLine(line)) {
      sendStatus(log);
    }
  });
});

server.listen(3000);
console.log("Start server.");

Railsログのライブラリー

node.js のモジュールとして RailsLogクラス(rails-log.js)を作ってみました。ログファイルの読み込み readLogFile は ES6の Generator (コルーチン、継続？) を使っています。Generator を手軽に使える Co ライブラリーや Co を fs (ファイルを扱うライブラリー)に組み込んだ co-fs などを使っています

'use strict';

var co = require('co');
var fs = require('co-fs');

module.exports = railsLog;

function railsLog(config) {
  return new RailsLog(config);
}

function RailsLog(config) {
  this.path = config.log_path;
  this.crucial_condition = prepareCondition(config.crucial_condition);
  this.pointless_condition = prepareCondition(config.pointless_condition);
  this.effective_time = config.effective_time || 120;
  this.max_log_size = config.max_log_size || 100;  // not implemented yet
  this.logs = [];
  this.lastAddedLine = '';
}

RailsLog.prototype.readTail = function*(len) {
  this.logs = []
  var content = yield readLogFile(this.path, len);
  content.split("\n").forEach(function(log) {this.addOneLine(log)}, this);
}

RailsLog.prototype.addOneLine = function(logString) {
  if (logString == this.lastAddedLine) return false;
  this.lastAddedLine = logString;

  var m = logString.match(/Started\s+(\w+)\s+\"(.*?)\"\s+for\s+([\d\.]+)\s+at\s+([\d: +-]+)\s+by\s+(.*)$/);
  if (!m) return false;
  var log = {method: m[1], path: m[2], ip: m[3], time: new Date(m[4]), user_agent: m[5]};
  if (isMatchCondition(log, this.pointless_condition)) return false;

  this.logs.push(log)
  return true;
}

RailsLog.prototype.isCrucial = function() {
  var cond = this.crucial_condition;
  addEffectiveTimeCondition(cond, this.effective_time);

  return this.logs.some(function(e) {
    return isMatchCondition(e, cond);
  })
}

RailsLog.prototype.isIdle = function() {
  var cond = {}
  addEffectiveTimeCondition(cond, this.effective_time);

  return !this.logs.some(function(e) {
    return isMatchCondition(e, cond);
  })
}

RailsLog.prototype.last = function(lines) {
  return this.logs.slice(-lines);
}

exports.railsLog = function(config) {new RailsLog(config);}

function *readLogFile(path, len) {
  var fd = yield fs.open(path, 'r');
  var stat = yield fs.fstat(fd);

  var buff = new Buffer(len);
  var pos = stat.size - len;
  if (pos < 0) {
    pos = 0;
  }
  var len_buff = yield fs.read(fd, buff, 0, len, pos);
  return len_buff[1].toString();
}

function isMatchCondition(e, conds) {
  for (var key in conds) {
    if (key == 'time') {
      if (e[key].getTime() < conds[key]) return false;
    } else {
      if (!e[key].match(conds[key])) return false;
    }
  }
  return true;
}

function prepareCondition(hash) {
  return Object.keys(hash || {}).reduce(function(conds, key){
      conds[key] = new RegExp(hash[key]);
      return conds
    }, 
    {});
}

function addEffectiveTimeCondition(conds, effective_time) {
  var d = new Date();
  conds['time'] = d.setTime(d.getTime() - effective_time * 1000);
}

クライアント側

index.jade

実はスタティックなページですが、テンプレートエンジンを使ってみたかったので使用しました。Angula.js はごく基本的な部分しか使っていません。

doctype html
html(ng-app='statusApp')
  head
    title application status
    script(src='/socket.io/socket.io.js')
    script(src='assets/javascripts/angular.min.js')
    script(src='assets/javascripts/ng-socket-io.min.js')
    script(src='assets/javascripts/status.js')
    link(rel='stylesheet' href='assets/stylesheets/bootstrap.min.css')
    link(rel='stylesheet' href='assets/stylesheets/bootstrap-theme.min.css')
    link(rel='stylesheet' href='assets/stylesheets/status.css')
  body
    div(ng-controller="StatusController")
      div(class="panel {{status_class}}")
        div.panel-heading {{status_text}}
        div.panel-body
          div.logs
            table(class='table table-striped')
              tbody
                tr(ng-repeat="log in logs")
                  td {{log.time | date : 'yyyy-MM-dd HH:mm:ss'}}
                  td {{log.method}}
                  td {{log.path}}
                  td {{log.ip}}
                  td {{log.user_agent}}

status.js

クライアント側のJS, サーバーからのステータス、ログを受け取り Angulaへ渡すだけの簡単なお仕事。Socket.IOは ngSocketIO を使ってます。

angular.module('statusApp', ['socket-io'])
  .controller('StatusController', function($scope, socket) {
    socket.on('update', function(data) {
      
      $scope.logs = data.logs;
      switch(data.status) {
        case 'red':
          $scope.status_class = 'panel-danger';
          $scope.status_text = 'Busy';
          break;
        case 'yellow':
          $scope.status_class = 'panel-warning';
          $scope.status_text = 'Warning';
          break;
        case 'green':
          $scope.status_class = 'panel-success';
          $scope.status_text = 'Idle';
          break;
        default:
          $scope.status_class = 'panel-info';
          $scope.status_text = '???';
          break;
      }
    });
  });

テスト

サーバー側の rails-log.js のテストを Mocha + expect.js でテストを書いてみました。

Co を使ったコードもあるので co-mocha を入れています。
時間に関係したテストには Sinon.js の Fake timers を使い new Date() の戻り時間を設定しています。

'use strict';

require('co-mocha');
var sinon = require('sinon');
var expect = require('expect.js');
var railsLog = require('../rails-log');

describe('RailsLog', function(){
  var log;
  var config = {
    "log_path" : "./test/sample.log",
    "effective_time" : 120,
    "crucial_condition" : {"path" : "^/(cart|order)"},
    "pointless_condition" : {"user_agent" : "Googlebot|bingbot"}
  };

  beforeEach(function(){
    log = railsLog(config);
  })

  describe('addOneLine', function(){
    var accessLine = 'I, [2014-07-06T08:45:33.076218 #1314]  INFO -- : Started GET "/products?s=3"' +
        ' for 203.140.209.190 at 2014-07-06 08:45:33 +0900 by Mozilla/4.0 (compatible; MSIE 8.0;' +
        ' Windows NT 5.1; Trident/4.0; GTB7.5; .NET CLR 1.0.3705; .NET CLR 1.1.4322; YTB730; ' +
        '.NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; .NET4.0C)';

    it('指定したログ文字列がアクセスログなら追加されtrueが戻る', function(){
      expect(log.addOneLine(accessLine)).to.be.ok();
      expect(log.logs.length).to.eql(1);
    })
    it('指定したログ文字列がアクセスログでなければ追加されずfalseが戻る', function(){
      expect(log.addOneLine('I, [2014-07-06T08:44:01.643727 #1311]  INFO -- : Completed 200 OK in 12ms ' +
        '(Views: 6.9ms | ActiveRecord: 1.6ms)')).to.not.be.ok();
      expect(log.logs.length).to.eql(0);
    })
    it('ログは解析されている', function(){
      log.addOneLine(accessLine);
      expect(log.logs[0]).to.eql({ip: "203.140.209.190", method: "GET", path: "/products?s=3", time: {},
        user_agent: "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; GTB7.5; .NET CLR 1.0.3705; .NET CLR 1.1.4322; " + 
                    "YTB730; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; .NET4.0C)"});
      expect(log.logs[0].time).to.eql(new Date(2014,7 - 1,6,8,45,33));
    })
    it('同じログ文字列ならアクセスログなら追加されない', function(){
      expect(log.addOneLine(accessLine)).to.be.ok();
      expect(log.addOneLine(accessLine)).to.not.be.ok();
      expect(log.logs.length).to.eql(1);
    })
  })

  describe('readTail', function(){
    it('ログファイルが読み込まれる', function*(){
      yield log.readTail(2000);
      expect(log.logs.length).to.eql(2);
      expect(log.logs[0].path).to.eql("/admin/scheduled_tasks/beat");
      expect(log.logs[1].path).to.eql("/products/211");
    })

    it('pointless_conditionに該当するログは読み込まれない', function*(){
      config["pointless_condition"] = {"user_agent" : "Googlebot|Wget"};
      log = railsLog(config);
      yield log.readTail(2000);
      expect(log.logs.length).to.eql(1);
    })
  })

  describe('isCrucial', function(){
    var accessLineIn = 'I, [2014-07-06T08:45:33.076218 #1314]  INFO -- : Started GET "/order/confirm"' +
        ' for 203.140.209.190 at 2014-07-06 08:45:33 +0900 by Mozilla/4.0';
    var accessLineOut = 'I, [2014-07-06T08:35:33.076218 #1314]  INFO -- : Started GET "/order/confirm"' +
        ' for 203.140.209.190 at 2014-07-06 08:35:33 +0900 by Mozilla/4.0';
    var clock;

    beforeEach(function(){
      clock = sinon.useFakeTimers((new Date(2014,6,6, 8,45,35)).getTime());
    })
    afterEach(function(){
      clock.restore();
    })
    it('crucial_conditionに該当するログが無ければfalseを戻す', function(){
      expect(log.isCrucial()).to.not.be.ok();
    })
    it('crucial_conditionに該当しeffective_time以内のログがあればtrueを戻す', function(){
      log.addOneLine(accessLineIn);
      expect(log.isCrucial()).to.be.ok();
    })
    it('crucial_conditionに該当しeffective_time以外のログがあればfalseを戻す', function(){
      log.addOneLine(accessLineOut);
      expect(log.isCrucial()).to.not.be.ok();
    })
  })

  describe('isIdle', function(){
    var accessLine = 'I, [2014-07-06T08:45:33.076218 #1314]  INFO -- : Started GET "/products"' +
        ' for 203.140.209.190 at 2014-07-06 08:45:33 +0900 by Mozilla/4.0';
    var clock;

    beforeEach(function(){
      clock = sinon.useFakeTimers((new Date(2014,6,6, 8,45,35)).getTime());
    })
    afterEach(function(){
      clock.restore();
    })
    it('effective_time以内のログが無ければtrueを戻す', function(){
      expect(log.isIdle()).to.be.ok();
    })
    it('effective_time以内のログがあればfalseを戻す', function(){
      log.addOneLine(accessLine);
      expect(log.isIdle()).to.not.be.ok();
    })
  })

  describe('last', function(){
    var accessLine = 'I, [2014-07-06T08:45:33.076218 #1314]  INFO -- : Started GET "/products"' +
        ' for 203.140.209.190 at 2014-07-06 08:45:33 +0900 by Mozilla/4.0 no=';
    var clock;

    beforeEach(function(){
      for(var i = 0; i < 10; i++) { log.addOneLine(accessLine + i); }
    })
    it('指定した行数のログを戻す', function(){
      expect(log.last(5).length).to.eql(5);
      expect(log.last(5)[0].user_agent).to.eql("Mozilla/4.0 no=5");
      expect(log.last(5)[4].user_agent).to.eql("Mozilla/4.0 no=9");
    })
    it('ログの終わりから指定した行を戻す', function(){
      expect(log.last(5)[0].user_agent).to.eql("Mozilla/4.0 no=5");
      expect(log.last(5)[4].user_agent).to.eql("Mozilla/4.0 no=9");
    })
  })

})

感想とか

良い点

npm, Mocha などRubyに似たツールがあり、Ruby プログラマーには入りやすい世界でした
Node.js はブラウザーでJSを書くのに比べ書きやすい気がする
Generatorを使うとコールバック地獄にならない(??)
Mochaは幾つかのスタイルが選べるがexpect.jsと組み合わせると RSpec と似た表記で書けうれしい
Angula.jsのデータバインディングは素晴らしい、チャンスがあれば Rails + Angula.js でアプリを作ってみたい

良くない点

いろいろと覚える事がある、またどのライブラリーを使ったら良いのかが判らない。Rubyも同じだけど ^^;
JSはRubyに比べると、いろいろと面倒くさい。たとえば null, undefined に対して .toString() 出来ないなど細かい事でコードが増えがち。またイテレータ系のメソッドも少ない
function() を書くのが面倒！ CoffeeScriptはまだGeneratorに対応してないようなので今回は見送りましたが、早くCoffeeScript か、ES6 の Arrow functions が使えるようになると良いな
Generatorは使うと非同期なコードが書きやすくなるが、やはり非同期で動作するので色々とハマりやすい
Angula.js 素晴らしいが、ちょっとしたhtmlタグのミスでも動かなくなったりする。慣れの問題かな？それかIDE WebStorm を使えば良いのだろうか？

次のステップは、Rails + Angula.js でView は全てJSのアプリを書いてみたい。

yuumi3のお仕事日記

Ruby on Railsのログ(production.log)にUserAgentを追加する

JavaScriptの勉強に、Node.js, Angula.js を使って簡単ツールを作った