Streams: req.on('end') is sometimes called, sometimes not

[iliakan]

Let's say I have a server.on('request') handler, with the code:

req
      .setEncoding('utf-8')
      .on('data', function(data) {
        body += data;
        if (body.length > 10) {
          res.statusCode = 413;
          res.end("Your message is too big for my little chat");
        }
      })
      .on('end', function() {
        console.log("END");
      });

If the message is too big (413) should on('end') event trigger?

P.S. I'm asking because it does trigger in this case (10 bytes limit), but it does not trigger in the case of a larger limit (1000000 bytes limit). The behavior - sometimes it triggers and sometimes not - seems weird.

[targos]

I can confirm that sometimes the 'end' event is not emitted.
It does not seem to be related to the body length as I can reproduce it with any limit.

Here is my testcase:

var http = require('http');

var limit = 10;
var reqCount = 0;
var endCount = 0;

var server = http.createServer();

server.on('request', function (req, res) {
    reqCount++;
    var body = '';
    req
        .setEncoding('utf-8')
        .on('data', function(data) {
            body += data;
            if (body.length === limit) {
                res.statusCode = 413;
                res.end('Your message is too big for my little chat');
            }
        })
        .on('end', function() {
            endCount++;
            nextRequest();
        });
});

server.on('listening', nextRequest);

function nextRequest() {
    //limit++;
    var r = http.request({
        port: 8080,
        method: 'POST'
    }, function () {
        if (reqCount !== endCount) {
            console.error(`Missing END!\nRequests: ${reqCount}\nEnded: ${endCount}`);
            process.exit(1);
        }
    });
    r.write('a'.repeat(limit));
    r.end();
}

server.listen(8080);

[iliakan]

This issue is labelled as "question", but it is actually a bug.

[trevnorris]

@targos Thanks for the test case. I've confirmed the bug.

[targos]

I have tried to debug this but it is difficult because of all the async stuff (stack trace basically contains only the process.nextTick stuff).
I also tried to use the debug build but in fact I don't know what information I can get with it or how to get it 😢. Is there a documentation somewhere about it ?

[matthewloring]

@targos I have been digging through the http module recently so I thought I'd give this a go but I'm not able to reproduce. I should be seeing the Missing END statement being printed, right?

[tehkonst]

@matthewloring Try this.

var http = require('http');

var limit = 10;
var length = 10000;
var reqCount = 0;
var endCount = 0;

var server = http.createServer();

server.on('request', function (req, res) {
    reqCount++;
    var body = '';
    req
        .setEncoding('utf-8')
        .on('data', function(data) {
            body += data;
            if (body.length > limit) {
                res.statusCode = 413;
                res.end('Your message is too big for my little chat');
            }
        })
        .on('end', function() {
            endCount++;
            nextRequest();
        });
});

server.on('listening', nextRequest);

function nextRequest() {
    length = length + 1000;
    console.log(length, reqCount, endCount);
    var r = http.request({
        port: 8080,
        method: 'POST'
    }, function () {
        if (reqCount !== endCount) {
            console.error(`Missing END!\nRequests: ${reqCount}\nEnded: ${endCount}`);
            process.exit(1);
        }
    });
    r.write('a'.repeat(length));
    r.end();
}

server.listen(8080);

I get error (Error: read ECONNRESET), don't know why.

[matthewloring]

Thanks! I am able to reproduce it with this example!

[matthewloring]

With further testing I have found that req.on('end') stops being called when the data size is greater than 65435. When the data is longer than 65443 characters, it is broken up into two calls to req.on('data'). An 'end' event is only emitted once all data has been consumed through calls to on('data'). Since the res object is receiving an end event before all data is consumed from the req object, req.on('end') will not execute until after the callback that compares the counts. I'm not sure what exactly is happening in the 65435 to 65443 range but my guess is that it is related to event emitter buffering. Though counter intuitive, I think this is actually working as intended.

[iliakan]

@matthewloring it's great you found out why it happens. I felt like this is going on too.

From the streams standpoint, req.on('end') should always happen, because req is a readable stream.

[matthewloring]

@iliakan To the best of my understanding of the spec, readable streams are not required to call on.('end'). They only do so if all data has been processed with a call to on.('data'). If a readable stream falls out of scope and not all data has been consumed it will never call on.('end') and, to my understanding of the spec, this is correct behavior. Since res.end emits the finish event that causes the server to immediately send the response and cease handling the request before all data on the request has been consumed, req.on('end') shouldn't execute in this case.

see: https://github.com/nodejs/io.js/blob/master/lib/_http_outgoing.js#L507

[iliakan]

@matthewloring: well, end event may not fire, because the data is not consumed fully. I'd agree here.

But there's no close event also after res.end (large body in the code above). So the req event hangs in the air without neither close nor end.

Actually, the event flow for req with large body and immediate res.end is like this:

resume
data

Only these 2 events.

Maybe the logic is like this?

• end triggers on full data consumption
• close triggers on unexpected(only) connection drop

Then it'd be sane to skip both events here.

[matthewloring]

@iliakan After reading around here (https://github.com/nodejs/io.js/blob/master/lib/_http_server.js#L257) it appears that 'close' is only triggered when a client has opened a TCP connection (causing a 'connection' event to be fired) and the socket associated with that connection closes prematurely.

[Trott]

@matthewloring Is it your opinion that this is not a bug? Although puzzling at first glance, it is working as intended? Or am I misunderstanding? /cc @trevnorris @targos

[matthewloring]

IIRC end not firing was not a bug but I don't know what the intended contract is for emitting close. If close should be fired for every connection then there is a bug but I couldn't find anything that specifies this behavior.

[iliakan]

Summary for your guys to triage more easily.

Assuming that:

• end triggers on full data consumption
• close triggers on unexpected(only) connection drop

It is possible that if the data is not fully consumed and the connection is explicitly closed (for example, limit reached), then both events do not trigger.

That is "an intended", right?

P.S. It seems to me that "yes", so I'm closing this.

[xosg]

here is a simple solution using Content-Length header, when the length of body >= content-length, we assume the stream end:

        const body = [];
        let length = 0;
        const contentLength = +request.headers["content-length"];
        request.body = await new Promise((resolve, reject) => {
            let ended = false;
            function onEnd() {
                if (!ended) {
                    resolve(Buffer.concat(body).toString());
                    ended = true;
                }
            }

            req.on("data", chunk => {
                body.push(chunk);
                length += chunk.length;
                if (length >= contentLength) onEnd();
            })
                .on("end", onEnd)
                .on("error", (err) => {
                    reject(err);
                });
        });