例外が発生しても異常終了しない log4js のロガーを作る
Node.js でロギングする際は log4js をよく使っているのだが、以前、ロギング処理自体に問題があってエラーを起こしてしまった。
そのコードは以下のようなコードだった。
let result = null;
try {
// API をコールしてデータを取得するテイ
result = await fetchAPI('http://example.com/users/1');
}
catch(error) {
// エラーオブジェクトを文字列化してログ出力しようとしたら…
myLog4JsLogger.error('API コールでエラー発生', JSON.stringify(error));
}
変数 myLog4JsLogger でエラーログを出力する際、error オブジェクトを JSON.stringify() で文字列化して出力しようとしていた。しかしこの error オブジェクト、循環参照が含まれており、JSON.stringify() する際に Converting circular structure to JSON というエラーが発生してしまっていた。catch 句の中で例外が発生するので、このエラーは外に漏れ、異常終了に繋がってしまった。
このような話は Murga の以下の記事にも書いた。
こんなことをやらかしたので、「ロガーでロギングする時に発生したエラーは握り潰せたらいいんじゃね？」と軽い気持ちで作ったのがこのラッパー。
logger-wrapper.js
/**
* 例外が発生しても握り潰す log4js ロガーのラッパー
*
* 引数に関数を渡すと、それを実行して戻り値をログ追記する
* 関数実行時に例外が発生した場合は catch し、例外を握り潰す
* ロギング中の例外発生による異常終了を防ぎたい狙いで作成した
*/
class LoggerWrapper {
/**
* コンストラクタ
*
* @param {*} logger ロガー
* @param {boolean} isAsync 引数に非同期関数を持たせられるようにするかどうか (デフォルトは false = 非同期関数に対応しない)
* @param {string} appendErrorLevel ログ追記時にエラーが発生した場合にログ出力するレベル (デフォルトは 'warn' レベルで通知する)
*/
constructor(logger, isAsync, appendErrorLevel) {
this.logger = logger;
this.isAsync = Boolean(isAsync);
this.appendLogFuncName = this.isAsync ? 'appendLogAsync' : 'appendLogSync';
if(['trace', 'debug', 'info', 'warn', 'error', 'fatal'].includes(`${appendErrorLevel}`.toLowerCase())) {
this.appendErrorLevel = `${appendErrorLevel}`.toLowerCase();
}
else {
this.appendErrorLevel = 'warn';
}
}
/**
* ログ追記 : 非同期処理非対応版
*
* @param {string} level ログレベル
* @param {Array<*>} args 追記する要素
*/
appendLogSync(level, ...args) {
try {
const logs = [];
for(let i = 0; i < args.length; i++) {
const arg = args[i];
if(typeof arg === 'function') {
// 関数が渡された場合は実行しその結果を出力する
const fnLogs = arg();
logs.push(...fnLogs);
}
else {
logs.push(arg);
}
}
this.logger[level](...logs);
}
catch(error) {
this.logger[this.appendErrorLevel]('ログ出力失敗', level, error);
}
}
/**
* ログ追記 : 非同期処理対応版
*
* @param {string} level ログレベル
* @param {Array<*>} args 追記する要素
*/
appendLogAsync(level, ...args) {
(async () => {
try {
const logs = [];
for(let i = 0; i < args.length; i++) {
const arg = args[i];
if(typeof arg === 'function') {
// 関数が渡された場合は実行しその結果を出力する
const fnLogs = await arg(); // 非同期処理の場合は待って出力する
logs.push(...fnLogs);
}
else {
logs.push(arg);
}
}
this.logger[level](...logs);
}
catch(error) {
this.logger[this.appendErrorLevel]('ログ出力失敗', level, error);
}
})();
}
// ログレベルごとに関数を定義する
trace(...args) { this[this.appendLogFuncName]('trace', ...args); }
debug(...args) { this[this.appendLogFuncName]('debug', ...args); }
info (...args) { this[this.appendLogFuncName]('info' , ...args); }
warn (...args) { this[this.appendLogFuncName]('warn' , ...args); }
error(...args) { this[this.appendLogFuncName]('error', ...args); }
fatal(...args) { this[this.appendLogFuncName]('fatal', ...args); }
}
// log4js のロガーを用意する
// ================================================================================
const log4js = require('log4js');
log4js.configure({
appenders: {
stdout: {
type: 'stdout'
}
},
categories: {
default: {
appenders: ['stdout'],
level: 'all'
}
}
});
const myLog4JsLogger = log4js.getLogger('default');
// 使用例 1 : 非同期処理非対応版
// ================================================================================
// ロガーインスタンスを準備する
const myLogger = new LoggerWrapper(myLog4JsLogger);
// 以下のように通常利用可能
myLogger.trace('Trace Log');
myLogger.debug('Debug Log');
myLogger.info ('Info Log', 'hoge');
myLogger.warn ('Warn Log', 1234);
myLogger.error('Error Log', () => ['a', 1234]);
myLogger.fatal('Fatal Log', () => ['a', 1234], 'foo', 'bar');
// JSON.parse() 部分をそのままログ出力しようとすると例外が発生するので関数でラップして出力する
myLogger.info('例外が発生するかもしれない要素のログ出力を試みる', () => JSON.parse('Invalid JSON String'));
// 使用例 2 : 非同期処理対応版
// ================================================================================
// 非同期処理に対応するロガーインスタンスを生成する
const myAsyncLogger = new LoggerWrapper(myLog4JsLogger, true);
// 循環参照例外が発生する連想配列
const dummyObj = {};
const dummyRefObj = {};
dummyObj.dummyRefObj = dummyRefObj;
dummyRefObj.dummyObj = dummyObj;
myAsyncLogger.info('例外が発生する同期処理', () => JSON.stringify(dummyObj));
// Reject される非同期処理
const dummyPromise = new Promise((_resolve, reject) => {
setTimeout(() => {
reject('Dummy Reject');
}, 1000);
});
myAsyncLogger.info('例外が発生する非同期処理', () => dummyPromise);
log4js.getLogger() で取得したロガーのインスタンスをラップする。
例えば以下のコードは、JSON.parse() に失敗すると例外が発生してしまう。
myLogger.info( JSON.parse(jsonStr) );
このように、例外が発生しそうで怖い要素は、以下のように関数でラップして渡してやる。
myLogger.info( () => JSON.parse(jsonStr) );
// 以下と同じ
myLogger.info( () => { return JSON.parse(jsonStr); } );
myLogger.info( function() { return JSON.parse(jsonStr); } );
このように関数でラップしてやれば、まだ関数は実行されていないので、この時点での例外は発生しない。
そして、ラッパークラス内は try / catch で全体を囲んだ状態で、引数に関数が渡っていればそれを実行しているので、例外が発生しても呼び出し元に影響しない、というワケ。
async / await を使って、ほとんど同じ作りで、非同期処理に対応した関数も用意してある。「Promise を返す関数」をロガーのラッパーの引数に渡してやれば良い。
以上。ホントはそもそもロギングするモノをよく把握して実装して例外なんか起こすなよって話なんだけども。ｗ