uv_async_t让Node.js脚本停止运行

在公司搬砖给Node.js写C++插件的时候遇到了一个BUG:在为Node.js导出的C++类中,如果存储了uv_async_t对象,会让一些Node.js的async/await操作不能正常工作。套上async/await,代码执行到C++代码通过回调函数异步返回给JS数据之后,脚本就停止工作了。

C++部分的代码大致是这样的:

#include <nan.h>
#include <memory>
#include <thread>
#include <vector>

// simple wrapper for uv_async_t
class uvAsyncEvent
{
public:
    uvAsyncEvent(void* context, uv_async_cb callback)
    {
        m_pAsyncHandle.reset(new uv_async_t());
        m_pAsyncHandle->data = context;
        uv_async_init(uv_default_loop(), m_pAsyncHandle.get(), callback);
    }
    ~uvAsyncEvent()
    {
    }
    void* GetContext() const
    {
        return m_pAsyncHandle->data;
    }
    void Notify()
    {
        uv_async_send(m_pAsyncHandle.get());
    }

private:
    struct Deleter
    {
        void operator()(uv_async_t* asyncEvent) const
        {
            if (asyncEvent)
            {
                uv_close((uv_handle_t*)asyncEvent, Deleter::uvCloseCallback);
            }
        }

        static void uvCloseCallback(uv_handle_t* handle)
        {
            delete (uv_async_t*)handle;
        }
    };
    std::unique_ptr<uv_async_t, Deleter> m_pAsyncHandle;
};

// a c++ class exported to Node.js which holds uv_async_t handles
class Hang
    : public Nan::ObjectWrap
{
public:
    static NAN_MODULE_INIT(Init)
    {
        v8::Local<v8::FunctionTemplate> tpl = Nan::New<v8::FunctionTemplate>(New);
        tpl->SetClassName(Nan::New("Hang").ToLocalChecked());
        tpl->InstanceTemplate()->SetInternalFieldCount(1);

        Nan::SetPrototypeMethod(tpl, "start", Start);
        Nan::SetPrototypeMethod(tpl, "stop", Stop);
        Nan::SetPrototypeMethod(tpl, "setCallback", SetCallback);

        constructor.Reset(Nan::GetFunction(tpl).ToLocalChecked());

        Nan::Set(target, Nan::New("Hang").ToLocalChecked(), Nan::GetFunction(tpl).ToLocalChecked());
    }

private:
    Hang()
        : m_pEvent(std::make_unique<uvAsyncEvent>(this, asyncCallback)) // async/await hangs
        , m_bRunning(true)
    {
    }
public:
    ~Hang()
    {
    }

    static NAN_METHOD(New)
    {
        if (info.IsConstructCall()) {
            // Invoked as constructor: `new Hang(...)`
            Hang* obj = new Hang();
            obj->Wrap(info.This());

            info.GetReturnValue().Set(info.This());

            v8::Local<v8::Object> context = v8::Local<v8::Object>::Cast(info[0]);
        }
        else {
            // Invoked as plain function `Hang(...)`, turn into construct call.
            const int argc = 1;
            v8::Local<v8::Value> argv[argc] = { info[0] };
            v8::Local<v8::Function> cons = Nan::New(constructor);
            v8::Local<v8::Object> result =
                Nan::NewInstance(cons, argc, argv).ToLocalChecked();
            info.GetReturnValue().Set(result);
        }
    }

    static NAN_METHOD(SetCallback)
    {
        Hang* obj = ObjectWrap::Unwrap<Hang>(info.Holder());

        if (!info[0]->IsFunction())
        {
            Nan::ThrowTypeError("arg 1 is not function");
            return;
        }

        obj->m_evCallback.reset(new Nan::Callback(info[0].As<v8::Function>()));
    }

    static NAN_METHOD(Start)
    {
        Hang* obj = ObjectWrap::Unwrap<Hang>(info.Holder());

        obj->m_bRunning = true;

        struct ThreadRunner
        {
            ThreadRunner(Hang& h)
                : m_obj(h)
            {
            }

            // Run
            void operator()()
            {
                while (m_obj.m_bRunning) {
                    std::this_thread::sleep_for(std::chrono::milliseconds(1000));
                    m_obj.m_pEvent->Notify();
                }
            }
        private:
            Hang& m_obj;
        };

        if (!obj->m_workThread)
        {
            obj->m_workThread = std::make_unique<std::thread>(ThreadRunner(*obj));
        }

    }

    static NAN_METHOD(Stop)
    {
        Hang* obj = ObjectWrap::Unwrap<Hang>(info.Holder());

        obj->m_bRunning = false;
        if (obj->m_workThread)
        {
            obj->m_workThread->join();
            obj->m_workThread.reset();
        }

        obj->m_pEvent.reset();
    }

private:
    static void asyncCallback(uv_async_t* handle)
    {
        Hang* pThis = (Hang*)handle->data;
        Nan::HandleScope scope;

        auto ret = Nan::New("async callback").ToLocalChecked();

        v8::Local<v8::Value> argv[] = { ret };

        Nan::Call(*pThis->m_evCallback, 1, argv);

    }

private:
    std::unique_ptr<uvAsyncEvent> m_pEvent;
    std::unique_ptr<Nan::Callback> m_evCallback;

    std::unique_ptr<std::thread> m_workThread;
    bool m_bRunning;

private:
    static Nan::Persistent<v8::Function> constructor;
};
Nan::Persistent<v8::Function> Hang::constructor;

