worker,src: display remaining handles if `uv_loop_close` fails

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>
nodejs · Jun 7, 2018 · 4a54ebc3bd0cd4a259f445604695ec3440975552 · 4a54ebc
1 parent aa468ab
commit 4a54ebc3bd0cd4a259f445604695ec3440975552
diff --git a/src/debug_utils.cc b/src/debug_utils.cc
@@ -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 {
@@ -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;
      }
@@ -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;
@@ -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());
@@ -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);
+  
+}
diff --git a/src/debug_utils.h b/src/debug_utils.h
@@ -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

diff --git a/src/inspector_io.cc b/src/inspector_io.cc
@@ -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"
@@ -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
@@ -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;
  }
@@ -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>

diff --git a/src/node_watchdog.cc b/src/node_watchdog.cc
@@ -21,6 +21,7 @@
 #include "node_watchdog.h"
 #include "node_internals.h"
+  
+#include "debug_utils.h"
 #include <algorithm>
 namespace node {
@@ -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;
 }

diff --git a/src/node_worker.cc b/src/node_worker.cc
@@ -1,4 +1,5 @@
 #include "node_worker.h"
+  
+#include "debug_utils.h"
 #include "node_errors.h"
 #include "node_internals.h"
 #include "node_buffer.h"
@@ -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.

diff --git a/src/spawn_sync.cc b/src/spawn_sync.cc
@@ -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"
@@ -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;

diff --git a/test/abort/test-addon-uv-handle-leak.js b/test/abort/test-addon-uv-handle-leak.js
@@ -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;
+  
+    }
+  
+  }
+  
+}
diff --git a/test/addons/uv-handle-leak/binding.cc b/test/addons/uv-handle-leak/binding.cc
@@ -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)
diff --git a/test/addons/uv-handle-leak/binding.gyp b/test/addons/uv-handle-leak/binding.gyp
@@ -0,0 +1,9 @@
+  
+{
+  
+  'targets': [
+  
+    {
+  
+      'target_name': 'binding',
+  
+      'defines': [ 'V8_DEPRECATION_WARNINGS=1' ],
+  
+      'sources': [ 'binding.cc' ]
+  
+    }
+  
+  ]
+  
+}
diff --git a/test/addons/uv-handle-leak/test.js b/test/addons/uv-handle-leak/test.js
@@ -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);