[async_hooks] Wrong after callback in case of uncaughtException

Version: 8.12.0, 10.11.0, master
Platform: windows
Subsystem: async_hooks

async_hooks call after with wrong id if an uncaughtException happens which does not end the process.

const async_hooks = require("async_hooks");
const fs = require("fs");

function init(asyncId, type, triggerAsyncId, resource) {
  fs.writeSync(1, `${type}(${asyncId}): trigger: ${triggerAsyncId} execution: ${async_hooks.executionAsyncId()}\n`);
}

function before(asyncId) {
  fs.writeSync(1, `before:  ${asyncId}\n`);
}

function after(asyncId) {
  fs.writeSync(1, `after:   ${asyncId}\n`);
}

function destroy(asyncId) {
  fs.writeSync(1, `destroy: ${asyncId}\n`);
}

async_hooks.createHook({ init, before, after, destroy }).enable();

process.nextTick(() => {
//setTimeout(() => {
  fs.writeSync(1, "in callback\n");
  throw new Error("foo");
}, 100);

process.on("uncaughtException", (e) => fs.writeSync(1, "uncaughtException\n"));

Results in

TickObject(5): trigger: 1 execution: 1
before:  5
in callback
uncaughtException
Immediate(6): trigger: 5 execution: 5
after:   5
after:   1   <=== I think this is not correct
destroy: 5
before:  6
after:   6
destroy: 6

if I change the sample above to use setTimeout instead process.nextTick the issue is limited to master and the async_id emitted is 0 instead 1.

I tried to find the root cause and I thought it's in _fatalException which should emit after for all except the last ids and in case there are no hooks clear all except the last.
But if I check the working setTimeout case in NodeJs 8.12.0 the stack only holds the async_ids for Timeout and TIMERWRAP but not the 0/1 entries.

I think the issue might be that we manually kick off nextTick from Module.runMain(), i.e. after running the main script, but while still on the main script stack. For other invocations, we only run the nextTick queue after returning to C++ from whatever callback we invoked, including for setTimeouts… does that make sense?

@addaleax

So, a few issues involved here:

When do the emitAfter loop in _fatalException, we need to ignore async frames with ID of 0.
There's already a stack for nextTick upon the start of the program, as @addaleax mentioned above which leads it to the 1 being logged. This is technically not a bug but it could be confusing... I don't really have an opinion as to whether it should be fixed... maybe?

For completeness the results with other node versions:
Master setTimeout

Timeout(5): trigger: 1 execution: 1
before:  5
in callback
uncaughtException
Immediate(6): trigger: 5 execution: 5
after:   5
after:   0
destroy: 5
before:  6
after:   6
destroy: 6

10.11.0 setTimeout:

Timeout(5): trigger: 1 execution: 1
TIMERWRAP(6): trigger: 1 execution: 1
before:  6
before:  5
in callback
uncaughtException
Immediate(7): trigger: 5 execution: 5
after:   5
after:   6
before:  6  <== strange before/after 6 again here with no callback inbetween
after:   6
destroy: 5
before:  7
after:   7
destroy: 7
destroy: 6

8.12.0 setTimeout:

Timeout(5): trigger: 1 execution: 1
TIMERWRAP(6): trigger: 1 execution: 1
before:  6
before:  5
in callback
uncaughtException
Immediate(7): trigger: 5 execution: 5
after:   5
after:   6
destroy: 5
before:  7
after:   7
destroy: 7
destroy: 6

I think we should not signal after if there was no before signalled.

I'm not sure about the 0/1 entries. If there are present because "something" / "the system" is running we should not remove them. But is there any need to have them on stack at all? Why not default to 0/1 if there is nothing on stack?

@addaleax

The issue with nextTick seems to be solved since 13.2.0. I guess it was one of the commits from @addaleax done around 6.11.
setTimeout has not changed.

process: ignore asyncId 0 in exception handler

Navigation Menu

Repository navigation

[async_hooks] Wrong after callback in case of uncaughtException #22982

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[async_hooks] Wrong after callback in case of uncaughtException #22982

Description

Activity

addaleax commented on Sep 22, 2018

apapirovski commented on Sep 23, 2018

Flarna commented on Sep 23, 2018

Flarna commented on Dec 19, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions