No finish/close event on aborted http-response - race condition #1309

Closed
not-implemented opened this Issue Apr 1, 2015 · 8 comments

Projects

None yet

7 participants

@not-implemented
Contributor

When tracking requests of a HTTP-Server - with server.on('request') and res.on('finish', ...) or res.on('close', ...) - we noticed inconsistent results over time (requests that are never finished or closed).

We tracked this race condition down to the following reproducable test case:

  1. connection is aborted from client side
  2. socket gets destroyed (but socket-"close"-event still not delivered)
  3. trying to send response
  4. socket-"close" event delivered

-> No "close" and no "finish" event on response!

var common = require('../common');
var assert = require('assert');
var http = require('http');

var clientRequest = null;
var serverResponseFinishedOrClosed = 0;

var server = http.createServer(function (req, res) {
    console.log('server: request');

    res.on('finish', function () {
        console.log('server: response finish');
        serverResponseFinishedOrClosed++;
    });
    res.on('close', function () {
        console.log('server: response close');
        serverResponseFinishedOrClosed++;
    });

    console.log('client: aborting request');
    clientRequest.abort();

    setImmediate(function() {
        console.log('server: tick 1' + (req.connection.destroyed ? ' (connection destroyed!)' : ''));

        setImmediate(function () {
            console.log('server: tick 2' + (req.connection.destroyed ? ' (connection destroyed!)' : ''));

            console.log('server: sending response');
            res.writeHead(200, {'Content-Type': 'text/plain'});
            res.end('Response\n');
            console.log('server: res.end() returned');

            setImmediate(function () {
                server.close();
            });
        });
    });
});

server.on('listening', function () {
    console.log('server: listening on port ' + common.PORT);
    console.log('client: starting request');

    var options = {port: common.PORT, path: '/'};
    clientRequest = http.get(options, function () {});
    clientRequest.on('error', function () {});
});

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

server.on('close', function () {
    console.log('server: close');
    assert.equal(serverResponseFinishedOrClosed, 1, 'Expected either one "finish" or one "close" event on the response for aborted connections (got ' + serverResponseFinishedOrClosed + ')');
});

server.listen(common.PORT);
  • With one more setImmediate() call, you get a response close event (which is fine)
  • With one less setImmediate() call, you get a response finish event (which is fine)
  • Reproducable with io.js 1.6.3, io.js 1.3.0, io.js 1.1.0, node 0.12.0
  • In node 0.10 the race-condition was different: This test case works fine, but with one more setImmediate(), two events are delivered (finish AND close)
@not-implemented
Contributor

The different behaviour between node 0.10 (<=0.11.5) and node 0.12 (>=0.11.6) may be related to the changes made by @isaacs ("http: Consistent 'finish' event semantics", 7c9b607, and "http: Add write()/end() callbacks" da93d6a).

@Olegas
Contributor
Olegas commented Apr 1, 2015

+1
Can see this happens sometimes.
Neither finish nor close event is triggered on res. Stable reproduces in our environment, we can see this graphically (we count "active" connections with finish/close events).

@not-implemented
Contributor

Proposed fix see pull request #1373

@Fishrock123
Member
@sonnyp sonnyp referenced this issue in node-xmpp/server May 12, 2015
Closed

BOSH client doesn't always emit close event #100

@brendanashworth
Member

The fix for this (#1411, semver-major) is now on track for the 3.0.0 release.

@KoltesDigital

Could it please be released earlier? I'm afraid 3.0.0 won't come soon.

@Fishrock123
Member

3.0.0 is out and this landed in it. :) https://iojs.org/dist/v3.0.0/

@danni danni pushed a commit to ask-izzy/ask-izzy that referenced this issue Oct 30, 2015
Danielle Madeley Update NodeJS to 4.x
Fixes memory leak caused by nodejs/node#1309
a083a23
@danni danni referenced this issue in ask-izzy/ask-izzy Oct 30, 2015
Merged

Update NodeJS to 4.x #240

@evantahler

I've found something similar here, which you can emulate with node v4 and v5... just by sending the Content-Length header.

https://gist.github.com/evantahler/2f6c4241c47d7c89f5555d833475c8b8

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment