サーバサイドスクリプトのデバッグ その2(log.nsf編)

XPagesのServer Side JavaScriptをデバッグするのに、log.nsfを使う方法も紹介する。

サーバサイドのスクリプトライブラリを用意し、以下の関数を入りつけておく。

  // デバッグ関数
  function inspect(obj) {
    if (obj === null) {
      return "null";
    } else if (obj === undefined) {
      return "undefined";
    }
    // swicthは===で比較される
    switch(typeof obj) {
    case "number":
      // 数値
      return obj;
    case "string":
      // 文字列
      return "\"" + obj + "\"";
    case "function":
      // 関数の場合
      return obj;
    case "java.util.ArrayList":
    case "java.util.Vector":
      // 配列タイプ
      var part1 = "[";
      var list = [];
      for(var index=0; index < obj.length; index++) {
        var item = obj[index];
        list.push(inspect(item));
      }
      return (part1 + list.join(",") + "]");
    case "object":
    case "com.sun.faces.context.SessionMap":
      //オブジェクト(Arrayかも)
      if (obj instanceof Array) {
        var part1 = "[";
        var list = [];
        for(var index=0; index < obj.length; index++) {
          var value = obj[index];
          list.push(inspect(value));
        }
        if (list.length == 0) {
          // 日付型みたいなのはkeyがないので、文字列に変換する
          list.push(obj);
        }
        return (part1 + list.join(",") + "]");
      } else {
        if (typeof(obj) == "object") {
          var part1 = "{";
        } else {
          var part1 = "<" + typeof(obj) + ">:{";
        }
        var list = [];
        for(var key in obj) {
          var value = obj[key];
          if (typeof(value) != "function") {
            list.push(key + ":" + inspect(value));
          }
        }
        if (list.length == 0) {
          // 日付型みたいなのはkeyがないので、文字列に変換する
          list.push(obj);
        }
        return (part1 + list.join(",") + "}");
      }
      break;
    default:
      return "<<" + typeof(obj) + ">>:{" + obj + "}";
    }
  }
  
  
  function debug(message, obj) {
    var header = "[DEBUG][" + @UserName(1) + "]:";
    if (obj === undefined) {
      print(header + message);
    } else {
      print(header + message + inspect(obj));
    }
  }
  

後は、このスクリプトライブラリをXPageのリソースとして組み込んでおけば、ServerSideスクリプトで、調べたいオブジェクトをdebug()に渡せば、log.nsfに以下のように記録される。

  var data = ["aaa", "bbb", "ccc", "ddd"];
  debug("data=", data);
  

この結果は、こんな感じで記録される。

  06/15/2013 09:43:07 PM  HTTP JVM: [DEBUG][CN=Administrator/O=tech]:data = [1,"aaa","3",4]
  

タイムスタンプの形式は、OSのLANG環境変数で変わるはず(Linux系の場合)。

ただ、log.nsfへの出力結果は他のログも出力されるし、debug()の出力結果も、1行の長さがながいと、複数行に分割されてしまい、ちょっと読みにくい。 そこでlog.nsfから必要な情報を抜き出すRubyのスクリプトを用意してみた。

これを使うと、NotesClientを入れているPCから最新のログからdebug()が出力した結果だけ抽出してくれる。

  #!ruby -Ks
  # getlog.nsf
  require 'notes_lib'
  
  def get_loglist(db, unid)
    doc = db.GetDocumentByUNID( unid )
    eventlist = doc["EventList"].values
    ret_list = []
    eventlist.each {|oneline|
      if oneline =~ /HTTP\sJVM\:/
        ret_list.push oneline
      end
    }
    return ret_list
  end
  
  ns = Notes::NotesSession.new
  db = ns.database("technotes", "log.nsf")
  view = db.view("MiscEvents")
  unid_list = []
  view.each {|doc|
    #puts doc["StartTime"].text
    unid_list.push doc.UniversalID
  }
  
  last_two = [unid_list[-2], unid_list[-1]]
  mode = "IDLE"
  loglist = []
  last_two.each {|unid|
    list = get_loglist(db, unid)
    list.each {|oneline|
      case mode
      when "IDLE"
        if oneline =~ /^(.+)HTTP\sJVM\:\s\[DEBUG\](.+)/
          timestamp = $1.strip
          log = $2
          loglist.push "[#{timestamp}]#{log}]"
          mode = "HEAD"
        end
      when "HEAD"
        if oneline =~ /^(.+)HTTP\sJVM\:\s\[DEBUG\](.+)/
          # 分割がなかった場合
          timestamp = $1.strip
          log = $2
          loglist.push "[#{timestamp}]#{log}]"
          mode = "HEAD"
        elsif oneline =~ /^(.+)HTTP\sJVM\:\s(.+)/
          # 分割されてた続きを見つけた
          log = $2
          loglist[-1]+=log
        else
          mode = "IDLE"
        end
      end
    }
  }
  puts loglist.join("\n")
  

注意事項

このスクリプトを使ってて気づいたのだが、ログが複数行に分割されるとき、1文字程度情報が欠落することがある。 log.nsfへ記録する時点で欠落してるので、ログシステムの問題だろう。

あと、以下のケースだと、"subproperty"を表示してくれない。

  var data = ["aaa", "bbb", "ccc", "ddd"];
  data.subproperty = "TEST";
  debug("data=", data);
  

これ、自作のinspect()の問題じゃなく、dataがArrayだからこうなるような気がする。 ためしに、XPagesに組み込まれているtoJson()でdataをJSON文字列にしても、subpropertyの値が記録されない。 JavaScriptのArrayというのはそういうものなのかも。