src: 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 -----

1: [eval]:1:23
2: runScriptInThisContext (node:internal/vm:144:10)
3: node:internal/process/execution:109:14
4: [eval]-wrapper:6:24
5: runScript (node:internal/process/execution:92:62)
6: evalScript (node:internal/process/execution:123:10)
7: node:internal/main/eval_string:51:3

[1]    24856 abort      out/Release/node -p "process.binding('fs').open
()"
```

Author: joyeecheung

src/debug_utils.cc

@@ -59,6 +59,9 @@ namespace per_process {
 EnabledDebugList enabled_debug_list;
 }
 
+using v8::Local;
+using v8::StackTrace;
+
 void EnabledDebugList::Parse(std::shared_ptr<KVStore> env_vars,
                              v8::Isolate* isolate) {
   std::string cats;
@@ -303,7 +306,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 +318,33 @@ 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);
+  Local<StackTrace> stack =
+      StackTrace::CurrentStackTrace(isolate, 10, StackTrace::kDetailed);
+
+  fprintf(fp, "\n----- JavaScript stack trace -----\n\n");
+
+  PrintStackTrace(isolate, stack, StackTracePrefix::kNumber);
+  fprintf(fp, "\n");
+
+  is_dumping_js_stacktrace.store(false);
+}
+
 void CheckedUvLoopClose(uv_loop_t* loop) {
   if (uv_loop_close(loop) == 0) return;
 
@@ -514,5 +545,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"
@@ -185,23 +186,29 @@ static std::string GetErrorSource(Isolate* isolate,
   return buf + std::string(underline_buf, off);
 }
 
-static std::string FormatStackTrace(Isolate* isolate, Local<StackTrace> stack) {
+static std::string FormatStackTrace(
+    Isolate* isolate,
+    Local<StackTrace> stack,
+    StackTracePrefix prefix = StackTracePrefix::kAt) {
   std::string result;
   for (int i = 0; i < stack->GetFrameCount(); i++) {
     Local<StackFrame> stack_frame = stack->GetFrame(isolate, i);
     node::Utf8Value fn_name_s(isolate, stack_frame->GetFunctionName());
     node::Utf8Value script_name(isolate, stack_frame->GetScriptName());
     const int line_number = stack_frame->GetLineNumber();
     const int column = stack_frame->GetColumn();
-
+    std::string prefix_str = prefix == StackTracePrefix::kAt
+                                 ? "    at "
+                                 : std::to_string(i + 1) + ": ";
     if (stack_frame->IsEval()) {
       if (stack_frame->GetScriptId() == Message::kNoScriptIdInfo) {
-        result += SPrintF("    at [eval]:%i:%i\n", line_number, column);
+        result += SPrintF("%s[eval]:%i:%i\n", prefix_str, line_number, column);
       } else {
         std::vector<char> buf(script_name.length() + 64);
         snprintf(buf.data(),
                  buf.size(),
-                 "    at [eval] (%s:%i:%i)\n",
+                 "%s[eval] (%s:%i:%i)\n",
+                 prefix_str.c_str(),
                  *script_name,
                  line_number,
                  column);
@@ -214,7 +221,8 @@ static std::string FormatStackTrace(Isolate* isolate, Local<StackTrace> stack) {
       std::vector<char> buf(script_name.length() + 64);
       snprintf(buf.data(),
                buf.size(),
-               "    at %s:%i:%i\n",
+               "%s%s:%i:%i\n",
+               prefix_str.c_str(),
                *script_name,
                line_number,
                column);
@@ -223,7 +231,8 @@ static std::string FormatStackTrace(Isolate* isolate, Local<StackTrace> stack) {
       std::vector<char> buf(fn_name_s.length() + script_name.length() + 64);
       snprintf(buf.data(),
                buf.size(),
-               "    at %s (%s:%i:%i)\n",
+               "%s%s (%s:%i:%i)\n",
+               prefix_str.c_str(),
                *fn_name_s,
                *script_name,
                line_number,
@@ -239,8 +248,10 @@ static void PrintToStderrAndFlush(const std::string& str) {
   fflush(stderr);
 }
 
-void PrintStackTrace(Isolate* isolate, Local<StackTrace> stack) {
-  PrintToStderrAndFlush(FormatStackTrace(isolate, stack));
+void PrintStackTrace(Isolate* isolate,
+                     Local<StackTrace> stack,
+                     StackTracePrefix prefix) {
+  PrintToStderrAndFlush(FormatStackTrace(isolate, stack, prefix));
 }
 
 std::string FormatCaughtException(Isolate* isolate,
@@ -329,7 +340,8 @@ void AppendExceptionLine(Environment* env,
 }
 
 [[noreturn]] void Abort() {
-  DumpBacktrace(stderr);
+  DumpNativeBacktrace(stderr);
+  DumpJavaScriptBacktrace(stderr);
   fflush(stderr);
   ABORT_NO_BACKTRACE();
 }
@@ -338,14 +350,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_internals.h

@@ -79,7 +79,13 @@ void GetSockOrPeerName(const v8::FunctionCallbackInfo<v8::Value>& args) {
   args.GetReturnValue().Set(err);
 }
 
-void PrintStackTrace(v8::Isolate* isolate, v8::Local<v8::StackTrace> stack);
+enum class StackTracePrefix {
+  kAt,  // "    at "
+  kNumber
+};
+void PrintStackTrace(v8::Isolate* isolate,
+                     v8::Local<v8::StackTrace> stack,
+                     StackTracePrefix prefix = StackTracePrefix::kAt);
 void PrintCaughtException(v8::Isolate* isolate,
                           v8::Local<v8::Context> context,
                           const v8::TryCatch& try_catch);

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();
-void DumpBacktrace(FILE* fp);
+void DumpNativeBacktrace(FILE* fp);
+void DumpJavaScriptBacktrace(FILE* fp);
 
 // Windows 8+ does not like abort() in Release mode
 #ifdef _WIN32

test/abort/test-abort-backtrace.js

@@ -10,19 +10,22 @@ if (process.argv[2] === 'child') {
   const stderr = child.stderr.toString();
 
   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 { nativeStack, jsStack } = common.getPrintedStackTrace(stderr);
 
-    if (!frames.every((frame, index) => frame.startsWith(`${index + 1}:`))) {
-      assert.fail(`Each frame should start with a frame number:\n${stderr}`);
-    }
+  if (!nativeStack.every((frame, index) => frame.startsWith(`${index + 1}:`))) {
+    assert.fail(`Each frame should start with a frame number:\n${stderr}`);
+  }
 
-    if (!common.isWindows) {
-      const { getBinaryPath } = require('../common/shared-lib-util');
-      if (!frames.some((frame) => frame.includes(`[${getBinaryPath()}]`))) {
-        assert.fail(`Some frames should include the binary name:\n${stderr}`);
-      }
+  // For systems that don't support backtraces, the native stack is
+  // going to be empty.
+  if (!common.isWindows && nativeStack.length > 0) {
+    const { getBinaryPath } = require('../common/shared-lib-util');
+    if (!nativeStack.some((frame) => frame.includes(`[${getBinaryPath()}]`))) {
+      assert.fail(`Some native stack frame include the binary name:\n${stderr}`);
     }
   }
+
+  if (jsStack.length > 0) {
+    assert(jsStack.some((frame) => frame.includes(__filename)));
+  }
 }

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);
-  }
+  assert(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) {
     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':

test/common/index.js

@@ -906,6 +906,45 @@ function spawnPromisified(...args) {
   });
 }
 
+function getPrintedStackTrace(stderr) {
+  const lines = stderr.split('\n');
+
+  let state = 'initial';
+  const result = {
+    message: [],
+    nativeStack: [],
+    jsStack: [],
+  };
+  for (let i = 0; i < lines.length; ++i) {
+    const line = lines[i].trim();
+    if (line.length === 0) {
+      continue;  // Skip empty lines.
+    }
+
+    switch (state) {
+      case 'initial':
+        result.message.push(line);
+        if (line.includes('Native stack trace')) {
+          state = 'native-stack';
+        } else {
+          result.message.push(line);
+        }
+        break;
+      case 'native-stack':
+        if (line.includes('JavaScript stack trace')) {
+          state = 'js-stack';
+        } else {
+          result.nativeStack.push(line);
+        }
+        break;
+      case 'js-stack':
+        result.jsStack.push(line);
+        break;
+    }
+  }
+  return result;
+}
+
 const common = {
   allowGlobals,
   buildType,
@@ -919,6 +958,7 @@ const common = {
   getArrayBufferViews,
   getBufferSources,
   getCallSite,
+  getPrintedStackTrace,
   getTTYfd,
   hasIntl,
   hasCrypto,