Only a single console.log is logged from a worker when exiting

[kripken]

Version

16.5.0

Platform

Linux64

Subsystem

No response

What steps will reproduce the bug?

Testcase:

const {
  Worker, isMainThread
} = require('worker_threads');

if (isMainThread) {
  console.log('main');
  const worker = new Worker(__filename, {});
} else {
  console.log('worker1');
  console.log('worker2');
  console.log('worker3');
  process.exit(0);
}

Run with node b.js

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

100% of the time.

What is the expected behavior?

I would expect to see

main
worker1
worker2
worker3

What do you see instead?

main
worker1

The main thread logged, but the worker only logged the first of three loggings.

Additional information

Somehow the first console.log is always logged out, but the other ones are stopped by the presence of the process.exit after them. This does not seem to be a race in my testing: the first one is always shown, and none of the others.

Returning to the main event loop after the first logging allows one more logging to show up. That is:

const {
  Worker, isMainThread
} = require('worker_threads');

if (isMainThread) {
  console.log('main');
  const worker = new Worker(__filename, {});
} else {
  console.log('worker1');
  setTimeout(() => { // return to main event loop after first logging
    console.log('worker2');
    console.log('worker3');
    process.exit(0);
  }, 0);
}

That prints out worker2. Once more a single logging appears of all those that are expected to happen, and worker3 is not logged.

This was noticed in Emscripten here: emscripten-core/emscripten#14804 Emscripten will use process.exit when the program is done, and we were only getting the first console.log out of all those the program prints. (As a workaround we write synchonously to the fd for stdout, which does work.)

[targos]

@nodejs/workers

[addaleax]

console.log() writes to stdout, which is an asynchrononous operation in Node.js (potentially also on the main thread, but always in worker threads). process.exit() exits synchronously, effectively aborting all currently ongoing asynchronous operations.

[RaisinTen]

When #40813 lands, you will be able to wait for the async operations to be over before exiting like this:

const {
  Worker, isMainThread
} = require('worker_threads');

if (isMainThread) {
  console.log('main');
  const worker = new Worker(__filename, {});
} else {
  console.log('worker1');
  console.log('worker2');
  console.log('worker3');
  setInterval(() => process.getActiveResourcesInfo().length === 0 && process.exit(0));
}

[addaleax]

@RaisinTen Wouldn’t the interval also be a resource? 😉

I think in general the recommendation here should be to let workers finish naturally whenever possible instead of using process.exit(), or using synchronous operations when you need synchronous operations (e.g. using Atomics here).

[RaisinTen]

@RaisinTen Wouldn’t the interval also be a resource? 😉

@addaleax I don't think the Immediate would be an active resource when the callback is run 🤔:

console.log('before', process.getActiveResourcesInfo());
setImmediate(() => console.log('during', process.getActiveResourcesInfo()));
console.log('after', process.getActiveResourcesInfo());

$ ./node test.js
before []
after [
  { type: 'TTYWrap', asyncId: 2, triggerAsyncId: 1 },
  { type: 'Immediate', asyncId: 5, triggerAsyncId: 1 }
]
during [ { type: 'TTYWrap', asyncId: 2, triggerAsyncId: 1 } ]

I think in general the recommendation here should be to let workers finish naturally whenever possible instead of using process.exit(), or using synchronous operations when you need synchronous operations (e.g. using Atomics here).

👍

[addaleax]

I don't think the Immediate would be an active resource when the callback is run 🤔:

This is getting a bit off topic for this issue, but I'd consider that a bug.

[kripken]

Thanks for the info @RaisinTen and @addaleax !

It's possible that with some work Emscripten can avoid calling process.exit() from workers and instead leave that to the main thread.

[sbc100]

FWIW, we work around this in emscripten by using fs.writeSync with 1 or 2 instead of console.error/log to implement our logging functions: https://github.com/emscripten-core/emscripten/blob/995ba815a9ac62b1de2d45b5bbb4b796f051cddb/src/shell.js#L432-L443.

Without this, it makes the use of logging to debug of multi-threaded programs very hard, because normal program stdout/stderr doesn't interleave as expected with log messages.

[avivkeller]

Hey, is it known if the process.exit() is the cause of this, or it worker threads in general (ref: #53701)

[sbc100]

That looks like the same issue yes.

[avivkeller]

I'm aware it looks like the same issue, but is process.exit the core of this issue, or is it the worker_threads.

[sbc100]

I think it stems from the use of worker_threads that don't yield to event loop. Its seems that consecutive console message to not reach the console while you not yielding.

This is very common in emscripten since workers that run pthreads normally never yield to the event loop.

[avivkeller]

Thanks for the insight!