Skip to content

Commit

Permalink
errors: print more information in C++ assertions
Browse files Browse the repository at this point in the history
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<v8::Value> &): Assertion `(argc) >= (3)' f
ailed.
 1: 0x1043fb9a4 node::Abort() [node]
 2: 0x1043fb6e4 node::PrintCaughtException(v8::Isolate*, v8::Local<v8::
Context>, v8::TryCatch const&) [node]
 3: 0x104407708 node::fs::Open(v8::FunctionCallbackInfo<v8::Value> cons
t&) [node]
 4: 0x104611e74 v8::internal::MaybeHandle<v8::internal::Object> v8::int
ernal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::
Isolate*, v8::internal::Handle<v8::internal::HeapObject
>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::intern
al::Handle<v8::internal::Object>, 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::JSFunction>, v8::internal::Hand
le<v8::internal::Object>, v8::internal::Handle<v8::in
ternal::Object>) [node]
12: 0x1045a9fa0 v8::Script::Run(v8::Local<v8::Context>, v8::Local<v8::D
ata>) [node]
13: 0x1043efb68 node::contextify::ContextifyScript::EvalMachine(v8::Loc
al<v8::Context>, node::Environment*, long long, bool, bool, bool, v8::M
icrotaskQueue*, v8::FunctionCallbackInfo<v8::Value> const&) [node
]
14: 0x1043ef3e0 node::contextify::ContextifyScript::RunInContext(v8::Fu
nctionCallbackInfo<v8::Value> const&) [node]
15: 0x104611e74 v8::internal::MaybeHandle<v8::internal::Object> v8::int
ernal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::
Isolate*, v8::internal::Handle<v8::internal::HeapObject>
, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::interna
l::Handle<v8::internal::Object>, 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::Object>, v8::internal::Handle<v8::int
ernal::Object>, int, v8::internal::Handle<v
8::internal::Object>*) [node]
29: 0x1045be23c v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8
::Value>, int, v8::Local<v8::Value>*) [node]
30: 0x1043df704 node::builtins::BuiltinLoader::CompileAndCall(v8::Local
<v8::Context>, char const*, node::Realm*) [node]
31: 0x10446f2d4 node::Realm::ExecuteBootstrapper(char const*) [node]
32: 0x1043c3378 node::StartExecution(node::Environment*, std::__1::func
tion<v8::MaybeLocal<v8::Value> (node::StartExecutionCallbackInfo const&
)>) [node]
33: 0x10432dc28 node::LoadEnvironment(node::Environment*, std::__1::fun
ction<v8::MaybeLocal<v8::Value> (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<v8::Value> &) 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::
Context>, v8::TryCatch const&) [node]
 3: 0x1001fb868 node::fs::Open(v8::FunctionCallbackInfo<v8::Value> cons
t&) [node]
 4: 0x100405fd4 v8::internal::MaybeHandle<v8::internal::Object> v8::int
ernal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::
Isolate*, v8::internal::Handle<v8::internal::HeapObject
>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::intern
al::Handle<v8::internal::Object>, 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::JSFunction>, v8::internal::Hand
le<v8::internal::Object>, v8::internal::Handle<v8::in
ternal::Object>) [node]
12: 0x10039e100 v8::Script::Run(v8::Local<v8::Context>, v8::Local<v8::D
ata>) [node]
13: 0x1001e4028 node::contextify::ContextifyScript::EvalMachine(v8::Loc
al<v8::Context>, node::Environment*, long long, bool, bool, bool, v8::M
icrotaskQueue*, v8::FunctionCallbackInfo<v8::Value> const&) [node
]
14: 0x1001e38a0 node::contextify::ContextifyScript::RunInContext(v8::Fu
nctionCallbackInfo<v8::Value> const&) [node]
15: 0x100405fd4 v8::internal::MaybeHandle<v8::internal::Object> v8::int
ernal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::
Isolate*, v8::internal::Handle<v8::internal::HeapObject>
, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::interna
l::Handle<v8::internal::Object>, 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::Object>, v8::internal::Handle<v8::int
ernal::Object>, int, v8::internal::Handle<v
8::internal::Object>*) [node]
29: 0x1003b239c v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8
::Value>, int, v8::Local<v8::Value>*) [node]
30: 0x1001d3bc4 node::builtins::BuiltinLoader::CompileAndCall(v8::Local
<v8::Context>, char const*, node::Realm*) [node]
31: 0x100263434 node::Realm::ExecuteBootstrapper(char const*) [node]
32: 0x1001b7838 node::StartExecution(node::Environment*, std::__1::func
tion<v8::MaybeLocal<v8::Value> (node::StartExecutionCallbackInfo const&
)>) [node]
33: 0x100121c28 node::LoadEnvironment(node::Environment*, std::__1::fun
ction<v8::MaybeLocal<v8::Value> (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
()"
```
  • Loading branch information
joyeecheung committed Oct 18, 2023
1 parent f971106 commit adbd194
Show file tree
Hide file tree
Showing 9 changed files with 77 additions and 20 deletions.
31 changes: 29 additions & 2 deletions src/debug_utils.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand All @@ -314,6 +315,31 @@ void DumpBacktrace(FILE* fp) {
}
}

static std::atomic<bool> 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;

Expand Down Expand Up @@ -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);
}
3 changes: 2 additions & 1 deletion src/env.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
15 changes: 9 additions & 6 deletions src/node_errors.cc
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
#include <cerrno>
#include <cstdarg>
#include <sstream>

#include "debug_utils-inl.h"
#include "node_errors.h"
Expand Down Expand Up @@ -329,7 +330,8 @@ void AppendExceptionLine(Environment* env,
}

[[noreturn]] void Abort() {
DumpBacktrace(stderr);
DumpNativeBacktrace(stderr);
DumpJavaScriptBacktrace(stderr);
fflush(stderr);
ABORT_NO_BACKTRACE();
}
Expand All @@ -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();
}

Expand Down
2 changes: 1 addition & 1 deletion src/node_platform.cc
Original file line number Diff line number Diff line change
Expand Up @@ -560,7 +560,7 @@ v8::TracingController* NodePlatform::GetTracingController() {
Platform::StackTracePrinter NodePlatform::GetStackTracePrinter() {
return []() {
fprintf(stderr, "\n");
DumpBacktrace(stderr);
DumpNativeBacktrace(stderr);
fflush(stderr);
};
}
Expand Down
3 changes: 2 additions & 1 deletion src/util.h
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion test/abort/test-abort-backtrace.js
Original file line number Diff line number Diff line change
Expand Up @@ -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}`);
Expand Down
7 changes: 1 addition & 6 deletions test/abort/test-abort-fatal-error.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
11 changes: 9 additions & 2 deletions test/abort/test-addon-uv-handle-leak.js
Original file line number Diff line number Diff line change
Expand Up @@ -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':
Expand All @@ -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\))?$/);
Expand All @@ -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':
Expand Down
23 changes: 23 additions & 0 deletions test/common/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -919,6 +941,7 @@ const common = {
getArrayBufferViews,
getBufferSources,
getCallSite,
getNativeStackTrace,
getTTYfd,
hasIntl,
hasCrypto,
Expand Down

0 comments on commit adbd194

Please sign in to comment.