Skip to content

Commit

Permalink
worker,src: display remaining handles if uv_loop_close fails
Browse files Browse the repository at this point in the history
Right now, we crash the process if there are handles remaining
on the event loop when we exit (except for the main thread).

This does not provide a lot of information about causes, though;
in particular, we don’t show which handles are pending and
who own them.

This patch adds debug output to these cases to help with the
situation.

PR-URL: #21238
Reviewed-By: Tiancheng "Timothy" Gu <timothygu99@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Gus Caplan <me@gus.host>
Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
  • Loading branch information
addaleax authored and targos committed Jun 13, 2018
1 parent aa468ab commit 4a54ebc
Show file tree
Hide file tree
Showing 11 changed files with 262 additions and 15 deletions.
59 changes: 52 additions & 7 deletions src/debug_utils.cc
Original file line number Diff line number Diff line change
Expand Up @@ -97,11 +97,11 @@ class Win32SymbolDebuggingContext final : public NativeSymbolDebuggingContext {
public:
Win32SymbolDebuggingContext() {
current_process_ = GetCurrentProcess();
USE(SymInitialize(process, nullptr, true));
USE(SymInitialize(current_process_, nullptr, true));
}

~Win32SymbolDebuggingContext() {
USE(SymCleanup(process));
USE(SymCleanup(current_process_));
}

SymbolInfo LookupSymbol(void* address) override {
Expand All @@ -114,16 +114,16 @@ class Win32SymbolDebuggingContext final : public NativeSymbolDebuggingContext {
info->SizeOfStruct = sizeof(SYMBOL_INFO);

SymbolInfo ret;
const bool have_info = SymFromAddr(process,
const bool have_info = SymFromAddr(current_process_,
reinterpret_cast<DWORD64>(address),
nullptr,
info);
if (have_info && strlen(info->Name) == 0) {
if (UnDecorateSymbolName(info->Name,
demangled_,
sizeof(demangled_),
demangled,
sizeof(demangled),
UNDNAME_COMPLETE)) {
ret.name = demangled_;
ret.name = demangled;
} else {
ret.name = info->Name;
}
Expand All @@ -135,7 +135,7 @@ class Win32SymbolDebuggingContext final : public NativeSymbolDebuggingContext {
bool IsMapped(void* address) override {
MEMORY_BASIC_INFORMATION info;

if (VirtualQuery(address, &info, sizeof(info)) != info)
if (VirtualQuery(address, &info, sizeof(info)) != sizeof(info))
return false;

return info.State == MEM_COMMIT && info.Protect != 0;
Expand All @@ -149,6 +149,7 @@ class Win32SymbolDebuggingContext final : public NativeSymbolDebuggingContext {
HANDLE current_process_;
};

std::unique_ptr<NativeSymbolDebuggingContext>
NativeSymbolDebuggingContext::New() {
return std::unique_ptr<NativeSymbolDebuggingContext>(
new Win32SymbolDebuggingContext());
Expand Down Expand Up @@ -177,4 +178,48 @@ void DumpBacktrace(FILE* fp) {
}
}

void CheckedUvLoopClose(uv_loop_t* loop) {
if (uv_loop_close(loop) == 0) return;

auto sym_ctx = NativeSymbolDebuggingContext::New();

fprintf(stderr, "uv loop at [%p] has active handles\n", loop);

uv_walk(loop, [](uv_handle_t* handle, void* arg) {
auto sym_ctx = static_cast<NativeSymbolDebuggingContext*>(arg);

fprintf(stderr, "[%p] %s\n", handle, uv_handle_type_name(handle->type));

void* close_cb = reinterpret_cast<void*>(handle->close_cb);
fprintf(stderr, "\tClose callback: %p %s\n",
close_cb, sym_ctx->LookupSymbol(close_cb).Display().c_str());

fprintf(stderr, "\tData: %p %s\n",
handle->data, sym_ctx->LookupSymbol(handle->data).Display().c_str());

// We are also interested in the first field of what `handle->data`
// points to, because for C++ code that is usually the virtual table pointer
// and gives us information about the exact kind of object we're looking at.
void* first_field = nullptr;
// `handle->data` might be any value, including `nullptr`, or something
// cast from a completely different type; therefore, check that it’s
// dereferencable first.
if (sym_ctx->IsMapped(handle->data))
first_field = *reinterpret_cast<void**>(handle->data);

if (first_field != nullptr) {
fprintf(stderr, "\t(First field): %p %s\n",
first_field, sym_ctx->LookupSymbol(first_field).Display().c_str());
}
}, sym_ctx.get());

fflush(stderr);
// Finally, abort.
CHECK(0 && "uv_loop_close() while having open handles");
}

} // namespace node

extern "C" void __DumpBacktrace(FILE* fp) {
node::DumpBacktrace(fp);
}
5 changes: 5 additions & 0 deletions src/debug_utils.h
Original file line number Diff line number Diff line change
Expand Up @@ -103,6 +103,11 @@ class NativeSymbolDebuggingContext {
virtual int GetStackTrace(void** frames, int count) { return 0; }
};

// Variant of `uv_loop_close` that tries to be as helpful as possible
// about giving information on currently existing handles, if there are any,
// but still aborts the process.
void CheckedUvLoopClose(uv_loop_t* loop);

} // namespace node

#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
Expand Down
9 changes: 5 additions & 4 deletions src/inspector_io.cc
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#include "inspector_socket_server.h"
#include "inspector/node_string.h"
#include "env-inl.h"
#include "debug_utils.h"
#include "node.h"
#include "node_crypto.h"
#include "node_mutex.h"
Expand Down Expand Up @@ -67,14 +68,14 @@ void HandleSyncCloseCb(uv_handle_t* handle) {
*static_cast<bool*>(handle->data) = true;
}

int CloseAsyncAndLoop(uv_async_t* async) {
void CloseAsyncAndLoop(uv_async_t* async) {
bool is_closed = false;
async->data = &is_closed;
uv_close(reinterpret_cast<uv_handle_t*>(async), HandleSyncCloseCb);
while (!is_closed)
uv_run(async->loop, UV_RUN_ONCE);
async->data = nullptr;
return uv_loop_close(async->loop);
CheckedUvLoopClose(async->loop);
}

// Delete main_thread_req_ on async handle close
Expand Down Expand Up @@ -281,7 +282,7 @@ void InspectorIo::ThreadMain() {
thread_req_.data = &queue_transport;
if (!server.Start()) {
state_ = State::kError; // Safe, main thread is waiting on semaphore
CHECK_EQ(0, CloseAsyncAndLoop(&thread_req_));
CloseAsyncAndLoop(&thread_req_);
uv_sem_post(&thread_start_sem_);
return;
}
Expand All @@ -291,7 +292,7 @@ void InspectorIo::ThreadMain() {
}
uv_run(&loop, UV_RUN_DEFAULT);
thread_req_.data = nullptr;
CHECK_EQ(uv_loop_close(&loop), 0);
CheckedUvLoopClose(&loop);
}

template <typename ActionType>
Expand Down
4 changes: 2 additions & 2 deletions src/node_watchdog.cc
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@

#include "node_watchdog.h"
#include "node_internals.h"
#include "debug_utils.h"
#include <algorithm>

namespace node {
Expand Down Expand Up @@ -60,8 +61,7 @@ Watchdog::~Watchdog() {
// UV_RUN_DEFAULT so that libuv has a chance to clean up.
uv_run(loop_, UV_RUN_DEFAULT);

int rc = uv_loop_close(loop_);
CHECK_EQ(0, rc);
CheckedUvLoopClose(loop_);
delete loop_;
loop_ = nullptr;
}
Expand Down
3 changes: 2 additions & 1 deletion src/node_worker.cc
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
#include "node_worker.h"
#include "debug_utils.h"
#include "node_errors.h"
#include "node_internals.h"
#include "node_buffer.h"
Expand Down Expand Up @@ -304,7 +305,7 @@ Worker::~Worker() {
CHECK(stopped_);
CHECK(thread_joined_);
CHECK_EQ(child_port_, nullptr);
CHECK_EQ(uv_loop_close(&loop_), 0);
CheckedUvLoopClose(&loop_);

// This has most likely already happened within the worker thread -- this
// is just in case Worker creation failed early.
Expand Down
3 changes: 2 additions & 1 deletion src/spawn_sync.cc
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
// USE OR OTHER DEALINGS IN THE SOFTWARE.

#include "spawn_sync.h"
#include "debug_utils.h"
#include "env-inl.h"
#include "string_bytes.h"
#include "util.h"
Expand Down Expand Up @@ -528,7 +529,7 @@ void SyncProcessRunner::CloseHandlesAndDeleteLoop() {
if (r < 0)
ABORT();

CHECK_EQ(uv_loop_close(uv_loop_), 0);
CheckedUvLoopClose(uv_loop_);
delete uv_loop_;
uv_loop_ = nullptr;

Expand Down
97 changes: 97 additions & 0 deletions test/abort/test-addon-uv-handle-leak.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,97 @@
// Flags: --experimental-worker
'use strict';
const common = require('../common');
const assert = require('assert');
const fs = require('fs');
const path = require('path');
const cp = require('child_process');
const { Worker } = require('worker_threads');

// This is a sibling test to test/addons/uv-handle-leak.

const bindingPath = path.resolve(
__dirname, '..', 'addons', 'uv-handle-leak', 'build',
`${common.buildType}/binding.node`);

if (!fs.existsSync(bindingPath))
common.skip('binding not built yet');

if (process.argv[2] === 'child') {
new Worker(`
const binding = require(${JSON.stringify(bindingPath)});
binding.leakHandle();
binding.leakHandle(0);
binding.leakHandle(0x42);
`, { eval: true });
} else {
const child = cp.spawnSync(process.execPath,
['--experimental-worker', __filename, 'child']);
const stderr = child.stderr.toString();

assert.strictEqual(child.stdout.toString(), '');

const lines = stderr.split('\n');

let state = 'initial';

// parse output that is formatted like this:

// uv loop at [0x559b65ed5770] has active handles
// [0x7f2de0018430] timer
// Close callback: 0x7f2df31de220 CloseCallback(uv_handle_s*) [...]
// Data: 0x7f2df33df140 example_instance [...]
// (First field): 0x7f2df33dedc0 vtable for ExampleOwnerClass [...]
// [0x7f2de000b870] timer
// Close callback: 0x7f2df31de220 CloseCallback(uv_handle_s*) [...]
// Data: (nil)
// [0x7f2de000b910] timer
// Close callback: 0x7f2df31de220 CloseCallback(uv_handle_s*) [...]
// Data: 0x42

if (!(common.isFreeBSD ||
common.isAIX ||
(common.isLinux && !common.isGlibc()) ||
common.isWindows)) {
assert(stderr.includes('ExampleOwnerClass'), stderr);
assert(stderr.includes('CloseCallback'), stderr);
assert(stderr.includes('example_instance'), stderr);
}

while (lines.length > 0) {
const line = lines.shift().trim();

switch (state) {
case 'initial':
assert(/^uv loop at \[.+\] has active handles$/.test(line), line);
state = 'handle-start';
break;
case 'handle-start':
if (/Assertion .+ failed/.test(line)) {
state = 'done';
break;
}
assert(/^\[.+\] timer$/.test(line), line);
state = 'close-callback';
break;
case 'close-callback':
assert(/^Close callback:/.test(line), line);
state = 'data';
break;
case 'data':
assert(/^Data: .+$/.test(line), line);
state = 'maybe-first-field';
break;
case 'maybe-first-field':
if (/^\(First field\)$/.test(line)) {
lines.unshift(line);
state = 'handle-start';
break;
}
state = 'maybe-first-field';
break;
case 'done':
break;
}
}
}
48 changes: 48 additions & 0 deletions test/addons/uv-handle-leak/binding.cc
Original file line number Diff line number Diff line change
@@ -0,0 +1,48 @@
#include <node.h>
#include <v8.h>
#include <uv.h>

using v8::Context;
using v8::FunctionCallbackInfo;
using v8::Isolate;
using v8::Local;
using v8::Object;
using v8::Value;

// Give these things names in the public namespace so that we can see
// them show up in symbol dumps.
void CloseCallback(uv_handle_t* handle) {}

class ExampleOwnerClass {
public:
virtual ~ExampleOwnerClass() {}
};

ExampleOwnerClass example_instance;

void LeakHandle(const FunctionCallbackInfo<Value>& args) {
Isolate* isolate = args.GetIsolate();
Local<Context> context = isolate->GetCurrentContext();
uv_loop_t* loop = node::GetCurrentEventLoop(isolate);
assert(loop != nullptr);

uv_timer_t* leaked_timer = new uv_timer_t;
leaked_timer->close_cb = CloseCallback;

if (args[0]->IsNumber()) {
leaked_timer->data =
reinterpret_cast<void*>(args[0]->IntegerValue(context).FromJust());
} else {
leaked_timer->data = &example_instance;
}

uv_timer_init(loop, leaked_timer);
uv_timer_start(leaked_timer, [](uv_timer_t*){}, 1000, 1000);
uv_unref(reinterpret_cast<uv_handle_t*>(leaked_timer));
}

void Initialize(v8::Local<v8::Object> exports) {
NODE_SET_METHOD(exports, "leakHandle", LeakHandle);
}

NODE_MODULE(NODE_GYP_MODULE_NAME, Initialize)
9 changes: 9 additions & 0 deletions test/addons/uv-handle-leak/binding.gyp
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
{
'targets': [
{
'target_name': 'binding',
'defines': [ 'V8_DEPRECATION_WARNINGS=1' ],
'sources': [ 'binding.cc' ]
}
]
}
23 changes: 23 additions & 0 deletions test/addons/uv-handle-leak/test.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
'use strict';
const common = require('../../common');
const bindingPath = require.resolve(`./build/${common.buildType}/binding`);
const binding = require(bindingPath);

// This tests checks that addons may leak libuv handles until process exit.
// It’s really not a good idea to do so, but it tests existing behaviour
// that likely can never be removed for backwards compatibility.

// This has a sibling test in test/abort/ which checks output for failures
// from workers.

try {
// We don’t want to run this in Workers because they do actually enforce
// a clean-exit policy.
const { isMainThread } = require('worker_threads');
if (!isMainThread)
common.skip('Cannot run test in environment with clean-exit policy');
} catch {}

binding.leakHandle();
binding.leakHandle(0);
binding.leakHandle(1);
Loading

0 comments on commit 4a54ebc

Please sign in to comment.