// an asynchronous function for test
NAN_METHOD(testAsync)
{
    class Worker : public Nan::AsyncWorker
    {
    public:
        Worker(Nan::Callback* callbk)
            : Nan::AsyncWorker(callbk)
        {
        }

        void Execute() override
        {
            std::this_thread::sleep_for(std::chrono::milliseconds(100));
        }

        void HandleOKCallback() override
        {
            Nan::HandleScope scope;

            int argc = 1;
            std::unique_ptr<v8::Local<v8::Value>[]> argv(new v8::Local<v8::Value>[argc]());

            argv[0] = Nan::New("async task result").ToLocalChecked();

            Nan::Call(*callback, argc, argv.get());
        }
    };

    Nan::Callback* callbk = new Nan::Callback(Nan::To<v8::Function>(info[0]).ToLocalChecked());

    Worker* pWorker = new Worker(callbk);
    Nan::AsyncQueueWorker(pWorker);
}

NAN_MODULE_INIT(InitAll) 
{
    Hang::Init(target);
    Nan::SetMethod(target, "testAsync", testAsync);
}

NODE_MODULE(hang, InitAll)

用来测试的脚本:

const { Hang, testAsync } = require('./build/Release/hang');
const { EventEmitter } = require('events');

let h = new Hang();

// calling start method or not does not affect the problem
// h.start();

function doTestAsync() {
  return new Promise((resolve, reject) => {
    testAsync((data) => {
      // This line of code got executed without any problems
      // after 100ms of the function call(according to the C++ code)
      console.log(data);
      resolve(data);
    });
  });
}

function doSetTimeoutAsync() {
  return new Promise((resolve, reject) => {
    setTimeout(() => {
      let data = 'timeout async';
      console.log(data);
      resolve(data);
    }, 100)
  });
}

// this is ok
//testAsync((data) => {
//    console.log(data);
//});

async function testHang() {
  let asyncRet = await doSetTimeoutAsync();

  // no problem
  console.log("after async call1");
  let asyncRet2 = await doTestAsync();

  // async/await operation blocks due to the creation of "hang"
  // I paused the execution via the debugger, then continue, 
  // Dramatically this line gets executed
  console.log("after async call2");
  let asyncRet3 = await doTestAsync();
  console.log("after async call3");
  let asyncRet4 = await doTestAsync();
  console.log("after async call4");

  h.stop();
}


testHang();

背景和BUG表现

