Workers only pipe one message to stdout before they stop running

[realriccio]

Version

22.4.0 (i also tried earlier versions and the bug is always present)

Platform

Both in Linux and Windows, all OS versions.

Subsystem

worker_threads

What steps will reproduce the bug?

const { Worker } = require("worker_threads");

let worker = new Worker(`function print_three_and_work(){
	console.log("a");
	console.log("b");
	console.log("c");

	while(true){}
}

print_three_and_work();`, {eval: true});

or

const { Worker } = require("worker_threads");

let worker = new Worker(`function print_three_and_work(){
	console.log("a");
	console.log("b");
	console.log("c");

	while(true){}
}

print_three_and_work();`, {eval: true, stdout: true});

worker.stdout.on("data", function(chunk){
	process.stdout.write(chunk);
});

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

It always happens.

What is the expected behavior? Why is that the expected behavior?

All logged messages should be piped to the main thread's stdout while the worker is running.

What do you see instead?

Only the first message is piped. All other messages are not piped while the worker is running. They get piped all at once once the worker stops running.

(I see "a" instead of seeing "a \n b \n c".)

Additional information

#40961

I believe this other issue has a similar problem but it was misunderstood as having something to do with "process.exit", while instead it must be because of something else.

[avivkeller]

@nodejs/workers

---

Possible duplicate of #40961

[climba03003]

Not really the duplicate of #40961
It is known that console is async operation and while (true) block all the async I/O.
So, it never been possible for the write operation to run.

If we turns in something that hold the Worker but allows async I/O. It works as expected.

import { Worker } from 'node:worker_threads';

let worker = new Worker(`function print_three_and_work(){
  console.log("a");
  console.log("b");
  console.log("c");
  
  // hold the thread, but allow async I/O
  setTimeout(() => {}, 1000)
}

print_three_and_work();`, {eval: true, stdout: true});

worker.stdout.on("data", function(chunk){
  process.stdout.write(chunk);
});

Or use sync operation and write to fd.

import { Worker } from 'node:worker_threads';

let worker = new Worker(`
const { writeSync } = require('node:fs')
function print_three_and_work(){
  writeSync(1, "a\\n")
  writeSync(1, "b\\n")
  writeSync(1, "c\\n")

  while(true) {}
}

print_three_and_work();`, {eval: true, stdout: true});

worker.stdout.on("data", function(chunk){
  process.stdout.write(chunk);
});

[realriccio]

Why is there such a difference between the behaviour of console.log inside of workers and on the main thread? If i run the same function normally instead of giving it to a worker, it works at expected (if it didn't this weird behaviour would have been noticed by many before me):

Code:

function print_three_and_work(){
	console.log("a");
	console.log("b");
	console.log("c");

	while(true){}
}

print_three_and_work();

Output:

a
b
c

[climba03003]

As stated inside the linked issue.
console inside Worker is always async I/O, but main thread is not guarantee to be sync or async.

So, if the result is printed right away, that means it is sync right now.

[realriccio]

Oh ok, i didn't know that, thanks. Is there a way to force the console to flush all messages before continuing with sync work?

[climba03003]

You should use fs.writeSync if you need consistent result.
You can write to the fd: 1 for stdout.

[mcollina]

I recommend using console.log() only for debugging and not in any production scenario.

Use pino for logging. Internally, it uses sonic-boom. Both can be set up to log synchronously, like so:

const pino = require('pino')
const logger = pino(pino.destination({
  dest: 1, // stdout
  sync: true // Synchronous logging
}))

logger.info({ foo: 'bar' }, 'my message from %s', 'Italy')