Node: 'close' event called before 'end' in paused stream

[DiegoTUI]

• v8.9.4:
• Linux tufopad 4.13.0-32-generic #35~16.04.1-Ubuntu SMP Thu Jan 25 10:13:43 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux:
• stream:

I believe I've found an akward behaviour of a stream in paused mode using the net module. In some specific cases, when the source socket ends, the close event is called before the end event in the destination socket. I've been able to reproduce it simulating the callback queue with nested setImmediates.

Server

'use strict';

const net = require('net');    

let n=0;                       

const opts = {                 
  host: '127.0.0.1',
  port: 1100
};

const server = net.createServer(s => {
  let id = n++;                
  s.setEncoding('utf8');       
  s.on('readable', () => {
    setImmediate(() => 
      setImmediate(() => 
        setImmediate(() =>
          setImmediate(() => s.read()))));
  });
  s.on('end', () => console.trace(`Socket ${id} END`));
  s.on('close', () => console.trace(`Socket ${id} CLOSE`));
});

server.listen(opts, console.info.bind(null, 'server listening', opts));

I've tried with two clients.

Client 1 (bash)
$ echo EVENT | nc localhost 1100

Client 2 (node)

'use strict';

const net = require('net');

let n=0;

function runOnce() { 
  const s = net.connect(1100, () => { 
    console.info('Connected', n++);
    s.write('EVENT', () => { 
      s.end();
    });
  });
  return new Promise(ok => { 
    s.on('close', ok)
  })
}

async function run(times) {
  for (let i=0; i<times; i++) { 
    await runOnce();
  }
}

run(10);

It consistently "fails" with both, "fail" meaning that the close event is called before the end event. According to the documentation this should never happen.

The 'close' event is emitted when the stream and any of its underlying resources (a file descriptor, for example) have been closed. The event indicates that no more events will be emitted, and no further computation will occur.

NOTE: The number of setImmediates that you need to nest in order to make it "fail" may vary depending on your environment.

[rohanraj7316]

end event triggers at the ending of the readable side of the socket execute completely.
so, it's not necessary that trigger of close and end events should be sequential.
@DiegoTUI

[DiegoTUI]

@rohanraj7316 but according to the docs, once the close event is emitted, no more events are emitted, right? It seems that in this case, the end event is emitted after the close event contradicting the docs.

[richardlau]

cc @nodejs/streams

[rohanraj7316]

can you share the link pls @DiegoTUI

[DiegoTUI]

@rohanraj7316 you mean the link to the docs? Here it is:
https://nodejs.org/dist/latest-v9.x/docs/api/stream.html#stream_event_close_1

[rohanraj7316]

Since we have multiple phases in the Node js event loop.
Close event is not behaving in the way you are
expecting it to be because of the absence of stream callback.

When we say event loop there are multiple phases of Event Loop cycle
all the callback corresponding to given event are present in that phase.
but since you are adding the listener to the net modules object it is acting
according to the net modules close and end callbacks. I guess this can
be one of the possible reason. for more details regarding the behavior of
event you can go through this link
@DiegoTUI

[DiegoTUI]

@rohanraj7316 If I understood correctly, you are suggesting that the fact that the end and close events come in the wrong order could be due to the fact that I am listening to the end and close events of a net.Socket, and not of a "pure" stream. It doesn't make a lot of sense to me because a Socket is a Duplex stream, and it seems that it relies in the stream's event to produce his own events. The docs of the Socket close event are also pretty clear about this:

Emitted once the socket is fully closed. The argument had_error is a boolean which says if the socket was closed due to a transmission error.

If the close event is emitted, then the socket is fully closed. It doesn't make any sense that the end event is emitted after the socket is fully closed.

[mcollina]

I _think_ this is a bug. It also goes back to Node 4 _at least_.