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: https://github.com/nodejs/node/pull/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>

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);
+}

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

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>

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;
 }

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.

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;
 

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;
+    }
+  }
+}

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)

test/addons/uv-handle-leak/binding.gyp

@@ -0,0 +1,9 @@
+{
+  'targets': [
+    {
+      'target_name': 'binding',
+      'defines': [ 'V8_DEPRECATION_WARNINGS=1' ],
+      'sources': [ 'binding.cc' ]
+    }
+  ]
+}

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);

test/common/index.js

@@ -68,6 +68,23 @@ exports.isOpenBSD = process.platform === 'openbsd';
 exports.isLinux = process.platform === 'linux';
 exports.isOSX = process.platform === 'darwin';
 
+let isGlibc;
+exports.isGlibc = () => {
+  if (isGlibc !== undefined)
+    return isGlibc;
+  try {
+    const lddOut = spawnSync('ldd', [process.execPath]).stdout;
+    const libcInfo = lddOut.toString().split('\n').map(
+      (line) => line.match(/libc\.so.+=>\s*(\S+)\s/)).filter((info) => info);
+    if (libcInfo.length === 0)
+      return isGlibc = false;
+    const nmOut = spawnSync('nm', ['-D', libcInfo[0][1]]).stdout;
+    if (/gnu_get_libc_version/.test(nmOut))
+      return isGlibc = true;
+  } catch {}
+  return isGlibc = false;
+};
+
 exports.enoughTestMem = os.totalmem() > 0x70000000; /* 1.75 Gb */
 const cpus = os.cpus();
 exports.enoughTestCpu = Array.isArray(cpus) &&