公司搬砖的项目里,要建立一个TCP长连接,用于与服务端之间通信和保持在线状态。通常情况下会单独启动一个线程用来维护连接,现在要把从服务端接收到的数据传给JS,一个很明显的思路是在工作线程里调用uv_async_send来通知主线程(能调用V8的API的线程)有数据传过来。

代码本身是简化后的模型。C++模块导出了一个Hang类和一个testAsync函数,Hang类对应的C++类管理了一个uv_async_t对象,testAsync函数使用了Nan::AsyncWorker用于测试Node.js的异步调用。

发生的问题是:直接通过命令行运行脚本,测试脚本会卡在调用doTestAsync之后,after async call2不会被输出出来。在vscode中启用调试模式时得到的结果也一样。程序的输出是这样的:

timeout async
after async call1
async task result

诡异的是,在vscode中把脚本暂停,脚本成功中断在了Node.js内部的代码里,然后继续运行,后面的输出居然输出了出来。然后脚本继续卡在第二次调用doTestAsync之后。如此暂停和继续运行,测试脚本居然能一路跑下去。

如果把断点停在testAsync提供的回调函数里,会发现程序走过resolve(data)之后就不能继续运行了。

把脚本本身改写成回调金字塔的样式,就像下面的代码一样,也是没有问题的。但是这样真的是太丑了,而且async/await是官方推崇的方式,总算能彻底解决回调金字塔地狱的问题,因为出现了这状况丫的还得改回去……

testAsync((data) => {
  console.log(data);
  console.log("after async call2");
  testAsync((data) => {
    console.log(data);
    console.log("after async call3");
    testAsync((data) => {
      console.log(data);
      console.log("after async call4");
    });
  });
});

尝试解决

首先用二分法找问题原因,逐个排查最近的修改,发现去掉了创建uv_async_t对象的代码,这个问题就不再出现了。

于是整理了下代码,写了个最小的可以必现这个问题的示例。信心满满地向Node.js提交了个issue,然后这个issue一小时后被项目管理者打入了nodejs/help的冷宫,而且没人回答我提出的问题。

既然没有人愿意回答我的问题,那就自己干!

不管怎么说先build个Debug版本的Node.js程序,Release版本经过优化,找错没有那么容易。签出代码库,按照vcbuild.bat的指示来构建,好了,Debug版的Node.js程序有了。因为ABI的问题,又手动建了个vcxproj项目把刚才的c++代码链接到了debug版生成出来的node.lib上。

然后开始调试。先找下Promise是在哪里实现的,Node.js中用JS写的实现都是放在lib目录下。在这个目录下搜索Promise字样,无果。然后在C++代码里继续搜,发现v8.h中声明了一个Promise类。Promise类里面声明了个Resolve方法。于是抱着试试看的心态在这个方法的实现(在deps/v8/src/api.cc)里加了断点。然后在vs的调试选项里面让Debug版的Node.js进程执行我们的测试脚本,脚本照样还是卡住了,api.cc里面的断点没有进去,看来找的Promise的实现的位置不对。

继续找Promise的实现,看到Promise类的声明里有个PromiseState枚举类型,应该是用来表示Promise对象当前的状态的,心想v8脚本引擎的内外应该都用同一种类型,用”查找所有引用”找了一下,原来v8脚本引擎内部还有个v8::internal::JSPromise类(在deps/v8/src/objects/js-promise.h里)。F12进去,看到了这样的代码,在deps/v8/src/objects.cc里面,这个应该是我们要找的Promise.resolve的实现了:

Handle<Object> JSPromise::Fulfill(Handle<JSPromise> promise,
                                  Handle<Object> value) {
  ...
  // 6. Set promise.[[PromiseState]] to "fulfilled".
  promise->set_status(Promise::kFulfilled);

  // 7. Return TriggerPromiseReactions(reactions, value).
  return TriggerPromiseReactions(isolate, reactions, value,
                                 PromiseReaction::kFulfill);
}

