child_process 'spawn' event is emitted too soon

[JakobJingleheimer]

Version: 15.1.0 thru 15.11.0 (see screenshot below)
Platform: Darwin CALLMT20389 19.6.0 Darwin Kernel Version 19.6.0: Thu Oct 29 22:56:45 PDT 2020; root:xnu-6153.141.2.2~1/RELEASE_X86_64 x86_64

What steps will reproduce the bug?

Run the following simple repro example:

$> node ./parent.mjs

parent.mjs

import { fork } from 'child_process';


const subprocess = fork('./child.mjs');

subprocess.on('close', (...args) => { console.error('[PARENT] received', ...args) });
subprocess.on('disconnect', (...args) => { console.error('[PARENT] received', ...args) });
subprocess.on('error', (...args) => { console.error('[PARENT] received', ...args) });
subprocess.on('exit', (...args) => { console.error('[PARENT] received', ...args) });
subprocess.on('message', (...args) => { console.log('[PARENT] received', ...args) });
subprocess.on('spawn', () => {
  console.log({
    'parent::subprocess.send': subprocess.send({ hello: 'child' })
  });
});

child.mjs

process.on('message', (...args) => { console.log('[CHILD] received', ...args) });

process.send({ hello: 'parent' });

How often does it reproduce? Is there a required condition?

100% of the time (dozens of executions)

What is the expected behavior?

child's process.on('message') should be triggered (parent's message should be received and logged to console).

What do you see instead?

Only parent's subprocess.on('message') is triggered:

$> node ./parent.mjs
{ 'parent::subprocess.send': true }
[PARENT] received { hello: 'parent' }

Additional info

I installed node via nvm. I verified the version of node actually running is truly 15.11.0 by console logging process.version in both parent.mjs and child.mjs (both output v15.11.0)

[JakobJingleheimer]

Interestingly, if I wrap the subprocess.send() (still inside on('spawn')) in a setTimeout with at least a 29 millisecond delay, it almost always works (~80–90% success rate).

The setTimeout trick outside on('spawn') works but needs a much larger number, like 3 seconds.

[Linkgoron]

This looks like a race condition where children .mjs take a bit longer to start, and the spawn is called "too early".

Look at the following change and console logs:

parent.mjs:

import { fork } from 'child_process';

const subprocess = fork('./tst/child.mjs');
subprocess.on('message', (...args) => { console.log('[PARENT] received', ...args) });
subprocess.on('spawn', () => {
  console.log('spawn was called');
  console.log({
    'parent::subprocess.send': subprocess.send({ hello: 'child' })
  });
});

child.mjs:

console.log('pre-message-handler');
process.on('message', (...args) => { console.log('[CHILD] received', ...args) });

process.send({ hello: 'parent' });

It prints:

spawn was called
{ 'parent::subprocess.send': true }
pre-message-handler
[PARENT] received { hello: 'parent' } undefined

The parent sends the message before the child adds the message handler.

[JakobJingleheimer]

Yep, that's what I surmised.

The docs for Event: 'spawn' say:

the 'spawn' event is emitted once the child process has spawned successfully.

It would appear the doc is either incorrect or (more likely) it's a bug.

[JakobJingleheimer]

As a workaround, I set up a handshake wherein the child immediately sends a "READY" message to its parent, resolving a promise in the parent:

parent.mjs

const settleReadyState = {};

const subprocess = fork('./child.mjs');

subprocess.ready = new Promise((resolve, reject) => Object.assign(settleReadyState, { resolve, reject }));

subprocess.once('message', () => {
  settleReadyState.resolve();
  subprocess.on('message', console.log);
});

subprocess.ready.then(() => subprocess.send({ hello: 'child' });
});

child.mjs

process.on('message', console.log);

process.send('READY');
process.send({ hello: 'parent' });

[schamberg97]

What is interesting is that I found out that it only reproduces, if the child script's extension is .mjs, even if import { fork } from 'child_process'; is used in the parent script. Probably ESM is a bit slower at Node startup and revealed a race condition elsewhere, only in the child itself.

child.js:

nikolayshamberg@m1001 /tmp % node ./parent.mjs
{ 'parent::subprocess.send': true }
[PARENT] received { hello: 'parent' } undefined
[CHILD] received { hello: 'child' } undefined

child.Mjs:

nikolayshamberg@m1001 /tmp % node ./parent.mjs
{ 'parent::subprocess.send': true }
[PARENT] received { hello: 'parent' } undefined

What is even weirder is that subprocess.connected is always true, unless disconnect was called. From documentation:

The subprocess.connected property indicates whether it is still possible to send and receive messages from a child process. When subprocess.connected is false, it is no longer possible to send or receive messages.

Obviously, true by default... Is just not true in our case ;)

Otherwise, if subprocess.connected was meaningful, we could just check in JS whether the child is already available to interact with. Perhaps subprocess.connected should be set to true only after the check akin to that of @JakobJingleheimer's is done first? I think that would be an elegant solution and we wouldn't need to deal with ESM issue

[JakobJingleheimer]

I wonder if it's because ESM loader is always async?

Update: The handshake workaround above seems to be working pretty well so far, and is backwards compatible (since the spawn event was added in 15.1, but child_process has existed since well before then).

I'd be happy to add it to the docs.

[JakobJingleheimer]

Yes and yes

I would guess subprocess.connected is also a bug—possibly with the same cause?

But the 'spawn' event is still pretty necessary (otherwise, without the handshake workaround, we'd have to poll subprocess.connected til it switches to true 😱).

I think subprocess.send() returning true here is also a bug. If not a bug, I can't think of a use-case for it (as-is, it seems like a lie).

[Linkgoron]

I disagree, because the connected property and spawn event are not Node cp specific. If there's an issue here, and I'm not 100% sure that there is one (except maybe better spawn documentation), it's (IMO) in the Node child-process that should probably be able to receive the messages that were sent before a listener could be added, and not in the parent.

[JakobJingleheimer]

If the spawn event is not specific to child_process, do the others maybe also suffer this problem?

IMHO, the spawn event etc should have the same behaviour for both commonjs and esm.

[schamberg97]

I think subprocess.send() returning true here is also a bug. If not a bug, I can't think of a use-case for it (as-is, it seems like a lie).

As far as I understand documentation, it only shows, whether comm channel was terminated or not. If channel is terminated, it becomes false. It will always show true, even before IPC is established in the first case.