Sitelet https://github.com/nodejs/node/issues/4416
Skip to content

AsyncWrap: HTTP parserOnBody events happen outside pre/post #4416

Description

@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
...

Activity

added
httpIssues and PRs related to the http subsystem.
c++Issues and PRs that require attention from people who are familiar with C++.
on Dec 24, 2015

mscdex commented on Dec 24, 2015

@mscdex
Contributor

chrisdickinson commented on Dec 26, 2015

@chrisdickinson
ContributorAuthor

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));
  })
}
self-assigned this
on Dec 27, 2015

trevnorris commented on Dec 27, 2015

@trevnorris
Contributor

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 commented on Dec 27, 2015

@trevnorris
Contributor

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 commented on Dec 27, 2015

@trevnorris
Contributor

@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 commented on Dec 27, 2015

@chrisdickinson
ContributorAuthor

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 commented on Dec 27, 2015

@chrisdickinson
ContributorAuthor

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 commented on Dec 27, 2015

@trevnorris
Contributor

@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 commented on Dec 27, 2015

@trevnorris
Contributor

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 commented on Dec 27, 2015

@indutny
Member

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

chrisdickinson commented on Dec 27, 2015

@chrisdickinson
ContributorAuthor

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

indutny commented on Dec 27, 2015

@indutny
Member

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

7 remaining items

indutny commented on Feb 24, 2016

@indutny
Member

Thanks man, and sorry for delaying it.

trevnorris commented on Feb 24, 2016

@trevnorris
Contributor

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

added a commit that references this issue on Mar 2, 2016
added a commit that references this issue on Jul 12, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

c++Issues and PRs that require attention from people who are familiar with C++.httpIssues and PRs related to the http subsystem.

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions