在公司搬砖给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没条件试。
想加你,结果你的Twitter 被禁了。有node.js项目咨询,有意回复邮件
同遇到这问题了,不过按我的猜测,这问题很可能跟uv_async_t的实现有关系——uv_async_t实际上会block掉主循环,直到遇到下一个uv_async_send发来的信号。
我没具体去看代码,但支撑我这个猜测的是调试时遇到的两个场景,产生了不一样的结果。
场景一,将uv_async_t用于一请求一响应的场景。主动调用一个方法,这个方法里面先是uv_async_init注册回调,然后通知另一条线程去拿数据,最后返回promise。另一条线程拿到数据后,uv_async_send触发主线程回调,主线程回调uv_close掉这个uv_async_t。写个脚本循环await这个方法,脚本完全没有卡住,符合预期。
场景二,将uv_async_t用于被动接收响应的场景。实现一个方法,从js层传入一个回调,用uv_async_init把这个回调包装成,从收到另一条线程收到数据,就把数据当成第一个参数调用回调。在脚本用这个方法注册一个回调,然后再用一个setTimeout的死循环保持主线程存活,并打印心跳。启动脚本,确保另一条线程完全没有数据传来主线程。然后问题就出来了,脚本会在第一次心跳后卡住,直到另一条线程传来一次数据出发回调,然后心跳跳一下,又再次卡住。
综上,不难看出uv_async_t被init后,实际上是在主循环中注册了一个会导致block的事件检测,如果要等的事件没来,整个主循环就会卡住,直到事件到来,然后这个loop才能跑下去。但只要一直不close,这个事件检测会一直存在,下一次loop,继续卡住等事件。
可以说,uv_async_t从设计之初就不打算支持被动接收响应的场景,只适用于一请求一响应的异步任务场景。