// static
MaybeHandle<Object> JSPromise::Resolve(Handle<JSPromise> promise,
                                       Handle<Object> resolution) {
  Isolate* const isolate = promise->GetIsolate();

  isolate->RunPromiseHook(PromiseHookType::kResolve, promise,
                          isolate->factory()->undefined_value());

  ...

  // 7. If Type(resolution) is not Object, then
  if (!resolution->IsJSReceiver()) {
    // a. Return FulfillPromise(promise, resolution).
    return Fulfill(promise, resolution);
  }

  ...

  // 10. Let thenAction be then.[[Value]].
  // 11. If IsCallable(thenAction) is false, then
  if (!then_action->IsCallable()) {
    // a. Return FulfillPromise(promise, resolution).
    return Fulfill(promise, resolution);
  }

  // 12. Perform EnqueueJob("PromiseJobs", PromiseResolveThenableJob,
  //                        «promise, resolution, thenAction»).
  Handle<PromiseResolveThenableJobTask> task =
      isolate->factory()->NewPromiseResolveThenableJobTask(
          promise, Handle<JSReceiver>::cast(then_action),
          Handle<JSReceiver>::cast(resolution), isolate->native_context());
  if (isolate->debug()->is_active() && resolution->IsJSPromise()) {
    // Mark the dependency of the new {promise} on the {resolution}.
    Object::SetProperty(resolution,
                        isolate->factory()->promise_handled_by_symbol(),
                        promise, LanguageMode::kStrict)
        .Check();
  }
  isolate->EnqueueMicrotask(task);

  // 13. Return undefined.
  return isolate->factory()->undefined_value();
}

在这个函数里加了断点,重新调试。发现在程序卡住之前,Node.js居然没有在JSPromise这里中断!甚至在after async call1输出之前,Node.js进程也没中断在刚才在objects.cc中加的断点上。

如果换一种调用JS脚本的方式:在shell模式下运行Node.js,输入命令require('./hang.js')调用脚本,在JSPromise里加的断点生效了,但是程序之后卡住的时候,仍然没进到加的断点上。

两种运行脚本的方式得到不同结果的原因,大概是在命令参数里直接运行脚本的时候,Node.js把脚本的JS代码包括Promise操作全都JIT掉了,JSPromise里面的那些代码根本没有用。

看来这个问题和Promise的实现是没有关系的。至于还有什么其它原因实在是百思不得其解。

转机

问题解决

这个问题拖了将近一周的时间,直到有一天想这个问题的时候拖了下控制台窗口,改变了下Node.js控制台窗口的大小。改变了窗口大小之后,await后面的语句居然被执行了!

期待的结果出现了,赶紧分析下到底发生了什么让结果是对的。再次打开Node.js项目里编译生成的node.sln,用我们的debug版的Node.js启动测试脚本,脚本毫无悬念地卡死。这时候在VS调试器里暂停node.exe的运行,看到主线程中断在了下面的位置:

可以看到Node.js调用了Windows的IOCP。一直等待的情况下,只有IOCP管理的HANDLE对应的IO操作完成或者用PostQueuedCompletionStatus直接向IOCP对象发消息,IOCP的等待操作才会退出。再看一下node.exe调用GetQueuedCompletionStatusEx传进去的超时时间是多少,现在这个状态下这个值是-1。所以说程序卡死的原因是一直在等待一个IOCP事件传过来。然而尝试修改前面的timeout数值,改成不是一直等待,重新编译代码,卡死的问题仍然存在。

