HTTP parser premature close

[awwright]

• Version: v12.10.0
• Platform: macOS
• Subsystem: http, stream

I'm running across an issue where when no response data is written during the "request" event call, the HTTP handling either closes the response without sending any apparent reply, or sends a Connection: close response but doesn't end the stream.

This is a strange behavior that I can't find an explanation for and I can't come up with any workaround; so I think this is a bug.

Case 1

"use strict";
const http = require('http');
const makeDuplexPair = require('./test/common/duplexpair.js');

const message = 'GET / HTTP/1.1\r\nHost: example.com\r\nConnection: close\r\n\r\n';
const server = http.createServer(function(req, res){
	console.log('Have request: ', req.method, req.url);
	req.resume();
	req.once('end', function(){
		console.log('(request end)');
		res.end('Fin\r\n');
	});
});

const {clientSide, serverSide} = makeDuplexPair();
clientSide.end(message);
clientSide.pipe(process.stdout);
clientSide.once('end', function(){ console.log('(Connection closed)'); });

server.emit('connection', serverSide);

Actual:

Have request:  GET /
(request end)
(Connection closed)

I expect to see the HTTP response output, but the connection simply closes.

Case 2 (using clientSide.write instead of clientSide.end)

"use strict";
const http = require('http');
const makeDuplexPair = require('./test/common/duplexpair.js');

const message = 'GET / HTTP/1.1\r\nHost: example.com\r\nConnection: close\r\n\r\n';
const server = http.createServer(function(req, res){
	console.log('Have request: ', req.method, req.url);
	req.resume();
	req.once('end', function(){
		console.log('(request end)');
		res.end('Fin\r\n');
	});
});

const {clientSide, serverSide} = makeDuplexPair();
clientSide.write(message);
clientSide.pipe(process.stdout);
clientSide.once('end', function(){ console.log('(Connection closed)'); });

server.emit('connection', serverSide);

I expect to see (Connection closed) at the end, but I do not.

Actual:

Have request:  GET /
(request end)
HTTP/1.1 200 OK
Date: Thu, 19 Sep 2019 01:01:49 GMT
Connection: close
Content-Length: 5

Fin

In one or the other case I expect:

Have request:  GET /
(request end)
HTTP/1.1 200 OK
Date: Thu, 19 Sep 2019 01:01:49 GMT
Connection: close
Content-Length: 5

Fin
(Connection closed)

As far as I can tell, there's no way to do this.

[awwright]

This might also be an interaction with streams and/or the test's makeDuplexPair implementation, since this works:

const serverSide = new Duplex;
serverSide._read = function(){};
serverSide._write = function(chunk, enc, cb){
	console.log(chunk.toString());
	cb();
};
serverSide._final = function(){
	console.log('(Connection close)');
}
serverSide.push(message);

producing the expected output:

Have request:  GET /
(request end)
HTTP/1.1 200 OK
Date: Thu, 19 Sep 2019 23:12:37 GMT
Connection: close
Content-Length: 5

Fin


(Connection close)

Adding serverSide.push(null);, however, does not:

Have request:  GET /
(Connection close)
(request end)

[awwright]

Case 2 works as expected in Node.js v10.16.3:

$ ./bin/node -v
v10.16.3
$ ./bin/node ./test.js 
Have request:  GET /
(request end)
HTTP/1.1 200 OK
Date: Thu, 19 Sep 2019 23:37:58 GMT
Connection: close
Content-Length: 5

Fin
(Connection closed)

[awwright]

git bisect says

206ae31 is the first bad commit

This is PR #27709 fixing issue #22066

[awwright]

I suspect this is a bad interaction between multiple components:

• In

  node/lib/_stream_readable.js

  Line 626 in 1fa4037

  function maybeReadMore_(stream, state) {

  if the assignment to readingMore happens at the top instead of at the bottom, the issue appears to go away

• In

  node/lib/_stream_readable.js

  Line 274 in 1fa4037

  } else if (state.objectMode || chunk && chunk.length > 0) {

  if the test for length is removed (or made chunk.length >= 0), the issue appears to go away (but fails other tests)

• This does not appear to happen if sending in chunked mode, and happens when OutgoingMessage#end flushes the output by writing a blank string, where the callback never gets called

  node/lib/_http_outgoing.js

  Line 748 in 1fa4037

  this._send('', 'latin1', finish);

[ronag]

Just pinging myself here. I'll take a look later this to see if I can help make sense of this one.

[awwright]

It appears this is caused by an underlying bug in streams and/or the duplex pair implementation:

'use strict';

const common = require('./test/common');
const makeDuplexPair = require('./test/common/duplexpair');

const { clientSide, serverSide } = makeDuplexPair();

serverSide.resume();
serverSide.on('end', function(buf){
  serverSide.write('out');
  serverSide.write('');
  serverSide.end();
});

clientSide.end();

clientSide.on('data', function(m){
  console.log(m.toString());
});
clientSide.on('end', common.mustCall(function(){
  console.log('(Connection closed)');
}));

Expected:

out
(Connection closed)

Actual:

out
Mismatched function calls. Expected exactly 1, actual 0.

A write call (empty or non-empty) followed by an empty write call causes this; note how removing either of the calls works around the bug.

This isn't related to HTTP so I'm not sure if/when this was ever introduced, I'll spin up a "git bisect" job soon.

[awwright]

This has been around since at least v10.16.3

[awwright]

As far as I can tell the bug I'm encountering isn't "http" related, so I've opened #29758