Possible bug in streams between node 8.1.4 and 8.2.0

[SimenB]

• Version: 8.1.4 & 8.2.0
• Platform: MacOS
• Subsystem: Streams (or http?)

We have some code which uses pump, and between 8.1.4 and 8.2.0 the handler in certain cases stopped being called with an error. We have a test that our error handler is invoked correctly, which fails on newer versions of node.

In 8.1.4 we hit https://github.com/mafintosh/end-of-stream/blob/0ae1658b8167596fafbb9195363ada3bc5a3eaf2/index.js#L44, whilst in 8.2.0 (and later) we don't.

I've created a repository with reproduction code.

https://github.com/SimenB/node-stream-repro

[targos]

@nodejs/streams

[SimenB]

Is this #14024?

[targos]

That seems like a good candidate.

[SimenB]

Our code for this particular case is really hairy, so if it was an actual bug, and the fix is backported to 6, I'll with great joy remove our current handling of it 🙂

[mcollina]

Can you please verify with 8.4.0?

[SimenB]

8.2.0, 8.2.1, 8.3.0 and 8.4.0 all behave the same

[SimenB]

6.11.2, 7.11.1, 8.0.0, 8.1.0 and 8.1.4 also behave the same, FWIW. So something changed between 8.1.4 and 8.2.0

[trygve-lie]

So fare I see: Under the hood, pump uses end-of-stream. In version 8.1.4 and older end-of-stream get a close event from the underlaying stream (which then are used to throw an Error further up). In version 8.2.0 and newer end-of-stream get a finish event from the underlaying stream.

[mcollina]

I think the bug is more subtle than this. I would like not to revert #14024, and figure out what events changed.

Can you reproduce the bug without Express and got?

[SimenB]

I've pushed usage of request instead of fetch. Never used got (it's get from http). Can look into removing express on Monday

[mcollina]

I meant, can you just show this using node core?

[SimenB]

@mcollina I've reduced the example down to just http and pump

[trygve-lie]

Here is a stipped down version:

const { get, createServer } = require('http');

let external;

// Http server
createServer((req, res) => {
    res.writeHead(200);
    setTimeout(() => {
        external.abort();
        res.end('Hello World\n');
    }, 1000);
}).listen(3000);

// Proxy server
createServer((req, res) => {
    get('http://127.0.0.1:3000', inner => {
        res.on('close', () => {
            console.log('response writable:', res.writable);
        });
        inner.pipe(res);
    });
}).listen(3001, () => {
    external = get('http://127.0.0.1:3001');
});

What happens here is that we (external) do a request to a server (proxy server) which stream data through from a second server (http serve) and we terminate the request before the stream is done. A real use case for this is ex a user hitting the stop button in the browser while the server is still piping data to it.

If one run the above in node 8.1.4 or older, response writable: true will be printed. If one run the above in node 8.2.0 or newer, response writable: false will be printed.

In other words; in node 8.1.4 and older it seems like the writable response stream was writable after a close event. This would again create a problem where the stream could be written too after it was closed.

To me this looks like a fixed bug in node 8.2.0 and not a new bug. What make it looks like a bug is that libraries such as end-of-stream and pump suddenly stopped providing error objects on the above scenario between two versions of node.

If anyone can confirm that the above behaviour is correct (the response should not be writable after a close event), I'll be happy to report this to end-of-stream and pump so they can account for this change between the node versions.

[trygve-lie]

This is a result of #14024 which went into 8.2.0.

This issue can be closed.

[SimenB]

Feel free to close if our analysis is correct (and the change in behavior is intended)

[mcollina]

Is there a way we can keep the existing behavior of pump and eos, and keep this change in?

I'm a bit lost on the Error issue: why the Error is not bubbling up?

[SimenB]

FWIW I think this new behavior is correct, and the error vi got from eos in older versions of node just exposed the bug that #14024 fixed.

Although it might be expected to get an error of some sort (write after end?), since we are trying to write to a closed stream, aren't we?

[trygve-lie]

The stream are terminated prematurelly in all versions. In node 8.1.4 and older eos (pump have this "error" inheritated from eos) ends with an error object telling us that. In 8.2.0 eos ends with no error so in newer versions we really do not know that the stream was terminated prematurelly.

I am not sure how eos will be able to figure this out now. I created an issue on it: mafintosh/end-of-stream#14

[mcollina]

@trygve-lie I understand the problem now. pump is calling .end()  on the response, causing res.writable to go to false. This prevents eos  to call the callback with the error.

I think it's a bug in core. stream.Writable sets ws.writable = false after emitting 'finish' , while OutgoingMessage sets ws.writable = true before emitting 'finish'.

[mcollina]

I was absolutely wrong in what I said. What's happening is clear to me, but not how to fix this and maintain #14024. I'll be reverting that asap.

[jasnell]

Reverting #14024 and revisiting it later looks like the only viable path forward on this.

[SimenB]

What's happening is clear to me

I'm curios, could you expand on that?

EDIT: Done in #15404 (comment), so no need to do so here. Thanks!