Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

errors: print JS stack in C++ assertions #50242

Merged
merged 1 commit into from
Nov 1, 2023
Merged

errors: print JS stack in C++ assertions #50242

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 23 additions & 2 deletions src/debug_utils.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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));
Expand All @@ -314,6 +318,22 @@ void DumpBacktrace(FILE* fp) {
}
}

void DumpJavaScriptBacktrace(FILE* fp) {
v8::Isolate* isolate = v8::Isolate::GetCurrent();
if (isolate == nullptr) {
return;
}

Local<StackTrace> 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;

Expand Down Expand Up @@ -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);
}
3 changes: 2 additions & 1 deletion src/env.cc
View file
Open in desktop
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
81 changes: 67 additions & 14 deletions src/node_errors.cc
View file
Open in desktop
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 All @@ -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;
Expand Down Expand Up @@ -185,23 +187,65 @@ static std::string GetErrorSource(Isolate* isolate,
return buf + std::string(underline_buf, off);
}

static std::string FormatStackTrace(Isolate* isolate, Local<StackTrace> stack) {
static std::atomic<bool> is_in_oom{false};
static std::atomic<bool> is_retrieving_js_stacktrace{false};
MaybeLocal<StackTrace> GetCurrentStackTrace(Isolate* isolate, int frame_count) {
if (isolate == nullptr) {
return MaybeLocal<StackTrace>();
}
// Generating JavaScript stack trace can result in V8 fatal error,
// which can re-enter this function.
if (is_retrieving_js_stacktrace.load()) {
return MaybeLocal<StackTrace>();
}

// 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<StackTrace>();
}

constexpr StackTrace::StackTraceOptions options =
static_cast<StackTrace::StackTraceOptions>(
StackTrace::kDetailed |
StackTrace::kExposeFramesAcrossSecurityOrigins);

is_retrieving_js_stacktrace.store(true);
EscapableHandleScope scope(isolate);
Local<StackTrace> stack =
StackTrace::CurrentStackTrace(isolate, frame_count, options);

is_retrieving_js_stacktrace.store(false);
if (stack->GetFrameCount() == 0) {
return MaybeLocal<StackTrace>();
}

return scope.Escape(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);
Expand All @@ -214,7 +258,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);
Expand All @@ -223,7 +268,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,
Expand All @@ -239,8 +285,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,
Expand Down Expand Up @@ -329,7 +377,8 @@ void AppendExceptionLine(Environment* env,
}

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

Expand Down Expand Up @@ -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";
Expand Down
12 changes: 11 additions & 1 deletion src/node_internals.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,7 +79,17 @@ void GetSockOrPeerName(const v8::FunctionCallbackInfo<v8::Value>& args) {
args.GetReturnValue().Set(err);
}

void PrintStackTrace(v8::Isolate* isolate, v8::Local<v8::StackTrace> stack);
constexpr int kMaxFrameCountForLogging = 10;
v8::MaybeLocal<v8::StackTrace> GetCurrentStackTrace(
v8::Isolate* isolate, int frame_count = kMaxFrameCountForLogging);

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);
Expand Down
2 changes: 1 addition & 1 deletion src/node_platform.cc
View file
Open in desktop
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
21 changes: 4 additions & 17 deletions src/node_report.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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<v8::StackTrace> stack;
if (!GetCurrentStackTrace(isolate, MAX_FRAME_COUNT).ToLocal(&stack)) {
PrintEmptyJavaScriptStack(writer);
return;
}

HandleScope scope(isolate);
RegisterState state;
state.pc = nullptr;
state.fp = &state;
Expand All @@ -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::StackTraceOptions>(
StackTrace::kDetailed |
StackTrace::kExposeFramesAcrossSecurityOrigins);
Local<StackTrace> 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++) {
Expand Down
3 changes: 2 additions & 1 deletion src/util.h
View file
Open in desktop
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
25 changes: 14 additions & 11 deletions test/abort/test-abort-backtrace.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)));
}
}
7 changes: 1 addition & 6 deletions test/abort/test-abort-fatal-error.js
View file
Open in desktop
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);
}
assert(common.nodeProcessAborted(err.code, err.signal));
});
11 changes: 9 additions & 2 deletions test/abort/test-addon-uv-handle-leak.js
View file
Open in desktop
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/);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@joyeecheung should this check be scoped only to linux ? Running this test on windows fails with

node:assert:1035
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The input did not match the regular expression /CheckedUvLoopClose/. Input:

'#  Windows PowerShell[6632]:  at C:\\Users\\demohan\\github\\node\\src\\debug_utils.cc:344'

    at Object.<anonymous> (C:\Users\demohan\github\node\test\abort\test-addon-uv-handle-leak.js:125:16)
    at Module._compile (node:internal/modules/cjs/loader:1376:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1435:10)
    at Module.load (node:internal/modules/cjs/loader:1207:32)
    at Module._load (node:internal/modules/cjs/loader:1023:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:135:12)
    at node:internal/main/run_main_module:28:49 {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: '#  Windows PowerShell[6632]:  at C:\\Users\\demohan\\github\\node\\src\\debug_utils.cc:344',
  expected: /CheckedUvLoopClose/,
  operator: 'match'
}

which is expected given lack of function name in

node/src/util.h

Line 165 in 8382da1

#define PRETTY_FUNCTION_NAME ""

Are the addon tests not run on windows CI ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe the abort tests are not run in the Windows CI because our test runner is written in python and it uses resource.RLIMIT_CORE to disable core file, which isn't available on Windows.

Copy link
Member Author

@joyeecheung joyeecheung May 24, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From a look of the docs, I am guessing we can use __FUNCSIG__ as a replacement on Windows https://learn.microsoft.com/en-us/cpp/preprocessor/predefined-macros?view=msvc-170 (or we can wait for the clangcl on Windows switch and it'll just work..)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the clarification!

state = 'assertion-failure';
break;
case 'assertion-failure':
assert.match(line, /Assertion .+ failed/);
assert.match(line, /Assertion failed:/);
state = 'done';
break;
case 'done':
Expand Down
Loading