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.

[chrisdickinson]

@indutny Is it safe to MakeCallback if we're in a stack that was entered with MakeCallback?

[indutny]

@chrisdickinson if it is not - we should fix it, I guess!

[trevnorris]

@chrisdickinson It's not, but that won't be a problem here. onBody never calls when already in a stack.

[indutny]

@trevnorris it will call it on stack if the socket is not consumed. Like in http client case.

[trevnorris]

Revised PR from @indutny after making MakeCallback reentrant: #5419

[indutny]

Thanks man, and sorry for delaying it.

[trevnorris]

@indutny no worries. I was the one who delayed it while figuring out the entire reentrant makecallback thing.