http_server: correct order prefinish=>finish

[indutny]

It is very important to wait for prefinish event.
It is emitted only when the response becomes active in the pipeline.
The ordering of requests/responses in _http_server.js is dependent
on this, doing it in different order will result in crash.

Fix: #2639

cc @nodejs/collaborators @trevnorris @rvagg

This is very important bug fix. We should consider reviewing it very carefully, and merging ASAP (after users will confirm that it fixes stuff for them).

[indutny]

CI: https://ci.nodejs.org/job/node-test-pull-request/377/

[indutny]

Updated PR, new CI: https://ci.nodejs.org/job/node-test-pull-request/378/

[trevnorris]

I feel like if this is possible then there's something else wrong with the logic. From the documentation:

After [the finish] event, no more events will be emitted on the response object.

So how could this function ever be called more than once?

[arthurschreiber]

I don't think this changes that logic. This change ensures that the prefinish event is actually emited before the finish event.

[trevnorris]

Yes. I'm trying to point out that it should be impossible to call this function twice. So the added check shouldn't be necessary.

[indutny]

It is not about calling twice. It is about the order of events. The check handles the case where finish is emitted before the prefinish was emitted.

[trevnorris]

This function is finish(). I find I confusing that it could be called in the preFinish case.

[indutny]

It is indeed very confusing because we don't use streams API for these events. We should move to them in the future. Feel free to open issue for this, @trevnorris

[arthurschreiber]

@indutny: The test case is not exhaustive enough:

This test won't ever exit:

'use strict';

const net = require('net');
const http = require("http");

let count = 0;

const server = http.createServer(function(req, res) {
  const id = res.id = count++;

  console.log("----> Closing", id, "in", (2 - id) * 10, "ms");

  res.on('prefinish', function() {
    console.log("prefinish", id);
  });

  res.on('finish', function() {
    console.log("finish", id);
  });

  setTimeout(function() {
    res.end('hello', function() {
      console.log("----> End", id);

      if (id === 1)
        server.close();
    });
  }, (2 - id) * 10);
});

server.listen(8080, function() {
  const host = server.address().address;
  const port = server.address().port;

  console.log('Example app (' + process.pid + ') listening at http://%s:%s', host, port);

  const s = net.connect(port);

  const req = 'GET / HTTP/1.1\r\nConnection: close\r\n\r\n';
  const big = req + req;
  s.end(big);
  s.resume();
});

output:

$ node test.js
Example app (14169) listening at http://:::8080
----> Closing 0 in 20 ms
----> Closing 1 in 10 ms
prefinish 0
finish 0
----> End 0

And then it'll be stuck. Looks like the second request never receives prefinish or finish events.

[arthurschreiber]

Basically, prefinish is never emitted because the check after debug('outgoing message end.') is not true for the second request, thus never emitting finish in turn.

[arthurschreiber]

@indutny I guess the modified snippet I posted above is not quite correct, and your patch most likely works. I'll deploy the Node 4.1.1 with your patch on top on our servers and see if the error has gone away.

On another note, I'm trying to understand how http responses and pipelining is supposed to work in respect to events fired on the response objects. I also checked the behaviour on 0.10, and I'm more confused than before.

When running the following snippet on 0.10 or 4.0: https://gist.github.com/arthurschreiber/f9e11e34adc6e0140867

I see this output:

Example app (13772) listening at http://0.0.0.0:8080
----> Closing 0 in 20 seconds
----> Closing 1 in 10 seconds
Event: closed 0
----> Closing 1 now
----> Closing 0 now
Event: finish 0

closed and finish events are only fired on the first request, not on the second one. Basically, the two pipelined responses share the same socket, but events from the socket only get propagated to the first ServerResponse object. Why is that? Why doesn't each response object get the close event?

The documentation for close says:

Indicates that the underlying connection was terminated before response.end() was called or able to flush.

Isn't this the case for both ServerResponse objects in the snippet above?

Does this mean there is no reliable way for determining when a response was sent off in the case that HTTP pipelining is used?

[jasnell]

If the intent is to ensure that finish is only ever called after prefinish completes, then there should be some documented warning against using process.nextTick or setImmediate within the prefinish handler, as you'd end up in exactly the same problem. What you almost want instead is to pass an additional callback into the prefinish handler that can be called when it's work is done and you're ready to proceed with the finish.

[arthurschreiber]

@indutny I deployed this patch 2 hours ago on multiple layers, and the AssertionErrors are gone.

It looks like this fixes the issue we've been encountering.

I believe that 2 different issues have been mixed up in #2639.

First:

AssertionError: false == true
    at ServerResponse.resOnFinish (_http_server.js:474:7)
    at emitNone (events.js:67:13)
    at ServerResponse.emit (events.js:166:7)
    at finish (_http_outgoing.js:529:10)
    at doNTCallback0 (node.js:407:9)
    at process._tickCallback (node.js:336:13)

Second:

AssertionError: false == true
    at ServerResponse.detachSocket (_http_server.js:144:3)
    at ServerResponse.resOnFinish (_http_server.js:483:11)
    at emitNone (events.js:67:13)
    at ServerResponse.emit (events.js:166:7)
    at finish (_http_outgoing.js:526:10)
    at doNTCallback0 (node.js:407:9)
    at process._tickDomainCallback (node.js:377:13)

This fixes the second issue. According to the comments in #2639, this does not fix the first issue. I believe these two are separate issues with very similar error messages.

[indutny]

@jasnell this is not related to nextTick. I'm going to dig more to figure out the cause of #2639 .

@arthurschreiber thanks! I'll continue investigating

[Fishrock123]

common.mustCall()?

[indutny]

@Fishrock123 I think this is way too much :) If this is not going to work - we are pretty much in a bad situation. What about verifying the count instead?

Also, there is a possibly better fix for this: #3068 .

[indutny]

Closing in a favor of #3068