Assertion `(env_->execution_async_id()) == (0)' failed

[ronag]

I managed to trigger an assertion.

undici$ node --version
v15.13.0

test/client-connect.js 2> /Users/ronagy/.nvm/versions/node/v15.13.0/bin/node[49832]: ../src/api/callback.cc:125:void node::InternalCallbackScope::Close(): Assertion `(env_->execution_async_id()) == (0)' failed.
test/client-connect.js 2>  1: 0x1013990c5 node::Abort() (.cold.1) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  2: 0x1000c6c89 node::Abort() [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  3: 0x1000c6af1 node::Assert(node::AssertionInfo const&) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  4: 0x100001cdd node::InternalCallbackScope::Close() [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  5: 0x10000228a node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  6: 0x10001a7e8 node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  7: 0x100183821 node::StreamBase::CallJSOnreadMethod(long, v8::Local<v8::ArrayBuffer>, unsigned long, node::StreamBase::StreamBaseJSChecks) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  8: 0x100185787 node::EmitToJSStreamListener::OnStreamRead(long, uv_buf_t const&) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2>  9: 0x10018a61b node::LibuvStreamWrap::OnUvRead(long, uv_buf_t const*) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 10: 0x100a63a8e uv__stream_io [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 11: 0x100a6c45c uv__io_poll [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 12: 0x100a58d51 uv_run [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 13: 0x100002e74 node::SpinEventLoop(node::Environment*) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 14: 0x100107a64 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 15: 0x1000949c4 node::Start(int, char**) [/Users/ronagy/.nvm/versions/node/v15.13.0/bin/node]
test/client-connect.js 2> 16: 0x7fff20386621 start [/usr/lib/system/libdyld.dylib]

[ronag]

@addaleax is this supposed to be possible?

[addaleax]

@ronag no, hence the assertion

[Flarna]

@ronag Do you have a reproducer? I doubt this happens just by calling node --version :o)

[ronag]

Sorry. Happened while debugging another issue and haven’t happened since.

[ronag]

@Flarna @addaleax If you clone this https://github.com/nodejs/undici/tree/native-assert and run tap test/tls-session-reuse.js you should get the assertion.

[Flarna]

I did a fast try but failed to reproduce the crash. Should it happen always or only every now and then?
Any dependecy to nodejs version or OS?

[ronag]

Node v15.5.1, OSX 11.2.3.

It should happen every time.

[targos]

Stack trace on my mac:

/Users/targos/git/nodejs/node/out/Debug/node[16113]: ../../src/api/callback.cc:125:void node::InternalCallbackScope::Close(): Assertion `(env_->execution_async_id()) == (0)' failed.
 1: 0x1024e3b38 node::DumpBacktrace(__sFILE*) [/Users/targos/git/nodejs/node/out/Debug/node]
 2: 0x10262bf90 node::Abort() [/Users/targos/git/nodejs/node/out/Debug/node]
 3: 0x10262bc18 node::AppendExceptionLine(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Message>, node::ErrorHandlingMode) [/Users/targos/git/nodejs/node/out/Debug/node]
 4: 0x1024627fc node::InternalCallbackScope::Close() [/Users/targos/git/nodejs/node/out/Debug/node]
 5: 0x1024625b4 node::InternalCallbackScope::~InternalCallbackScope() [/Users/targos/git/nodejs/node/out/Debug/node]
 6: 0x102461dcc node::InternalCallbackScope::~InternalCallbackScope() [/Users/targos/git/nodejs/node/out/Debug/node]
 7: 0x102513d70 node::Environment::RunAndClearNativeImmediates(bool) [/Users/targos/git/nodejs/node/out/Debug/node]
 8: 0x10251352c node::Environment::CheckImmediate(uv_check_s*) [/Users/targos/git/nodejs/node/out/Debug/node]
 9: 0x10365256c uv__run_check [/Users/targos/git/nodejs/node/out/Debug/node]
10: 0x103647f60 uv_run [/Users/targos/git/nodejs/node/out/Debug/node]
11: 0x10246791c node::SpinEventLoop(node::Environment*) [/Users/targos/git/nodejs/node/out/Debug/node]
12: 0x1026c3594 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/Users/targos/git/nodejs/node/out/Debug/node]
13: 0x1025a0724 node::Start(int, char**) [/Users/targos/git/nodejs/node/out/Debug/node]
14: 0x103e4f3d4 main [/Users/targos/git/nodejs/node/out/Debug/node]
15: 0x195131f34 start [/usr/lib/system/libdyld.dylib]

[targos]

node/src/api/callback.cc

Lines 122 to 127 in e46c680

	// Make sure the stack unwound properly. If there are nested MakeCallback's
	// then it should return early and not reach this code.
	if (env_->async_hooks()->fields()[AsyncHooks::kTotals]) {
	CHECK_EQ(env_->execution_async_id(), 0);
	CHECK_EQ(env_->trigger_async_id(), 0);
	}

I think it's that assert?

[Flarna]

Till now I failed to reproduce on windows or WSL. Found no time yet to test on linux. I have no access to a mac.

[Flarna]

Tried on linux and can't reproduce there with 15.14.0. The test just fails with JS exceptions:

 FAIL  test/tls-session-reuse.js 5 failed of 5 142.07ms
 ✖ Cannot convert undefined or null to object
 ✖ should be equal
 ✖ Cannot read property 'toString' of undefined
 ✖ Cannot read property 'reuseSessions' of undefined
 ✖ connect ECONNREFUSED 127.0.0.1:33543

Either I'm doing something wrong here or it effects only MacOs.