process: flaky behavior of 'exit' event handler

[vsemozhetbyt]

• Version: '8.0.0-rc.0'
• Platform: Windows 7 x64
• Subsystem: process

process.md states:

Listener functions must only perform synchronous operations. The Node.js
process will exit immediately after calling the 'exit' event listeners
causing any additional work still queued in the event loop to be abandoned.
In the following example, for instance, the timeout will never occur:

process.on('exit', (code) => {
  setTimeout(() => {
    console.log('This will not run');
  }, 0);
});

However, the behavior of the code is flaky:

> test.js

> test.js
This will not run

> test.js
This will not run

> test.js

> test.js

> test.js

> test.js
This will not run

...

If this flakiness is not a bug, what would be better?

1. Increase the timeout up to 1000 or something and save the categorical 'the timeout will never occur'.
2. State flakiness. If so, what would be preferable wordings for the description and the logged string?

[sam-github]

What about a timeout of 1, is that flaky?

[vsemozhetbyt]

@sam-github For me, yes, it is.

[drifkin]

I think a timeout of 0 is the same as 1 due to this code.

fwiw, I prefer (2), since (1) might make people think that there would be no flakiness, even if the timeout were lowered.

[addaleax]

I’m not sure, but isn’t it a bug that that code actually runs?

[sam-github]

Smells like a bug to me.

[vsemozhetbyt]

@sam-github @addaleax Could we check this for various OS?

I've checked for various Node.js versions in Windows 7 x64:

Node.js 4.8.2 x64 (v8 4.5.103.46)
consistently not run

Node.js 6.10.2 x64 (v8 5.1.281.98)
consistently not run

Node.js 7.8.0 x64 (v8 5.5.372.43)
flaky

Node.js 8.0.0-nightly201703249ff7ed23cd x64 (v8 5.6.326.57)
flaky

Node.js 8.0.0-nightly20170404394b6ac5cb x64 (v8 5.7.492.69)
flaky

Node.js 8.0.0-pre x64 (v8 5.8.202)
flaky

Node.js 8.0.0-pre x64 (v8 5.9.0 candidate turbo on)
flaky

Node.js 8.0.0-pre x64 (v8 5.9.0 candidate turbo off)
flaky

[addaleax]

I can confirm, the behaviour differs between Node 6 and Node 7 on x64 Linux, too.

[Fishrock123]

Does this only happen if you let the process expire normally, or also if you call process.exit()?

If it does not happen with process.exit(), it is simply a race condition with the beforeExit handler, I think:

node/src/node.cc

Lines 4383 to 4392 in affe0f2

	if (more == false) {
	v8_platform.PumpMessageLoop(isolate);
	EmitBeforeExit(&env);
	// Emit `beforeExit` if the loop became alive either after emitting
	// event, or after running some callbacks.
	more = uv_loop_alive(env.event_loop());
	if (uv_run(env.event_loop(), UV_RUN_NOWAIT) != 0)
	more = true;
	}

[Fishrock123]

ok I just double-checked and that doesn't make sense because your scheduling it in the exit handler... Smells like a bug but I'm not sure where

[addaleax]

aac79df is the first bad commit

/cc @bnoordhuis – This really seems to be the first commit where this happens, although I can’t quite make out why that is from looking at the diff…

[bnoordhuis]

It's caused by the while (handle_cleanup_waiting_ != 0) uv_run(event_loop(), UV_RUN_ONCE) loop in the Environment destructor.

aac79df merges CleanupHandles() into the destructor, before that commit it was only used in debug-agent.cc.

[addaleax]

@bnoordhuis Thanks for explaining, makes sense. I would say this is a bug that we should fix by ensuring the “old” behaviour; do you agree? And if you do, would you prefer to do that yourself? I should be able to take care of it, too.

[vsemozhetbyt]

Maybe a test could be added to check old behavior.

[addaleax]

Oh, yeah, definitely – we should have a test for that, no matter whether we change behaviour or not. One can turn your code into a non-flaky version like this:

process.on('exit', (code) => {
  setTimeout(() => {
    console.log('This will not run'); // crash or w/e
  }, 0);
  // busy loop to make sure the timeout always expires during this tick
  const a = process.hrtime();
  while (process.hrtime(a)[1] < 5000);
});

[bnoordhuis]

It's not as simple as bringing back CleanupHandles() though. See #12344, it breaks #9753.

[bnoordhuis]

Fixed in 5ef6000.