Repository navigation
AsyncWrap: HTTP parserOnBody events happen outside pre/post #4416
Description
Activity
/cc @trevnorris
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));
})
}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.
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.
@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'.
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.
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.
@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.
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.
@trevnorris I think it should be fixed by doing MakeCallback in node_http_parser.cc.
@indutny Is it safe to MakeCallback if we're in a stack that was entered with MakeCallback?
@chrisdickinson if it is not - we should fix it, I guess!
7 remaining items
Thanks man, and sorry for delaying it.
@indutny no worries. I was the one who delayed it while figuring out the entire reentrant makecallback thing.
In the case where an incoming HTTP request is consumed by the C++ layer, the resulting
parserOnBodycallbacks are not made throughMakeCallback. Instead they use->Calldirectly. In the slow case, where the TCP connection is not consumed by C++, the appropriatepre/postevents are fired.Given the example program:
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:And the following when the example is run with
RUN_SLOWLY=1 node example.js: