From adbd19478f7362fc49916fbf01200c2d64777d49 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Tue, 10 Oct 2023 02:03:26 +0200 Subject: [PATCH] errors: print more information in C++ assertions This patch: - Indent the assertion message so that is separated from the native stack trace for redability - Print the JS stack trace when it's available Previoiusly the abort message looks like this: ``` out/Release/node[24458]: ../../src/node_file.cc:2008:void node::fs::Ope n(const FunctionCallbackInfo &): Assertion `(argc) >= (3)' f ailed. 1: 0x1043fb9a4 node::Abort() [node] 2: 0x1043fb6e4 node::PrintCaughtException(v8::Isolate*, v8::Local, v8::TryCatch const&) [node] 3: 0x104407708 node::fs::Open(v8::FunctionCallbackInfo cons t&) [node] 4: 0x104611e74 v8::internal::MaybeHandle v8::int ernal::(anonymous namespace)::HandleApiCallHelper(v8::internal:: Isolate*, v8::internal::Handle, v8::internal::Handle, v8::intern al::Handle, unsigned long*, int) [node ] 5: 0x1046116c8 v8::internal::Builtin_HandleApiCall(int, unsigned long* , v8::internal::Isolate*) [node] 6: 0x104e9cb24 Builtins_CEntry_Return1_ArgvOnStack_BuiltinExit [node] 7: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 8: 0x104e1250c Builtins_JSEntryTrampoline [node] 9: 0x104e121f4 Builtins_JSEntry [node] 10: 0x1046ed54c v8::internal::(anonymous namespace)::Invoke(v8::interna l::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [node] 11: 0x1046edb60 v8::internal::Execution::CallScript(v8::internal::Isola te*, v8::internal::Handle, v8::internal::Hand le, v8::internal::Handle) [node] 12: 0x1045a9fa0 v8::Script::Run(v8::Local, v8::Local) [node] 13: 0x1043efb68 node::contextify::ContextifyScript::EvalMachine(v8::Loc al, node::Environment*, long long, bool, bool, bool, v8::M icrotaskQueue*, v8::FunctionCallbackInfo const&) [node ] 14: 0x1043ef3e0 node::contextify::ContextifyScript::RunInContext(v8::Fu nctionCallbackInfo const&) [node] 15: 0x104611e74 v8::internal::MaybeHandle v8::int ernal::(anonymous namespace)::HandleApiCallHelper(v8::internal:: Isolate*, v8::internal::Handle , v8::internal::Handle, v8::interna l::Handle, unsigned long*, int) [node ] 16: 0x1046116c8 v8::internal::Builtin_HandleApiCall(int, unsigned long* , v8::internal::Isolate*) [node] 17: 0x104e9cb24 Builtins_CEntry_Return1_ArgvOnStack_BuiltinExit [node] 18: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 19: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 20: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 21: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 22: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 23: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 24: 0x104e143e4 Builtins_InterpreterEntryTrampoline [node] 25: 0x104e1250c Builtins_JSEntryTrampoline [node] 26: 0x104e121f4 Builtins_JSEntry [node] 27: 0x1046ed54c v8::internal::(anonymous namespace)::Invoke(v8::interna l::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [node] 28: 0x1046ecdc8 v8::internal::Execution::Call(v8::internal::Isolate*, v 8::internal::Handle, v8::internal::Handle, int, v8::internal::Handle*) [node] 29: 0x1045be23c v8::Function::Call(v8::Local, v8::Local, int, v8::Local*) [node] 30: 0x1043df704 node::builtins::BuiltinLoader::CompileAndCall(v8::Local , char const*, node::Realm*) [node] 31: 0x10446f2d4 node::Realm::ExecuteBootstrapper(char const*) [node] 32: 0x1043c3378 node::StartExecution(node::Environment*, std::__1::func tion (node::StartExecutionCallbackInfo const& )>) [node] 33: 0x10432dc28 node::LoadEnvironment(node::Environment*, std::__1::fun ction (node::StartExecutionCallbackInfo const &)>) [node] 34: 0x10443d1f4 node::NodeMainInstance::Run(node::ExitCode*, node::Envi ronment*) [node] 35: 0x10443cfd0 node::NodeMainInstance::Run() [node] 36: 0x1043c5d18 node::Start(int, char**) [node] 37: 0x19a027f28 start [/usr/lib/dyld] [1] 24458 abort out/Release/node -p "process.binding('fs').open ()" ``` Now it looks like this: ``` # out/Release/node[24856]: void node::fs::Open(const FunctionCallbac kInfo &) at ../../src/node_file.cc:2008 # Assertion failed: (argc) >= (3) ----- Native stack trace ----- 1: 0x1001efe64 node::Abort() [node] 2: 0x1001efba4 node::PrintCaughtException(v8::Isolate*, v8::Local, v8::TryCatch const&) [node] 3: 0x1001fb868 node::fs::Open(v8::FunctionCallbackInfo cons t&) [node] 4: 0x100405fd4 v8::internal::MaybeHandle v8::int ernal::(anonymous namespace)::HandleApiCallHelper(v8::internal:: Isolate*, v8::internal::Handle, v8::internal::Handle, v8::intern al::Handle, unsigned long*, int) [node ] 5: 0x100405828 v8::internal::Builtin_HandleApiCall(int, unsigned long* , v8::internal::Isolate*) [node] 6: 0x100c90b24 Builtins_CEntry_Return1_ArgvOnStack_BuiltinExit [node] 7: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 8: 0x100c0650c Builtins_JSEntryTrampoline [node] 9: 0x100c061f4 Builtins_JSEntry [node] 10: 0x1004e16ac v8::internal::(anonymous namespace)::Invoke(v8::interna l::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [node] 11: 0x1004e1cc0 v8::internal::Execution::CallScript(v8::internal::Isola te*, v8::internal::Handle, v8::internal::Hand le, v8::internal::Handle) [node] 12: 0x10039e100 v8::Script::Run(v8::Local, v8::Local) [node] 13: 0x1001e4028 node::contextify::ContextifyScript::EvalMachine(v8::Loc al, node::Environment*, long long, bool, bool, bool, v8::M icrotaskQueue*, v8::FunctionCallbackInfo const&) [node ] 14: 0x1001e38a0 node::contextify::ContextifyScript::RunInContext(v8::Fu nctionCallbackInfo const&) [node] 15: 0x100405fd4 v8::internal::MaybeHandle v8::int ernal::(anonymous namespace)::HandleApiCallHelper(v8::internal:: Isolate*, v8::internal::Handle , v8::internal::Handle, v8::interna l::Handle, unsigned long*, int) [node ] 16: 0x100405828 v8::internal::Builtin_HandleApiCall(int, unsigned long* , v8::internal::Isolate*) [node] 17: 0x100c90b24 Builtins_CEntry_Return1_ArgvOnStack_BuiltinExit [node] 18: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 19: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 20: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 21: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 22: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 23: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 24: 0x100c083e4 Builtins_InterpreterEntryTrampoline [node] 25: 0x100c0650c Builtins_JSEntryTrampoline [node] 26: 0x100c061f4 Builtins_JSEntry [node] 27: 0x1004e16ac v8::internal::(anonymous namespace)::Invoke(v8::interna l::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [node] 28: 0x1004e0f28 v8::internal::Execution::Call(v8::internal::Isolate*, v 8::internal::Handle, v8::internal::Handle, int, v8::internal::Handle*) [node] 29: 0x1003b239c v8::Function::Call(v8::Local, v8::Local, int, v8::Local*) [node] 30: 0x1001d3bc4 node::builtins::BuiltinLoader::CompileAndCall(v8::Local , char const*, node::Realm*) [node] 31: 0x100263434 node::Realm::ExecuteBootstrapper(char const*) [node] 32: 0x1001b7838 node::StartExecution(node::Environment*, std::__1::func tion (node::StartExecutionCallbackInfo const& )>) [node] 33: 0x100121c28 node::LoadEnvironment(node::Environment*, std::__1::fun ction (node::StartExecutionCallbackInfo const &)>) [node] 34: 0x100231354 node::NodeMainInstance::Run(node::ExitCode*, node::Envi ronment*) [node] 35: 0x100231130 node::NodeMainInstance::Run() [node] 36: 0x1001ba1d8 node::Start(int, char**) [node] 37: 0x19a027f28 start [/usr/lib/dyld] ----- JavaScript stack trace ----- [eval]:1:23 Script.runInThisContext (node:vm:127:12) Object.runInThisContext (node:vm:301:38) node:internal/process/execution:83:21 [eval]-wrapper:6:24 runScript (node:internal/process/execution:82:62) evalScript (node:internal/process/execution:104:10) node:internal/main/eval_string:51:3 [1] 24856 abort out/Release/node -p "process.binding('fs').open ()" ``` --- src/debug_utils.cc | 31 +++++++++++++++++++++++-- src/env.cc | 3 ++- src/node_errors.cc | 15 +++++++----- src/node_platform.cc | 2 +- src/util.h | 3 ++- test/abort/test-abort-backtrace.js | 2 +- test/abort/test-abort-fatal-error.js | 7 +----- test/abort/test-addon-uv-handle-leak.js | 11 +++++++-- test/common/index.js | 23 ++++++++++++++++++ 9 files changed, 77 insertions(+), 20 deletions(-) diff --git a/src/debug_utils.cc b/src/debug_utils.cc index fadf321c3d925f..2f0eba2ce203f7 100644 --- a/src/debug_utils.cc +++ b/src/debug_utils.cc @@ -303,7 +303,8 @@ std::string NativeSymbolDebuggingContext::SymbolInfo::Display() const { return oss.str(); } -void DumpBacktrace(FILE* fp) { +void DumpNativeBacktrace(FILE* fp) { + fprintf(fp, "----- Native stack trace -----\n\n"); auto sym_ctx = NativeSymbolDebuggingContext::New(); void* frames[256]; const int size = sym_ctx->GetStackTrace(frames, arraysize(frames)); @@ -314,6 +315,31 @@ void DumpBacktrace(FILE* fp) { } } +static std::atomic is_dumping_js_stacktrace { false }; +void DumpJavaScriptBacktrace(FILE* fp) { + // Printing JavaScript stack trace can result in V8 fatal error, + // which can re-enter this function. + if (is_dumping_js_stacktrace.load()) { + return; + } + + v8::Isolate* isolate = v8::Isolate::GetCurrent(); + if (isolate == nullptr) { + return; + } + + std::string js_stack; + std::stringstream ss; + is_dumping_js_stacktrace.store(true); + v8::Message::PrintCurrentStackTrace(isolate, ss); + js_stack = ss.str(); + fprintf(fp, + "\n----- JavaScript stack trace -----\n\n" + "%s\n\n", + js_stack.c_str()); + is_dumping_js_stacktrace.store(false); +} + void CheckedUvLoopClose(uv_loop_t* loop) { if (uv_loop_close(loop) == 0) return; @@ -514,5 +540,6 @@ void FWrite(FILE* file, const std::string& str) { } // namespace node extern "C" void __DumpBacktrace(FILE* fp) { - node::DumpBacktrace(fp); + node::DumpNativeBacktrace(fp); + node::DumpJavaScriptBacktrace(fp); } diff --git a/src/env.cc b/src/env.cc index 1d8df40c3446ac..4a25309449c8c7 100644 --- a/src/env.cc +++ b/src/env.cc @@ -1662,7 +1662,8 @@ void AsyncHooks::FailWithCorruptedAsyncStack(double expected_async_id) { "actual: %.f, expected: %.f)\n", async_id_fields_.GetValue(kExecutionAsyncId), expected_async_id); - DumpBacktrace(stderr); + DumpNativeBacktrace(stderr); + DumpJavaScriptBacktrace(stderr); fflush(stderr); // TODO(joyeecheung): should this exit code be more specific? if (!env()->abort_on_uncaught_exception()) Exit(ExitCode::kGenericUserError); diff --git a/src/node_errors.cc b/src/node_errors.cc index fe74717d00e140..d22721c74dff00 100644 --- a/src/node_errors.cc +++ b/src/node_errors.cc @@ -1,5 +1,6 @@ #include #include +#include #include "debug_utils-inl.h" #include "node_errors.h" @@ -329,7 +330,8 @@ void AppendExceptionLine(Environment* env, } [[noreturn]] void Abort() { - DumpBacktrace(stderr); + DumpNativeBacktrace(stderr); + DumpJavaScriptBacktrace(stderr); fflush(stderr); ABORT_NO_BACKTRACE(); } @@ -338,14 +340,15 @@ void AppendExceptionLine(Environment* env, std::string name = GetHumanReadableProcessName(); fprintf(stderr, - "%s: %s:%s%s Assertion `%s' failed.\n", + "\n" + " # %s: %s at %s\n" + " # Assertion failed: %s\n\n", name.c_str(), - info.file_line, - info.function, - *info.function ? ":" : "", + info.function ? info.function : "(unknown function)", + info.file_line ? info.file_line : "(unknown source location)", info.message); - fflush(stderr); + fflush(stderr); Abort(); } diff --git a/src/node_platform.cc b/src/node_platform.cc index 74ab4a3df8f09b..927fdddb8d9a1a 100644 --- a/src/node_platform.cc +++ b/src/node_platform.cc @@ -560,7 +560,7 @@ v8::TracingController* NodePlatform::GetTracingController() { Platform::StackTracePrinter NodePlatform::GetStackTracePrinter() { return []() { fprintf(stderr, "\n"); - DumpBacktrace(stderr); + DumpNativeBacktrace(stderr); fflush(stderr); }; } diff --git a/src/util.h b/src/util.h index 344f7753dab2b1..5340182423681e 100644 --- a/src/util.h +++ b/src/util.h @@ -115,7 +115,8 @@ struct AssertionInfo { }; [[noreturn]] void NODE_EXTERN_PRIVATE Assert(const AssertionInfo& info); [[noreturn]] void NODE_EXTERN_PRIVATE Abort(); -void DumpBacktrace(FILE* fp); +void DumpNativeBacktrace(FILE* fp); +void DumpJavaScriptBacktrace(FILE* fp); // Windows 8+ does not like abort() in Release mode #ifdef _WIN32 diff --git a/test/abort/test-abort-backtrace.js b/test/abort/test-abort-backtrace.js index b609ec7e4e6a7a..bda1c4151a4e6a 100644 --- a/test/abort/test-abort-backtrace.js +++ b/test/abort/test-abort-backtrace.js @@ -12,7 +12,7 @@ if (process.argv[2] === 'child') { assert.strictEqual(child.stdout.toString(), ''); // Stderr will be empty for systems that don't support backtraces. if (stderr !== '') { - const frames = stderr.trimRight().split('\n').map((s) => s.trim()); + const frames = common.getNativeStackTrace(stderr); if (!frames.every((frame, index) => frame.startsWith(`${index + 1}:`))) { assert.fail(`Each frame should start with a frame number:\n${stderr}`); diff --git a/test/abort/test-abort-fatal-error.js b/test/abort/test-abort-fatal-error.js index b723b5b920849b..e1c1e38e07ffa3 100644 --- a/test/abort/test-abort-fatal-error.js +++ b/test/abort/test-abort-fatal-error.js @@ -38,10 +38,5 @@ exec(cmdline, function(err, stdout, stderr) { assert(false, 'this test should fail'); } - if (err.code !== 134 && err.signal !== 'SIGABRT') { - console.log(stdout); - console.log(stderr); - console.log(err); - assert(false, err); - } + common.nodeProcessAborted(err.code, err.signal); }); diff --git a/test/abort/test-addon-uv-handle-leak.js b/test/abort/test-addon-uv-handle-leak.js index d2c4f8e646f457..dad245ad61bbb2 100644 --- a/test/abort/test-addon-uv-handle-leak.js +++ b/test/abort/test-addon-uv-handle-leak.js @@ -88,6 +88,9 @@ if (process.argv[2] === 'child') { while (lines.length > 0) { const line = lines.shift().trim(); + if (line.length === 0) { + continue; // Skip empty lines. + } switch (state) { case 'initial': @@ -96,7 +99,7 @@ if (process.argv[2] === 'child') { break; case 'handle-start': if (/^uv loop at \[.+\] has \d+ open handles in total$/.test(line)) { - state = 'assertion-failure'; + state = 'source-line'; break; } assert.match(line, /^\[.+\] timer( \(active\))?$/); @@ -116,8 +119,12 @@ if (process.argv[2] === 'child') { } state = 'handle-start'; break; + case 'source-line': + assert.match(line, /CheckedUvLoopClose/); + state = 'assertion-failure'; + break; case 'assertion-failure': - assert.match(line, /Assertion .+ failed/); + assert.match(line, /Assertion failed:/); state = 'done'; break; case 'done': diff --git a/test/common/index.js b/test/common/index.js index 6345a636a0f805..2872739fab7c42 100644 --- a/test/common/index.js +++ b/test/common/index.js @@ -906,6 +906,28 @@ function spawnPromisified(...args) { }); } +function getNativeStackTrace(stderr) { + const lines = stderr.split('\n'); + const result = []; + let shouldRecord = false; + for (const line of lines) { + if (line.includes('Native stack trace')) { + shouldRecord = true; + continue; + } else if (line.includes('JavaScript stack trace')) { + shouldRecord = false; + break; + } + if (shouldRecord) { + const trimmed = line.trim(); + if (trimmed.length > 0) { + result.push(trimmed); + } + } + } + return result; +} + const common = { allowGlobals, buildType, @@ -919,6 +941,7 @@ const common = { getArrayBufferViews, getBufferSources, getCallSite, + getNativeStackTrace, getTTYfd, hasIntl, hasCrypto,