difference in broken pipe behaviour for console.log() & process.stdout.write()

[alexlamsl]

What version of Bun is running?

--canary

What platform is your computer?

Linux 5.15.0-56-generic x86_64 x86_64

What steps can reproduce the bug?

$ cat test.js
require("child_process").exec(process.argv.slice(2).join(" "), (err) => {
  if (err) console.error(err.code, err.killed, err.signal);
}).stdout.destroy();

$ cat console.js
console.log("testing");

$ cat stdout.js
process.stdout.write("testing\n");

What is the expected behavior?

$ node test.js node stdout.js
1 false null
$ node test.js bun stdout.js
1 false null
$ bun test.js node stdout.js
1 false null
$ bun test.js bun stdout.js
1 false null

$ node test.js node console.js
$ node test.js bun console.js
$ bun test.js node console.js
$ bun test.js bun console.js

What do you see instead?

$ node test.js node stdout.js
1 false null
$ node test.js bun stdout.js
$ bun test.js node stdout.js
1 false null
$ bun test.js bun stdout.js

$ node test.js node console.js
$ node test.js bun console.js
141 false null
$ bun test.js node console.js
$ bun test.js bun console.js
141 false null

Additional information

Discovered while investigating bun wiptest failures in:

bun/test/bun.js/child_process-node.test.js

Lines 200 to 258 in 79abd24

	describe("ChildProcess spawn bad stdio", () => {
	// Monkey patch spawn() to create a child process normally, but destroy the
	// stdout and stderr streams. This replicates the conditions where the streams
	// cannot be properly created.
	function createChild(options, callback, done) {
	var __originalSpawn = ChildProcess.prototype.spawn;
	ChildProcess.prototype.spawn = function () {
	const err = __originalSpawn.apply(this, arguments);
	this.stdout.destroy();
	this.stderr.destroy();
	return err;
	};
	const { mustCall } = createCallCheckCtx(done);
	const cmd = `bun ${__dirname}/spawned-child.js`;
	const child = exec(cmd, options, mustCall(callback));
	ChildProcess.prototype.spawn = __originalSpawn;
	return child;
	}
	it("should handle normal execution of child process", (done) => {
	createChild(
	{},
	(err, stdout, stderr) => {
	strictEqual(err, null);
	strictEqual(stdout, "");
	strictEqual(stderr, "");
	},
	done,
	);
	});
	it("should handle error event of child process", (done) => {
	const error = new Error("foo");
	createChild(
	{},
	(err, stdout, stderr) => {
	strictEqual(err, error);
	strictEqual(stdout, "");
	strictEqual(stderr, "");
	},
	done,
	);
	});
	it("should handle killed process", (done) => {
	createChild(
	{ timeout: 1 },
	(err, stdout, stderr) => {
	strictEqual(err.killed, true);
	strictEqual(stdout, "");
	strictEqual(stderr, "");
	},
	done,
	);
	});
	});

[alexlamsl]

Discrepancies in behaviour can be observed without any .destroy():

$ cat exec.js
const child = require("child_process").exec(process.argv.slice(2).join(" "));

child.stdin.on("close", () => {
  console.log("stdin CLOSED");
}).on("end", () => {
  console.log("stdin ENDED");
}).on("error", (err) => {
  console.error("stdin", err);
}).end("foo\nbar\n");

child.stdout.on("data", data => {
  console.log(data);
}).on("close", () => {
  console.log("stdout CLOSED");
}).on("end", () => {
  console.log("stdout ENDED");
}).on("error", (err) => {
  console.error("stdout", err);
});

$ cat grep.js
const filter = process.argv[2];
let result = "";
process.stdin.setEncoding("utf8").on("data", data => {
  result += data;
}).on("end", () => {
  result.split(/\n/).filter(line => line.indexOf(filter) >= 0).forEach(line => {
    process.stdout.write(line + "\n");
  });
});

Added native binary grep into the mix, since it causes bun to fail differently as well:

$ node exec.js grep o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED
$ node exec.js node grep.js o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED
$ node exec.js bun grep.js o
stdin CLOSED
stdout ENDED
stdout CLOSED

Observe above that output from bun child is missing (lack of end event from process.stdin)

$ bun exec.js grep o
stdin CLOSED
$ bun exec.js node grep.js o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED
$ bun exec.js bun grep.js o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED

