diff --git a/src/debug_utils.cc b/src/debug_utils.cc index fadf321c3d925f..26f2a96831c137 100644 --- a/src/debug_utils.cc +++ b/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 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,22 @@ void DumpBacktrace(FILE* fp) { } } +void DumpJavaScriptBacktrace(FILE* fp) { + v8::Isolate* isolate = v8::Isolate::GetCurrent(); + if (isolate == nullptr) { + return; + } + + Local stack; + if (!GetCurrentStackTrace(isolate).ToLocal(&stack)) { + return; + } + + fprintf(fp, "\n----- JavaScript stack trace -----\n\n"); + PrintStackTrace(isolate, stack, StackTracePrefix::kNumber); + fprintf(fp, "\n"); +} + void CheckedUvLoopClose(uv_loop_t* loop) { if (uv_loop_close(loop) == 0) return; @@ -514,5 +534,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..9c4ebbe4502698 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" @@ -15,6 +16,7 @@ namespace node { using errors::TryCatchScope; using v8::Boolean; using v8::Context; +using v8::EscapableHandleScope; using v8::Exception; using v8::Function; using v8::FunctionCallbackInfo; @@ -185,7 +187,46 @@ static std::string GetErrorSource(Isolate* isolate, return buf + std::string(underline_buf, off); } -static std::string FormatStackTrace(Isolate* isolate, Local stack) { +static std::atomic is_in_oom{false}; +static std::atomic is_retrieving_js_stacktrace{false}; +MaybeLocal GetCurrentStackTrace(Isolate* isolate, int frame_count) { + if (isolate == nullptr) { + return MaybeLocal(); + } + // Generating JavaScript stack trace can result in V8 fatal error, + // which can re-enter this function. + if (is_retrieving_js_stacktrace.load()) { + return MaybeLocal(); + } + + // Can not capture the stacktrace when the isolate is in a OOM state or no + // context is entered. + if (is_in_oom.load() || !isolate->InContext()) { + return MaybeLocal(); + } + + constexpr StackTrace::StackTraceOptions options = + static_cast( + StackTrace::kDetailed | + StackTrace::kExposeFramesAcrossSecurityOrigins); + + is_retrieving_js_stacktrace.store(true); + EscapableHandleScope scope(isolate); + Local stack = + StackTrace::CurrentStackTrace(isolate, frame_count, options); + + is_retrieving_js_stacktrace.store(false); + if (stack->GetFrameCount() == 0) { + return MaybeLocal(); + } + + return scope.Escape(stack); +} + +static std::string FormatStackTrace( + Isolate* isolate, + Local stack, + StackTracePrefix prefix = StackTracePrefix::kAt) { std::string result; for (int i = 0; i < stack->GetFrameCount(); i++) { Local stack_frame = stack->GetFrame(isolate, i); @@ -193,15 +234,18 @@ static std::string FormatStackTrace(Isolate* isolate, Local stack) { 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 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 +258,8 @@ static std::string FormatStackTrace(Isolate* isolate, Local stack) { std::vector 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 +268,8 @@ static std::string FormatStackTrace(Isolate* isolate, Local stack) { std::vector 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 +285,10 @@ static void PrintToStderrAndFlush(const std::string& str) { fflush(stderr); } -void PrintStackTrace(Isolate* isolate, Local stack) { - PrintToStderrAndFlush(FormatStackTrace(isolate, stack)); +void PrintStackTrace(Isolate* isolate, + Local stack, + StackTracePrefix prefix) { + PrintToStderrAndFlush(FormatStackTrace(isolate, stack, prefix)); } std::string FormatCaughtException(Isolate* isolate, @@ -329,7 +377,8 @@ void AppendExceptionLine(Environment* env, } [[noreturn]] void Abort() { - DumpBacktrace(stderr); + DumpNativeBacktrace(stderr); + DumpJavaScriptBacktrace(stderr); fflush(stderr); ABORT_NO_BACKTRACE(); } @@ -338,14 +387,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(); } @@ -528,6 +578,9 @@ static void ReportFatalException(Environment* env, [[noreturn]] void OOMErrorHandler(const char* location, const v8::OOMDetails& details) { + // We should never recover from this handler so once it's true it's always + // true. + is_in_oom.store(true); const char* message = details.is_heap_oom ? "Allocation failed - JavaScript heap out of memory" : "Allocation failed - process out of memory"; diff --git a/src/node_internals.h b/src/node_internals.h index d7f78664615fcf..9a96e042fc5cda 100644 --- a/src/node_internals.h +++ b/src/node_internals.h @@ -79,7 +79,17 @@ void GetSockOrPeerName(const v8::FunctionCallbackInfo& args) { args.GetReturnValue().Set(err); } -void PrintStackTrace(v8::Isolate* isolate, v8::Local stack); +constexpr int kMaxFrameCountForLogging = 10; +v8::MaybeLocal GetCurrentStackTrace( + v8::Isolate* isolate, int frame_count = kMaxFrameCountForLogging); + +enum class StackTracePrefix { + kAt, // " at " + kNumber +}; +void PrintStackTrace(v8::Isolate* isolate, + v8::Local stack, + StackTracePrefix prefix = StackTracePrefix::kAt); void PrintCaughtException(v8::Isolate* isolate, v8::Local context, const v8::TryCatch& try_catch); 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/node_report.cc b/src/node_report.cc index 88c9a97789e30b..54121cb6b48210 100644 --- a/src/node_report.cc +++ b/src/node_report.cc @@ -27,7 +27,7 @@ constexpr int NODE_REPORT_VERSION = 3; constexpr int NANOS_PER_SEC = 1000 * 1000 * 1000; constexpr double SEC_PER_MICROS = 1e-6; -constexpr int MAX_FRAME_COUNT = 10; +constexpr int MAX_FRAME_COUNT = node::kMaxFrameCountForLogging; namespace node { using node::worker::Worker; @@ -458,14 +458,13 @@ static void PrintEmptyJavaScriptStack(JSONWriter* writer) { static void PrintJavaScriptStack(JSONWriter* writer, Isolate* isolate, const char* trigger) { - // Can not capture the stacktrace when the isolate is in a OOM state or no - // context is entered. - if (!strcmp(trigger, "OOMError") || !isolate->InContext()) { + HandleScope scope(isolate); + Local stack; + if (!GetCurrentStackTrace(isolate, MAX_FRAME_COUNT).ToLocal(&stack)) { PrintEmptyJavaScriptStack(writer); return; } - HandleScope scope(isolate); RegisterState state; state.pc = nullptr; state.fp = &state; @@ -476,18 +475,6 @@ static void PrintJavaScriptStack(JSONWriter* writer, void* samples[MAX_FRAME_COUNT]; isolate->GetStackSample(state, samples, MAX_FRAME_COUNT, &info); - constexpr StackTrace::StackTraceOptions stack_trace_options = - static_cast( - StackTrace::kDetailed | - StackTrace::kExposeFramesAcrossSecurityOrigins); - Local stack = StackTrace::CurrentStackTrace( - isolate, MAX_FRAME_COUNT, stack_trace_options); - - if (stack->GetFrameCount() == 0) { - PrintEmptyJavaScriptStack(writer); - return; - } - writer->json_keyvalue("message", trigger); writer->json_arraystart("stack"); for (int i = 0; i < stack->GetFrameCount(); i++) { 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..ce9ed39196eb1f 100644 --- a/test/abort/test-abort-backtrace.js +++ b/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))); + } } diff --git a/test/abort/test-abort-fatal-error.js b/test/abort/test-abort-fatal-error.js index b723b5b920849b..6c197ceb028540 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); - } + assert(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 52ac054c8c3f9a..1ebc040eca0610 100644 --- a/test/common/index.js +++ b/test/common/index.js @@ -898,6 +898,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, @@ -911,6 +950,7 @@ const common = { getArrayBufferViews, getBufferSources, getCallSite, + getPrintedStackTrace, getTTYfd, hasIntl, hasCrypto, diff --git a/test/js-native-api/test_finalizer/test_fatal_finalize.js b/test/js-native-api/test_finalizer/test_fatal_finalize.js index 352310128a97f6..a100eb220024da 100644 --- a/test/js-native-api/test_finalizer/test_fatal_finalize.js +++ b/test/js-native-api/test_finalizer/test_fatal_finalize.js @@ -27,5 +27,5 @@ const { spawnSync } = require('child_process'); const child = spawnSync(process.execPath, [ '--expose-gc', __filename, 'child', ]); -assert.strictEqual(child.signal, common.isWindows ? null : 'SIGABRT'); +assert(common.nodeProcessAborted(child.status, child.signal)); assert.match(child.stderr.toString(), /Finalizer is calling a function that may affect GC state/); diff --git a/test/node-api/test_fatal/test_threads.js b/test/node-api/test_fatal/test_threads.js index 8c306694f5e259..4a4f867613a3b5 100644 --- a/test/node-api/test_fatal/test_threads.js +++ b/test/node-api/test_fatal/test_threads.js @@ -18,4 +18,4 @@ const p = child_process.spawnSync( assert.ifError(p.error); assert.ok(p.stderr.toString().includes( 'FATAL ERROR: work_thread foobar')); -assert.ok(p.status === 134 || p.signal === 'SIGABRT'); +assert(common.nodeProcessAborted(p.status, p.signal));