console.log()をラップすると何かしら上手くいかない
想定要件
組み込みソフトのキャリアはそこそこあるけど JavaScript 初心者です。Zenn も。
console.log()など console メソッドのラッパ実装で以下の要件を全て満たしたく、既存の Web 記事をいろいろ参照して試行錯誤してみたけど完全な方法が見付からず挫折..
- ログ出力の有効／無効を切り替えられる（空関数に置換できる）
- 表示文字列を横取りして編集できる（行頭/行末に付加情報を付けたりスタイルを変えたり）
- 書式付き文字列も正しく表示する（%s,%o とか printf 仕様のやつ）
- ブラウザのコンソールに表示されるソースコード位置情報を維持する（ファイル名・行番号）
- ログ出力にソースコード位置情報を付加もできる（端末実行などで表示されない場合）
- 元の console メソッドはそのまま使える
bind が常套手段のようだけど...
恐らく、上記 4. を守るため、Function.bind を使って例えば以下のように書く[1]のが常套手段と思われる。
prefix = "[LOG]";
myconsole.log = console.log.bind(console, prefix);
呼出例は以下のようになる。
myconsole.log("hello, world.");
[LOG] hello, world.
ただし、bind の仕様による制約で、上記 2,3,4 に関して以下の問題が残る。
2x. 行頭にしか文字列を付加できない
3x. 書式付き文字列に変数が代入されず、そのまま表示されてしまう
4x. bind 時点で確定できる文字列しか付加できない（呼出元のファイル名とかは無理）
書式付き文字列の問題は、prefix 挿入のせいで console.log()に渡される引数位置が後ろにずれるからで、例えば以下のようになってしまう。
x = "beautiful";
myconsole.log("hello, %s world.", x);
[LOG] hello, %s world. x
通常は書式付き文字列が使えないのも許しがたいと思うので、結局は prefix もなしで bind するだけが現実解かもしれない。
ブラウザ表示のファイル名・行番号を犠牲にするなら
bind ではなく普通にラップ関数を作れば、自分でコールスタックを取って呼出元情報をログに付加できる。ブラウザ側でリンクをつついてソースコードを見ることがないなら、気持ち悪いけど実用上は問題ないかも?
function log_wrapper(...args) {
callerInfo = getCaller(); // throw new Error() してコールスタックからファイル名・行番号・関数名などを取る
newArgs = editArgs(callerInfo, ...args); // ログレベル・ファイル名・行番号・関数名を付加（argsを自由に編集）
console.log(...newArgs);
}
myconsole.log = log_wrapper.bind(console);
この形なら、例えば以下のような表示にできる。引数を横取りして自由に処理できるので書式付き文字列にも対応可。
x = "beautiful";
myconsole.log("hello, %s world.", x);
[LOG][file.js:57:testFunc] hello, beautiful world.
残念ながらブラウザ側で表示するファイル名・行番号は全てラップ関数（上記コード例では log_wrapper()）のところになってしまうけど、他の要件は全て叶えられそう。いまいち満足はできないけど..
console.log 自体をフックするのは恐い [3/22 追記]
既に console.log()を直接呼び出しているコードがたくさんある場合、console.log()自体をフックしたくなるかもしれない。
console_org = { log: console.log }; // 元のメソッドを保持
console.log = (...args) => log_wrapper(...args); // フックする
function log_wrapper(...args) {
// 前記コードと同じ部分は省略
console_org.log(...newArgs); // 元のメソッドを呼ぶ
}
のように書くとできる。実質は先程と同じラップ関数で、console.log()を横取りできるから既存コードを書き直さずに済む。呼出例はこうなる。
console.log("hello, world."); // console.log()をそのまま呼ぶ。省略するが書式付き文字列もOK。
[LOG][file.js:57:testFunc] hello, world.
でもこれは自分が書いてない console.log()にも全て影響するので、かなり恐い。例えば上記コードを一般化して他の console メソッドもフックしてみる。ここでは簡単のため log, warn, assert のみ考える。
for (key of ["log", "warn", "assert"]) {
console_org[key] = console[key];
console[key] = (...args) => log_wrapper(key, ...args);
}
function log_wrapper(key, ...args) {
// 前記コードと同じ部分は省略
console_org[key](...newArgs);
}
こうすると assert の第 2 引数以降に渡すメッセージ文字列もいじれるが[2]、node コマンドの端末実行では以下のような結果になった。
console.log("hello, world.");
console.assert(false, "something wrong!");
[LOG][file.js:57:testFunc] hello, world.
[WARN] Assertion failed: [ASSERT] somthing wrong!
editArgs()の中で何かバグってるかと思うが、どうやら console.assert()の内部で console.warn()が呼ばれているらしい[3]。この問題自体は log_wrapper()の実装で回避できるけど、なんだか汚いコードになるし、console.xxx()の再起呼出に対して漏れなく安全に動くのかどうか不安になる。どこで呼ばれているか分からない低レベルのメソッドを安直にフックするのは危ない。
そもそも必要なのかと言うと
自分が主に C/C++の組み込み系で育った人間だからこういうのが癖になっているだけかも。今どきは開発環境が優秀だから、なるべくならログよりもブラウザや vscode の機能でデバッグする方が賢い気もする。
とはいえ製品開発だと SQA 以降はログを頼りに調査するのが普通だし、開発中でも目の前で再現できない問題はログを見るしかない。特にリアルタイム系はデバッガで動かすと再現しない問題も多々ある。大規模になるほど大勢の人が毎日のようにログを読むから、ログの情報や可読性はかなり重要な気がする。 上の例みたいなファイル名と行番号はともかく、タイムスタンプは必須だし、モジュール名とか注目するログをフィルタするのに必要な情報は付けたい。
Web アプリは経験ないけど、たぶんそういう事情は同じなのでは？ それは console ではなく独自に出力されてるんですかね..。ブラウザのデベロッパツールとか気にせずに。
Web アプリ初心者すぎて単に基礎が分かってなかったらすみません。ご指摘歓迎いたします。
サンプルコード [3/25 追記]
一応動いているサンプルコードを貼っておきます。
EnableWrapper = true ならラップ関数（prefix 付加）、false なら console に bind するだけです。
getCallerInfo() は node, chrome で確認してますが環境依存かもしれません。
const EnableWrapper = true; // set false to just bind all methods to console, and browser's devtool can get caller information correctly
const log_prefix = ["error", "warn", "info", "log", "debug"]; // with prefix and caller info
const log_through = ["assert", "trace", "dir", "time", "timeEnd", "count", "countReset", "group", "groupEnd", "table", "clear"]; // fall through to corresponding console method
const log_all_keys = [...log_prefix, ...log_through];
const function_org = {};
function getCallerInfo(lineNo = 4) {
try {
throw new Error(lineNo);
} catch (err) {
const caller = err.stack.split("\n")?.at(Number(err.message));
const file = caller.indexOf("http:") >= 0 ? caller.match(/([^\/]+)\?/)?.at(1) : caller.match(/([^\\\()\/:]+)[:]\d+:\d+/)?.at(1);
const lineNo = caller.match(/:(\d+):\d+/)?.at(1);
const func = caller.match(/at (.+) \(/)?.at(1);
return { file, func, lineNo };
}
}
function editArgs(key, ...args) {
args = [...args];
const heads = [];
if (key === "assert") {
heads.push(args[0]); // expr
args = args.slice(1);
}
if (log_prefix.includes(key)) {
const caller = getCallerInfo();
//const prefix = `[${caller.file}:${caller.lineNo}:${caller.func}]`;
const prefix = `[${key.toUpperCase()}][${caller.file}:${caller.lineNo}:${caller.func}]`;
if (args.length >= 1 && typeof args[0] === "string" && args[0].includes("%")) {
heads.push(`${prefix} ${args[0]}`);
args = args.slice(1);
} else {
heads.push(prefix);
}
}
return [...heads, ...args];
}
function logWrapper(key, ...args) {
if (log_through.includes(key)) {
function_org[key](...args);
} else {
args = editArgs(key, ...args);
function_org[key](...args);
//console[key](...heads, ...args);
}
}
function makePrefix(key) {
let prefix = [];
if (log_prefix.includes(key)) {
prefix.push(`[${getCallerInfo().func}]`);
}
return prefix;
}
for (const key of log_all_keys) {
function_org[key] = console[key];
//console[key] = logWrapper.bind(console, key);
}
const log_methods = log_all_keys.reduce((methods, key) => {
methods[key] = EnableWrapper ? logWrapper.bind(console, key) : console[key].bind(console);
return methods;
}, {});
const debug_utils = { ...log_methods };
export default debug_utils;
import dbg from "@/utils/debug-utils.js";
function test_logs() {
dbg.time("time");
dbg.debug("Hello, %s", "world.");
dbg.info("Hello, %s", "world.");
dbg.log("Hello, %s", "world.");
dbg.warn("Hello, %s", "world.");
dbg.error("Hello, %s", "world.");
dbg.assert(false, "Hello, %s", "world.");
dbg.timeEnd("time");
}
test_logs();
Discussion