While bun failed to wait long enough to read from grep, it curiously managed to cause its bun child to end its process.stdin properly.

[Jarred-Sumner]

This reads like an event loop queue order bug

process.nextTick is currently the same as queueMicrotask with extra optional arguments to propagate

As a quick test, if you reassign process.nextTick to (cb, ...args) => setTimeout(cb, 0, undefined, ...args) does the behavior change?

[alexlamsl]

--- a/src/bun.js/streams.exports.js
+++ b/src/bun.js/streams.exports.js
@@ -105,7 +105,7 @@ var __copyProps = (to, from, except, desc) => {
   return to;
 };
 
-var runOnNextTick = process.nextTick;
+var runOnNextTick = (cb, ...args) => setTimeout(cb, 0, undefined, ...args);
 
 function isReadableStream(value) {
   return (

$ export BUN_OVERRIDE_MODULE_PATH=/path/to/bun/repo

No luck on the child (grep.js):

$ node exec.js bun grep.js o
stdin CLOSED
stdout ENDED
stdout CLOSED

RUD with parent (exec.js):

$ bun exec.js grep o
4326 |         }
4327 |       }
4328 |     }
4329 |     function finish(stream, state) {
4330 | 
4331 |       state.pendingcb--;
         ^
TypeError: undefined is not an object (evaluating 'state.pendingcb')
      at finish (node:stream:4331:6)
foo

2154 |       emitErrorNT(self, err);
2155 |       emitCloseNT(self);
2156 |     }
2157 |     function emitCloseNT(self) {
2158 | 
2159 |       const r = self._readableState;
                   ^
TypeError: undefined is not an object (evaluating 'self._readableState')
      at emitCloseNT (node:stream:2159:16)
3705 |           state.length,
3706 |           stream.__id,
3707 |         );
3708 |       if (
3709 | 
3710 |         !state.errored &&
            ^
TypeError: undefined is not an object (evaluating 'state.errored')
      at endReadableNT (node:stream:3710:9)
3705 |           state.length,
3706 |           stream.__id,
3707 |         );
3708 |       if (
3709 | 
3710 |         !state.errored &&
            ^
TypeError: undefined is not an object (evaluating 'state.errored')
      at endReadableNT (node:stream:3710:9)

[alexlamsl]

Also tried:

var runOnNextTick = (cb, ...args) => setTimeout(cb, 0, ...args);

var runOnNextTick = setImmediate;

without any (further) changes in behaviour.

[Jarred-Sumner]

what about setTimeout(1)

[alexlamsl]

This is slightly incorrect

Are you sure about that? 🤔

https://developer.mozilla.org/en-US/docs/Web/API/setTimeout

Syntax

setTimeout(functionRef, delay, param1, param2, /* … ,*/ paramN)

https://nodejs.org/dist/latest-v18.x/docs/api/timers.html#settimeoutcallback-delay-args

setTimeout(callback[, delay[, ...args]])

• callback | The function to call when the timer elapses.
• delay | The number of milliseconds to wait before calling the callback. Default: 1.
• ...args | Optional arguments to pass when the callback is called.

$ echo 'setTimeout(console.log, 0, "arg1", "arg2")' | node
arg1 arg2

[alexlamsl]

Tried var runOnNextTick = (cb, ...args) => setTimeout(cb, 100, ...args);

$ bun exec.js grep o
foo

4326 |         }
4327 |       }
4328 |     }
4329 |     function finish(stream, state) {
4330 | 
4331 |       state.pendingcb--;
         ^
TypeError: undefined is not an object (evaluating 'state.pendingcb')
      at finish (node:stream:4331:6)
2154 |       emitErrorNT(self, err);
2155 |       emitCloseNT(self);
2156 |     }
2157 |     function emitCloseNT(self) {
2158 | 
2159 |       const r = self._readableState;
                   ^
TypeError: undefined is not an object (evaluating 'self._readableState')
      at emitCloseNT (node:stream:2159:16)
3705 |           state.length,
3706 |           stream.__id,
3707 |         );
3708 |       if (
3709 | 
3710 |         !state.errored &&
            ^
TypeError: undefined is not an object (evaluating 'state.errored')
      at endReadableNT (node:stream:3710:9)
3705 |           state.length,
3706 |           stream.__id,
3707 |         );
3708 |       if (
3709 | 
3710 |         !state.errored &&
            ^
TypeError: undefined is not an object (evaluating 'state.errored')
      at endReadableNT (node:stream:3710:9)

Notice that foo on the first line − it's actually there in #1632 (comment) too, just appear in a different order (after the first trace)

[Jarred-Sumner]

This is slightly incorrect

Are you sure about that? 🤔

No, I was wrong. I didn't see the comment above it before sending comment

TypeError: undefined is not an object (evaluating 'state.pendingcb')
at finish (node:stream:4331:6)

i wonder if this means we are missing a this binding somewhere

[alexlamsl]

That's odd then, since all the runOnNextTick() calls seem to be passing the correct values:

var runOnNextTick = (cb, ...args) => {
  console.log(cb.name, args[0] != null, args[1] != null);
  setTimeout(cb, 0, ...args);
};

$ bun exec.js grep o
finish true true
emitCloseNT true false
4329 |         }
4330 |       }
4331 |     }
4332 |     function finish(stream, state) {
4333 | 
4334 |       state.pendingcb--;
         ^
TypeError: undefined is not an object (evaluating 'state.pendingcb')
      at finish (node:stream:4334:6)
foo

endReadableNT true true
endReadableNT true true
2157 |       emitErrorNT(self, err);
2158 |       emitCloseNT(self);
2159 |     }
2160 |     function emitCloseNT(self) {
2161 | 
2162 |       const r = self._readableState;
                   ^
TypeError: undefined is not an object (evaluating 'self._readableState')
      at emitCloseNT (node:stream:2162:16)
3708 |           state.length,
3709 |           stream.__id,
3710 |         );
3711 |       if (
3712 | 
3713 |         !state.errored &&
            ^
TypeError: undefined is not an object (evaluating 'state.errored')
      at endReadableNT (node:stream:3713:9)
3708 |           state.length,
3709 |           stream.__id,
3710 |         );
3711 |       if (
3712 | 
3713 |         !state.errored &&
            ^
TypeError: undefined is not an object (evaluating 'state.errored')
      at endReadableNT (node:stream:3713:9)

[alexlamsl]

after working around #1633:

--- a/src/bun.js/streams.exports.js
+++ b/src/bun.js/streams.exports.js
@@ -105,7 +105,11 @@ var __copyProps = (to, from, except, desc) => {
   return to;
 };
 
-var runOnNextTick = process.nextTick;
+var runOnNextTick = (cb, ...args) => {
+  setTimeout(() => {
+    cb(...args);
+  }, 0);
+};
 
 function isReadableStream(value) {
   return (

No changes to the child (grep.js) case, obviously:

$ node exec.js grep o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED
$ node exec.js node grep.js o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED
$ node exec.js bun grep.js o
stdin CLOSED
stdout ENDED
stdout CLOSED

However, the behaviour in the parent (exec.js) case is now consistent, albeit the order of stdin CLOSED has changed:

$ bun exec.js grep o
foo

stdin CLOSED
stdout ENDED
stdout CLOSED
$ bun exec.js node grep.js o
foo

stdin CLOSED
stdout ENDED
stdout CLOSED
$ bun exec.js bun grep.js o
foo

stdin CLOSED
stdout ENDED
stdout CLOSED

[alexlamsl]

Changing the timeout from 0 to 100 consistently changes the order of stdin CLOSED in this particular case further:

$ bun exec.js node grep.js o
foo

stdout ENDED
stdin CLOSED
stdout CLOSED

[alexlamsl]

Using Bun's API for the child, with more logging:

$ cat grep-bun.js
const filter = process.argv[2];
try {
  for await (const line of console) {
    if (line.indexOf(filter) >= 0) console.log(line);
  }
} catch (err) {
  console.log("grep ERROR");
  console.log(err);
}

Reason for the missing output when parent is node becomes apparent:

$ node exec.js bun grep-bun.js o
stdin CLOSED
grep ERROR


1 | const filter = process.argv[2];
2 | try {
3 |   for await (const line of console) {
                       ^
EINVAL: Invalid argument
syscall: "fstat"
  errno: -22

      at /home/alexlamsl/grep-bun.js:3:19


stdout ENDED
stdout CLOSED

Whereas if bun is the parent, we don't run into the same issue:

$ bun exec.js bun grep-bun.js o
stdin CLOSED
foo

stdout ENDED
stdout CLOSED