課題
expressでWebアプリを作っている時に、loggerとしてbunyanを利用していた。
その時に、logger.error({ req:req, res:res, error:error }, message)と毎回書くのがだるいので、req.logError(error, message)で済むように下記のようなmiddlewareを書いて対応した。
var bunyan = require('bunyan');
var log = bunyan.createLogger({name: 'myApp'});
module.exports = function (req, res, next) {
req.logError = function (error, message) {
log.error({ req:req, res:res, error:error }, message);
}
next();
};
うまく動いているかのように思ったが、出力されているログのsrc（ソースのどの位置からログが出力されたかの情報）を見ると、req.logErrorを呼び出しているところではなく、middlewareの中でlog.error({ ... })を呼び出しているところのファイル名・行番号を出力しており、全くデバッグに役立たない情報になってしまっていた。
対応
bunyanの実装をほとんどパクって、呼び出し元のファイル名・行番号を取得するgetCallerという関数を定義した。
/**
* StackTrace APIを利用して呼び出し元を取得する
*
* @param {Number} stackIndex 取得するstacktraceのindex, デフォルトは1
* @return {Object} { file: 'ファイル名’, line: '行番号', func: '関数名（設定されている場合)' }
*/
function getCaller(stackIndex) {
var callerInfo = {};
var saveLimit = Error.stackTraceLimit;
var savePrepare = Error.prepareStackTrace;
stackIndex = (stackIndex - 0) || 1;
Error.stackTraceLimit = stackIndex + 1;
Error.captureStackTrace(this, getCaller);
Error.prepareStackTrace = function (_, stack) {
var caller = stack[stackIndex];
callerInfo.file = caller.getFileName();
callerInfo.line = caller.getLineNumber();
var func = caller.getFunctionName();
if (func) {
callerInfo.func = func;
}
};
this.stack;
Error.stackTraceLimit = saveLimit;
Error.prepareStackTrace = savePrepare;
return callerInfo;
}
middlewareのsrcにgetCallerの返り値を設定する。
module.exports = function (req, res, next) {
req.logError = function (error, message) {
log.error({ req:req, res:res, error:error, src: getCaller() }, message);
}
next();
};
仕組み
v8のStack Trace APIを使う。
v8（Node.js、Chrome） では、スタックトレースはErrorをインスタンス化した時に収集され、error.stackプロパティから文字列として取得できる。
var error = new Error();
console.log(error.stack);
//出力:
//Error
// at Object.<anonymous> (/Users/pirosikick/tmp/hoge.js:1:75)
// at Module._compile (module.js:456:26)
// at Object.Module._extensions..js (module.js:474:10)
// at Module.load (module.js:356:32)
// at Function.Module._load (module.js:312:12)
// at Function.Module.runMain (module.js:497:10)
// at startup (node.js:119:16)
// at node.js:906:3
error.stackに入っている文字列は、フォーマットされた状態で保存されているわけではなく取得しようとしたタイミングでフォーマットされる。
フォーマットにはError.prepareStackTrace関数を使っているので、ここに自分で定義した関数を入れるとフォーマットされる前のスタックトレースを取得できる。
また、Error以外の任意の関数でスタックトレースを取得したい場合は、Error.captureStackTrace関数を使い任意の関数にstackプロパティを用意する。
function myFunction () {
// 第2引数に渡した関数はスタックトレースから除外される
Error.captureStackTrace(this, myFunction);
console.log(this.stack);
}
myFunction();
// 出力：
//[object global]
// at Object.<anonymous> (/Users/pirosikick/tmp/hoge.js:7:1)
// at Module._compile (module.js:456:26)
// at Object.Module._extensions..js (module.js:474:10)
// at Module.load (module.js:356:32)
// at Function.Module._load (module.js:312:12)
// at Function.Module.runMain (module.js:497:10)
// at startup (node.js:119:16)
// at node.js:906:3
Error.prepareStackTraceとError.captureStackTraceを組み合わせると、任意の関数で文字列にフォーマットされる前のスタックトレースが取得できる。
function myFunction () {
// あとで元に戻すためにバックアップ
var backupPrepare = Error.prepareStackTrace;
// 第2引数に渡した関数はスタックトレースから除外される
Error.captureStackTrace(this, myFunction);
Error.prepareStackTrace = function (_, stack) {
// stackはCallSiteオブジェクトの配列
stack.forEach(function (callSite, i) {
console.log('index:%d', i);
console.log('> getFileName():%s', callSite.getFileName());
console.log('> getLineNumber():%s', callSite.getLineNumber());
console.log('> getColumnNumber():%s', callSite.getColumnNumber());
});
};
// stackプロパティにアクセスしないとprepareStackTraceが呼ばれない
this.stack;
// デフォルトのprepareStackTrace関数に戻す
Error.prepareStackTrace = backupPrepare;
}
myFunction();
// 出力:
// index:0
// > getFileName():/Users/pirosikick/tmp/hoge.js
// > getLineNumber():30
// > getColumnNumber():1
// index:1
// > 省略...
取れるスタックトレースの最大数はError.stackTraceLimitで管理されており、デフォルトは10なので、適宜調整する。（getCaller関数では、必要な分だけ取得するようにしている。）