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<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 ()" ```

Author: joyeecheung

src/debug_utils.cc

@@ -303,7 +303,8 @@ std::string NativeSymbolDebuggingContext::SymbolInfo::Display() const{
 return oss.str();
 }
 
-voidDumpBacktrace(FILE* fp){
+voidDumpNativeBacktrace(FILE* fp){
+fprintf(fp, "----- Native stack trace -----\n\n");
 auto sym_ctx = NativeSymbolDebuggingContext::New();
 void* frames[256];
 constint size = sym_ctx->GetStackTrace(frames, arraysize(frames));
@@ -314,6 +315,31 @@ void DumpBacktrace(FILE* fp){
  }
 }
 
+static std::atomic<bool> is_dumping_js_stacktrace{false };
+voidDumpJavaScriptBacktrace(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);
+}
+
 voidCheckedUvLoopClose(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);
 }

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);

src/node_errors.cc

@@ -1,5 +1,6 @@
 #include<cerrno>
 #include<cstdarg>
+#include<sstream>
 
 #include"debug_utils-inl.h"
 #include"node_errors.h"
@@ -329,7 +330,8 @@ void AppendExceptionLine(Environment* env,
 }
 
 [[noreturn]] voidAbort(){
-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();
 }
 

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);
  };
 }

src/util.h

@@ -115,7 +115,8 @@ struct AssertionInfo{
 };
 [[noreturn]] void NODE_EXTERN_PRIVATE Assert(const AssertionInfo& info);
 [[noreturn]] void NODE_EXTERN_PRIVATE Abort();
-voidDumpBacktrace(FILE* fp);
+voidDumpNativeBacktrace(FILE* fp);
+voidDumpJavaScriptBacktrace(FILE* fp);
 
 // Windows 8+ does not like abort() in Release mode
 #ifdef _WIN32

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!==''){
-constframes=stderr.trimRight().split('\n').map((s)=>s.trim());
+constframes=common.getNativeStackTrace(stderr);
 
 if(!frames.every((frame,index)=>frame.startsWith(`${index+1}:`))){
 assert.fail(`Each frame should start with a frame number:\n${stderr}`);

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);
 });

test/abort/test-addon-uv-handle-leak.js

@@ -88,6 +88,9 @@ if (process.argv[2] === 'child'){
 
 while(lines.length>0){
 constline=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(/^uvloopat\[.+\]has\d+openhandlesintotal$/.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,/Assertionfailed:/);
 state='done';
 break;
 case'done':

test/common/index.js

@@ -906,6 +906,28 @@ function spawnPromisified(...args){
 });
 }
 
+functiongetNativeStackTrace(stderr){
+constlines=stderr.split('\n');
+constresult=[];
+letshouldRecord=false;
+for(constlineoflines){
+if(line.includes('Native stack trace')){
+shouldRecord=true;
+continue;
+}elseif(line.includes('JavaScript stack trace')){
+shouldRecord=false;
+break;
+}
+if(shouldRecord){
+consttrimmed=line.trim();
+if(trimmed.length>0){
+result.push(trimmed);
+}
+}
+}
+returnresult;
+}
+
 constcommon={
  allowGlobals,
  buildType,
@@ -919,6 +941,7 @@ const common ={
  getArrayBufferViews,
  getBufferSources,
  getCallSite,
+ getNativeStackTrace,
  getTTYfd,
  hasIntl,
  hasCrypto,