GetQueuedCompletionStatusEx的下一行加个断点,然后让node.exe继续跑下去。这之后拖一下控制台窗口,继续单步跟下去,可以看到IOCP消息对应的libuv消息(uv_req_t)类型是UV_SIGNAL_REQ。继续跟到循环结束走到下一轮循环,单步调试到uv_process_signal_req的时候(在uv_process_reqs里面),可以看到信号的编号是28。编号为28的信号是什么信号?查了下是SIGWINCH,在控制台窗口大小发生改变时,操作系统会向对应的进程发送这个信号。不管这么多,继续单步调试跑到下面signal_wrap.cc的代码时,代码走过wrap->MakeCallback这一行之后,await后面的JS代码要输出的东西输出到了屏幕上。

  static void OnSignal(uv_signal_t* handle, int signum) {
    SignalWrap* wrap = ContainerOf(&SignalWrap::handle_, handle);
    Environment* env = wrap->env();
    HandleScope handle_scope(env->isolate());
    Context::Scope context_scope(env->context());

    Local<Value> arg = Integer::New(env->isolate(), signum);
    wrap->MakeCallback(env->onsignal_string(), 1, &arg);
  }

所以这个MakeCallback到底做了什么?看代码可以知道SignalWrap也是向JS环境导出的一个类,在JS端的名字叫Signal。在node项目的lib目录下狂搜,找到了与SIGWINCH信号相关的几个处理函数,但是这些函数和执行当前要继续执行的JS代码都没有任何关系。所以可能是C++代码的问题?
换一种思路来找代码能正常运行的原因。既然控制台都有输出,在Windows下向控制台窗口输出,最终都会调用kernel32.dll导出的WriteConsole函数。又因为涉及到字符串的函数Windows都会提供分别处理char*wchar_t*的两种函数,所以需要加两个断点,按Ctrl+B打开添加断点窗口,手动加上这两个断点:

  {,,kernel32.dll}WriteConsoleA
  {,,kernel32.dll}WriteConsoleW

在启用这两个断点调试的情况下去单步调试MakeCallback方法的实现,最终锁定到了这一行C++代码:

代码中断在env_->tick_callback_function()->Call(process, 0, nullptr).IsEmpty()这一行时,让代码继续运行,node进程就会立刻中断在kernel32.dll导出的WriteConsoleW函数上。看函数的名字tick_callback_function,这个应该就是用来执行等待运行的JS代码的相关的函数,也就是测试脚本里await之后的部分。

所以结论是:拖动控制台窗口能让async/await继续运行,完全是个副作用。原因只不过是Node.js要运行操作系统信号相关的处理函数的时候,顺带会把等待执行的JS代码拎过来也执行一下而已。鬼使神差地就让脚本按预期的方式工作了。至于为什么新建uv_async_t对象就会让Node.js陷入无限等待IOCP消息的状态,这个我实在是无力去追查。

SIGWINCH信号是如何在windows下模拟出来的

Windows本身是不支持SIGWINCH信号的,Node.js(libuv)用启动监听线程监听控制台窗口大小变化的方法模拟了这个信号。窗口大小变化的消息本身是用PostQueuedCompletionStatus直接向主线程IOCP发消息发过去的。要验证可以Ctrl+B手动加个断点{,,kernelbase.dll}PostQueuedCompletionStatus,然后拖动控制台窗口,程序就会中断在监听控制台窗口的线程里面。

解决办法

既然系统向Node.js进程发送SIGWINCH信号会迫使Node.js去运行下个事件循环需要执行的JS代码,那么解决方法也就出来了。

方法是:在测试脚本前面加个定时器,向当前Node.js进程不停地发送SIGWINCH信号,脚本就能继续跑下去直到结束:

setInterval(() => {
    process.emit('SIGWINCH');
}, 100);

这个解决方法实在是过于草生(中日双语),我始终认为这是Node.js的BUG,应该在事件循环处于空闲的状态时就去处理等待执行的JS代码,然而官方不理,当然原因也可能是真的不好处理。

感想

  • 二分法找BUG万岁。
  • 带JIT的脚本引擎找问题是真难,因为JIT出来的汇编代码产出的调用堆栈和编译器生成出来的约定不一样。然后你就没办法看到调用JIT代码之前的堆栈发生了什么。
  • 有些固有的BUG估计是没有人会理的,久而久之估计就成了feature。

后续

Node.js 8.x 10.x 12.x 在Windows/Linux上都有这个问题,Mac没条件试。