process: flaky behavior of 'exit' event handler

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?

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

What about a timeout of 1, is that flaky?

@sam-github

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

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.

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

Smells like a bug to me.

@sam-github

@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

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

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; 
        
           }

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

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.

@bnoordhuis

@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.

Maybe a test could be added to check old behavior.

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);
});

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

src: don't call uv_run() after 'exit' event

Fixed in 5ef6000.

src: don't call uv_run() after 'exit' event

test: rename regression tests more expressively

Navigation Menu

Repository navigation

process: flaky behavior of 'exit' event handler #12322

1 remaining item

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	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;
	}

process: flaky behavior of 'exit' event handler #12322

Description

Activity

sam-github commented on Apr 11, 2017

vsemozhetbyt commented on Apr 11, 2017

drifkin commented on Apr 11, 2017

addaleax commented on Apr 11, 2017

sam-github commented on Apr 11, 2017

vsemozhetbyt commented on Apr 11, 2017

addaleax commented on Apr 11, 2017

Fishrock123 commented on Apr 11, 2017

Fishrock123 commented on Apr 11, 2017

1 remaining item

bnoordhuis commented on Apr 11, 2017

addaleax commented on Apr 11, 2017

vsemozhetbyt commented on Apr 11, 2017

addaleax commented on Apr 11, 2017

bnoordhuis commented on Apr 11, 2017

bnoordhuis commented on Apr 19, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions