AsyncWrap: HTTP parserOnBody events happen outside pre/post

[chrisdickinson]

In the case where an incoming HTTP request is consumed by the C++ layer, the resulting parserOnBody callbacks are not made through MakeCallback. Instead they use ->Call directly. In the slow case, where the TCP connection is not consumed by C++, the appropriate pre/post events are fired.

Given the example program:

const asyncHooks = process.binding('async_wrap');
const http = require('http');

asyncHooks.setupHooks(_ => _, function () {
 process._rawDebug('pre', this.constructor.name);
}, function () {
 process._rawDebug('post', this.constructor.name);
});
asyncHooks.enable();

const server = http.createServer(req => {
 req.on('data', data => {
 process._rawDebug('RECV');
 });
})

if (process.env.RUN_SLOWLY) {
 server.on('connection', conn => {
 // unconsume the stream.
 conn.on('data', _ => _);
 });
}

server.listen(8124);

Running the following:

$ curl -sLi -d@/usr/share/dict/words 'http://localhost:8124'

Produces the following when the program is run with node example.js:

pre TCP
post TCP
RECV
RECV
RECV
RECV
RECV
RECV
RECV
RECV
...

And the following when the example is run with RUN_SLOWLY=1 node example.js:

pre TCP
post TCP
pre TCP
post TCP
pre TCP
RECV
post TCP
pre TCP
RECV
post TCP
pre TCP
RECV
post TCP
pre TCP
RECV
post TCP
pre TCP
RECV
post TCP
pre TCP
RECV
post TCP
...

[mscdex]

/cc @trevnorris

[chrisdickinson]

Attaching a test case:

'use strict';

const async_wrap = process.binding('async_wrap');
const fork = require('child_process').fork;
const Writable = require('stream').Writable;
const assert = require('assert');
const http = require('http');

const common = require('../common');

return process.env.NODE_TEST_FORK
 ? runChild()
 : runParent();

function runChild () {
 async_wrap.setupHooks(init, pre, post);
 async_wrap.enable();

 const server = http.createServer((req, res) => {
 req.on('data', data => {
 process._rawDebug('DATA');
 });
 req.once('end', () => {
 res.end('end response');
 server.close(() => {
 process.exit(0);
 });
 });
 });
 server.listen(common.PORT, () => {
 // this "console.log" is load-bearing: we have to send something
 // out over stdout to signal that we're ready to receive requests.
 console.log('listening');
 });

 function init (type, id, parent) {
 process._rawDebug('init', this.constructor.name);
 }

 function pre () {
 process._rawDebug('pre', this.constructor.name);
 }

 function post () {
 process._rawDebug('post', this.constructor.name);
 }
}

function runParent () {
 const proc = fork(__filename, {
 env: Object.assign({}, process.env, {NODE_TEST_FORK: '1'}),
 silent: true
 });

 const acc = [];
 proc.stderr.pipe(Writable({
 write (chunk, enc, cb) {
 acc.push(chunk);
 cb();
 }
 }));

 proc.stdout.once('data', () => {
 const req = http.request({
 host: '127.0.0.1',
 port: common.PORT,
 method: 'POST'
 }, res => {
 res.resume();
 });
 req.write('hello'.repeat(16000));
 req.end();
 });

 setTimeout(() => {
 try {
 child.kill()
 } finally {
 process.exit()
 }
 }, 100).unref();

 proc.once('exit', () => {
 assert.equal(Buffer.concat(acc).toString('utf8'), `
 init TCP
 init TCP
 pre TCP
 init Timer
 post TCP
 pre TCP
 post TCP
 DATA
 pre TCP
 DATA
 post TCP
 init ShutdownWrap
 `.split('\n').map(xs => xs.trim()).join('\n').slice(1));
 })
}

[trevnorris]

Thanks for the test cases. Holiday is of course slowing things down, but I'll try to have this solved by the end of the week.

[trevnorris]

Is there a diagram of the data flow from the TCP connection receiving a packet to where it's delivered via the 'data' event?

/cc @indutny

EDIT: Also, when it runs. This isn't happening anywhere within the execution of AsyncWrap::MakeCallback.

[trevnorris]

@chrisdickinson Also realize that the 'request' http callback is not called within the pre/post. Easy enough to observe by adding a process._rawDebug just before req.on('data'.

[chrisdickinson]

Yeah - that may be due to a process.nextTick, I think. (At least, the first chunk of data is nextTick'd.)

On Dec 27, 2015, at 1:47 PM, Trevor Norris notifications@github.com wrote:

@chrisdickinson Also realize that the 'request' http callback is not called within the pre/post. Easy enough to observe by adding a process._rawDebug just before req.on('data'.

—
Reply to this email directly or view it on GitHub.

[chrisdickinson]

Err, just replied and immediately realized those are two different problems! whoops! :)

On Dec 27, 2015, at 1:47 PM, Trevor Norris notifications@github.com wrote:

@chrisdickinson Also realize that the 'request' http callback is not called within the pre/post. Easy enough to observe by adding a process._rawDebug just before req.on('data'.

—
Reply to this email directly or view it on GitHub.

[trevnorris]

@chrisdickinson To test I delayed running the post callback until after the nextTickQueue had run. Didn't help anything. So this isn't running during either AsyncWrap::MakeCallback or node::MakeCallback.

[trevnorris]

To further support this, here's an alteration to your first example:

const d = require('domain').create();
let server;

d.run(function() {
 server = http.createServer(req => {
 print('CONN');
 req.on('data', data => {
 print('RECV', process.domain);
 });
 })
});

Output:

pre TCP 
post TCP 
CONN 
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined
RECV undefined

So the process.domain isn't being set because the call doesn't go through MakeCallback. This is therefore a problem bigger than just not running the async hooks properly.

/cc @indutny sorry for the second cc but this info is more directly related to how HTTPParser fundamentally works.

[indutny]

@trevnorris I think it should be fixed by doing MakeCallback in node_http_parser.cc.