http.Server: close event not fired

[lpinca]

Consider the following example:

'use strict';

var server = require('http').createServer();

server.on('close', function close() {
  console.log('bye');
});

server.on('request', function upgrade() {
  console.log('received a request');
  server.close();
});

server.on('upgrade', function upgrade() {
  console.log('received an upgrade request');
  server.close();
});

server.listen(3000, function listen() {
  var addr = server.address();
  console.log('server listening on %s:%s', addr.address, addr.port);
});

Now simulate an upgrade request and close it when the upgrade event is fired:

macbook:~ luigi$ nc localhost 3000
GET ws://localhost:3000/ HTTP/1.1
Host: localhost
Upgrade: websocket
Connection: Upgrade

^C
macbook:~ luigi$

The process exits but the close event is not fired.

If i use a non upgrade request:

macbook:~ luigi$ nc localhost 3000
GET / HTTP/1.1
User-Agent: curl/7.37.1
Host: localhost:3000
Accept: */*

^C
macbook:~ luigi$

The close event is fired as expected.

[lpinca]

This is the debug output for the upgrade request:

macbook:~ luigi$ NODE_DEBUG=net node server.js
NET: 1798 listen2 0.0.0.0 3000 4 false
NET: 1798 _listen2: create a handle
NET: 1798 bind to 0.0.0.0
server listening on 0.0.0.0:3000
NET: 1798 onconnection
NET: 1798 _read
NET: 1798 Socket._read readStart
NET: 1798 onread undefined 0 34 34
NET: 1798 got data
NET: 1798 onread undefined 48 35 83
NET: 1798 got data
NET: 1798 onread undefined 96 20 116
NET: 1798 got data
NET: 1798 onread undefined 128 1 129
NET: 1798 got data
received an upgrade request
NET: 1798 SERVER _emitCloseIfDrained
NET: 1798 SERVER handle? false   connections? 1
NET: 1798 onread EOF undefined undefined NaN
NET: 1798 EOF
NET: 1798 onSocketEnd { highWaterMark: 16384,
  buffer: [],
  length: 0,
  pipes: null,
  pipesCount: 0,
  flowing: false,
  ended: true,
  endEmitted: false,
  reading: false,
  calledRead: true,
  sync: false,
  needReadable: true,
  emittedReadable: false,
  readableListening: false,
  objectMode: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null }
macbook:~ luigi$

This is the debug output for the non upgrade request:

macbook:~ luigi$ NODE_DEBUG=net node server.js
NET: 1805 listen2 0.0.0.0 3000 4 false
NET: 1805 _listen2: create a handle
NET: 1805 bind to 0.0.0.0
server listening on 0.0.0.0:3000
NET: 1805 onconnection
NET: 1805 _read
NET: 1805 Socket._read readStart
NET: 1805 onread undefined 0 60 60
NET: 1805 got data
NET: 1805 onread undefined 64 12 76
NET: 1805 got data
NET: 1805 onread undefined 80 1 81
NET: 1805 got data
received a request
NET: 1805 SERVER _emitCloseIfDrained
NET: 1805 SERVER handle? false   connections? 1
NET: 1805 onread EOF undefined undefined NaN
NET: 1805 EOF
NET: 1805 onSocketEnd { highWaterMark: 16384,
  buffer: [],
  length: 0,
  pipes: null,
  pipesCount: 0,
  flowing: false,
  ended: true,
  endEmitted: false,
  reading: false,
  calledRead: true,
  sync: false,
  needReadable: true,
  emittedReadable: false,
  readableListening: false,
  objectMode: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null }
NET: 1805 onSocketFinish
NET: 1805 oSF: ended, destroy { highWaterMark: 16384,
  buffer: [],
  length: 0,
  pipes: null,
  pipesCount: 0,
  flowing: false,
  ended: true,
  endEmitted: true,
  reading: false,
  calledRead: true,
  sync: false,
  needReadable: false,
  emittedReadable: true,
  readableListening: false,
  objectMode: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null }
NET: 1805 destroy undefined
NET: 1805 destroy
NET: 1805 close
NET: 1805 close handle
NET: 1805 has server
NET: 1805 SERVER _emitCloseIfDrained
NET: 1805 SERVER: emit close
bye
NET: 1805 emit close
macbook:~ luigi$

[chrisdickinson]

Which version of Node did you notice this on? What operating system are you running? I haven't been able to reproduce against v0.11.15-pre or v0.10.33.

[lpinca]

@chrisdickinson tested it on Linux (v0.10.32) and OS X (v0.10.33)

[lpinca]

Just tried with v0.11.14 (OS X) still no close event

macbook:~ luigi$ node server.js 
server listening on :::3000
received an upgrade request
macbook:~ luigi$

macbook:~ luigi$ nc localhost 3000
GET ws://localhost:3000/ HTTP/1.1
Host: localhost
Upgrade: websocket
Connection: Upgrade

^C
macbook:~ luigi$ node -v
v0.11.14
macbook:~ luigi$

[lpinca]

The issue seems to be caused by the fact that the socket has the allowHalfOpen flag set to true.
When the client sends the FIN packet the socket is still writable https://github.com/joyent/node/blob/v0.10.33-release/lib/net.js#L411, so the close event is not emitted.

I'm not sure why the process exits.

[chrisdickinson]

With node v0.10.33 / OSX 10.10 I get:

$ NODE_DEBUG=net node test.js
NET: 39031 listen2 0.0.0.0 3000 4 false
NET: 39031 _listen2: create a handle
NET: 39031 bind to 0.0.0.0
server listening on 0.0.0.0:3000
NET: 39031 onconnection
NET: 39031 _read
NET: 39031 Socket._read readStart
NET: 39031 onread undefined 0 34 34
NET: 39031 got data
NET: 39031 onread undefined 48 16 64
NET: 39031 got data
NET: 39031 onread undefined 64 19 83
NET: 39031 got data
NET: 39031 onread undefined 96 20 116
NET: 39031 got data
NET: 39031 onread undefined 128 1 129
NET: 39031 got data
received an upgrade request
NET: 39031 SERVER _emitCloseIfDrained
NET: 39031 SERVER handle? false   connections? 1
NET: 39031 onread ECONNRESET undefined undefined NaN
NET: 39031 error ECONNRESET
NET: 39031 destroy
NET: 39031 close
NET: 39031 close handle
NET: 39031 has server
NET: 39031 SERVER _emitCloseIfDrained
NET: 39031 destroy { [Error: read ECONNRESET] code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }
NET: 39031 destroy
NET: 39031 already destroyed, fire error callbacks
NET: 39031 SERVER: emit close
bye
NET: 39031 emit close

With node v0.11.15-pre I get:

$ NODE_DEBUG=net ./node test.js
NET 38971: listen2 null 3000 4 false
NET 38971: _listen2: create a handle
NET 38971: bind to anycast
server listening on :::3000
NET 38971: onconnection
NET 38971: _read
NET 38971: Socket._read readStart
NET 38971: onread 34
NET 38971: got data
NET 38971: _read
NET 38971: onread 16
NET 38971: got data
NET 38971: _read
NET 38971: onread 19
NET 38971: got data
NET 38971: _read
NET 38971: onread 20
NET 38971: got data
NET 38971: _read
NET 38971: onread 1
NET 38971: got data
received an upgrade request
NET 38971: SERVER _emitCloseIfDrained
NET 38971: SERVER handle? false   connections? 1
NET 38971: _read
NET 38971: onread -54
NET 38971: destroy
NET 38971: close
NET 38971: close handle
NET 38971: has server
NET 38971: SERVER _emitCloseIfDrained
NET 38971: destroy { [Error: read ECONNRESET] code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }
NET 38971: destroy
NET 38971: already destroyed, fire error callbacks
NET 38971: SERVER: emit close
bye
NET 38971: emit close

Both given the input:

$ nc localhost 3000
GET ws://localhost:3000/ HTTP/1.1
Host: localhost
Upgrade: websocket
Connection: Upgrade

^C

This is strange indeed -- I'm definitely seeing the "bye" text on both versions. What version of OSX are you testing against? Linux distro/version?

[lpinca]

OS X 10.10.1 and CentOS 7, this is definitely strange.

[lpinca]

We have different results. This is what i get:

NET: 2622 SERVER handle? false   connections? 1
NET: 2622 onread EOF undefined undefined NaN

and this is what you get:

NET: 39031 SERVER handle? false   connections? 1
NET: 39031 onread ECONNRESET undefined undefined NaN

[3rd-Eden]

Getting exactly the same results as @lpinca on Mac OSX 10.10.1 node v0.10.33;

NET: 12917 listen2 0.0.0.0 3000 4 false
NET: 12917 _listen2: create a handle
NET: 12917 bind to 0.0.0.0
server listening on 0.0.0.0:3000
NET: 12917 onconnection
NET: 12917 _read
NET: 12917 Socket._read readStart
NET: 12917 onread undefined 0 69 69
NET: 12917 got data
NET: 12917 onread undefined 80 20 100
NET: 12917 got data
NET: 12917 onread undefined 112 1 113
NET: 12917 got data
received an upgrade request
NET: 12917 SERVER _emitCloseIfDrained
NET: 12917 SERVER handle? false   connections? 1
NET: 12917 onread EOF undefined undefined NaN
NET: 12917 EOF
NET: 12917 onSocketEnd { highWaterMark: 16384,
  buffer: [],
  length: 0,
  pipes: null,
  pipesCount: 0,
  flowing: false,
  ended: true,
  endEmitted: false,
  reading: false,
  calledRead: true,
  sync: false,
  needReadable: true,
  emittedReadable: false,
  readableListening: false,
  objectMode: false,
  defaultEncoding: 'utf8',
  ranOut: false,
  awaitDrain: 0,
  readingMore: false,
  decoder: null,
  encoding: null }

[lpinca]

@chrisdickinson let me know if you can reproduce it with this test case.

[misterdjules]

I was also able to reproduce this issue with node built from the v0.10 and v0.12 branches.

http.Server sets for every connection a callback that is called when EOF is read. This callback ends the write side of the socket. When the write side of the socket is closed, the socket is destroyed and the http.Server.close event is emitted if it was the last connection that has handled by this server.

However, when an "upgrade" HTTP request is received, http.Server clears the callback that ends the write side when EOF is read on the socket. As a result the socket is not destroyed and the http.Server.close event is not emitted. My understanding is that after an "upgrade" request is received, the http.Server instance considers that this socket is somewhat "independent" and it should be handled by the listener(s) of the "upgrade" event.

If in the original sample code, we write the upgrade event listener like following:

server.on('upgrade', function upgrade(request, socket) {
  console.log('received an upgrade request');
  socket.end();
  server.close();
});

the "correct" sequence of events happen, and the message "bye" is written to the console.

What makes the node process exit before the close event is emitted on http.Server is that, when EOF is read on the socket, the underlying libuv stream is removed from the active handles. The event loop then doesn't have any active handle, since the http.Server's listening handle was also closed with the call to server.close(), and it doesn't block node anymore, which can exit.

I'm not sure how to fix that, but hopefully this provides some useful information regarding what's going on.

[lpinca]

What makes the node process exit before the close event is emitted on http.Server is that, when EOF is read on the socket, the underlying libuv stream is removed from the active handles.

At least now i understand why the process exits, thank you for this @misterdjules.

[glasser]

So does every upgrade handler need to set onend on its socket or something?