Mongoose: Implement Async Hooks (async_hooks) Embedder API

[Jeff-Lewis]

As a developer needing to maintain context information during asynchronous database calls and Mongoose's Middleware hooks, we should implement Node Async Hooks' Embedder API to allow proper usage of Async Hooks.

This will allow Mongoose consumers to carry context information across Mongoose's user-land queueing and Operation Buffering.

Questions/Considerations for Mongoose:

• The Embedder API will have to be implemented in a way that allows Mongoose to still support previous versions of Node.
• Besides Mongoose's Operational Buffering, what other areas need to be instrumented with the Embedder API?

History and References:

• #2987 Mongoose and CLS
• #3313 Mongoose and CLS, take 2
• cls-mongoose

Finally, it appears Node's Diagnostics team is willing to help out. Hopefully we can get some assistance if needed.

[vkarpov15]

This sounds like a very good idea. Honestly there will likely need to be some changes to the hooks lib. Will investigate this more for 5.1, but any help before that would be much appreciated

[varunjayaraman]

my only concern is that this feature has a stability index of 1. Releasing production code that depends on this seems like a dangerous move at the moment. I could see how this is something we could implement down the line but releasing a version of mongoose in the near future that relies on a stability 1 node api doesn't seem tenable.

Thoughts @vkarpov15 ?

[vkarpov15]

That's a good point. Perhaps we can just implement this as a plugin?

[vkarpov15]

@Jeff-Lewis so I'm very hesitant to put this into mongoose core because it looks like the entire heart of the embedder API, the emitBefore() and emitAfter() functions, was deprecated in node 10. I also don't quite understand how async hooks are supposed to work, but I think the below plugin does the trick in node 8:

mongoose.plugin(schema => {
  schema.statics.$wrapCallback = function(callback) {
    var _this = this;
    const resource = new asyncHooks.AsyncResource(`mongoose.${this.modelName}`);
    return function() {
      let emittedAfter = false;
      try {
        resource.emitBefore();
        callback.apply(null, arguments);
        emittedAfter = true;
        resource.emitAfter();
      } catch (error) {
        if (!emittedAfter) {
          resource.emitAfter();
        }
        _this.emit('error', error);
      }
    };
  };
});

Below script seems to tie mongoose correctly to an HTTP trigger:

const asyncHooks = require('async_hooks');
const fs = require('fs');
const http = require('http');
const mongoose = require('mongoose');

const hooks = {
  init: init
};
const asyncHook = asyncHooks.createHook(hooks);

mongoose.plugin(schema => {
  schema.statics.$wrapCallback = function(callback) {
    var _this = this;
    const resource = new asyncHooks.AsyncResource(`mongoose.${this.modelName}`);
    return function() {
      let emittedAfter = false;
      try {
        resource.emitBefore();
        callback.apply(null, arguments);
        emittedAfter = true;
        resource.emitAfter();
      } catch (error) {
        if (!emittedAfter) {
          resource.emitAfter();
        }
        _this.emit('error', error);
      }
    };
  };
});

mongoose.connect('mongodb://localhost:27017/test');
const Model = mongoose.model('Test', new mongoose.Schema({}), 'Test');

asyncHook.enable();

http.createServer(function(req, res) {
  Model.find({}, function(err, docs) {
    return res.end(JSON.stringify(docs, null, '  '));
  });
}).listen(8079);

function init(asyncId, type, triggerId) {
  fs.writeSync(1, `${type} ${asyncId} ${triggerId}\n`);
}

Output from curling:

$ node async.js 
TCPWRAP 13 1
TickObject 14 13
TCPCONNECTWRAP 16 6
TIMERWRAP 17 16
TickObject 18 16
TickObject 19 18
TickObject 20 18
TickObject 21 6
TickObject 22 6
TickObject 23 6
Timeout 24 22
TIMERWRAP 25 22
TickObject 26 22
TickObject 27 26
TickObject 29 27
TCPWRAP 31 13
TIMERWRAP 32 13
Timeout 33 13
HTTPPARSER 34 13
HTTPPARSER 35 13
TickObject 36 13
mongoose.Test 37 35
TickObject 38 35
TickObject 39 35
TickObject 40 38
TickObject 41 40
TickObject 42 40
TickObject 43 6
TickObject 44 6
TickObject 45 6

Does this look right to you?

[vkarpov15]

I published this plugin on npm: https://www.npmjs.com/package/@mongoosejs/async-hooks . Please give it a shot and report any issues on that repo

[iliakan]

Looks like no one cares/uses mongoose with cls-hooked?

[vkarpov15]

@iliakan what makes you say that?

[iliakan]

@vkarpov15 I look at download stats of https://www.npmjs.com/package/@mongoosejs/async-hooks, it's zero :(

[vkarpov15]

Yeah I hadn't noticed that. Unfortunate but I'd guess there's a lot of solutions out there for Mongoose + CLS.

[bmacnaughton]

Most applications don't know/care about CLS (or the underlying technologies). It is used by application performance monitoring solutions but the mechanism is opaque to the end users. I'm sure there are other uses that I'm not aware of.

I'm happy to see that it's there as might solve the problem when a customer reports that mongoose is not showing up in their traces.

[iliakan]

in web dev CLS "made right" could be awesome.
"Thread-local" request etc.

Java has that for ages. JavaScript does not. What a joke.

[joebowbeer]

I notice that mongoosejs/async_hooks depends on $wrapCallback, which has no effect if promises are used instead.

[joebowbeer]

I notice that in most cases wrapCallback is passed a function that eventually calls a callback, not the callback itself. So in most cases the init/before/after async hooks will be called in rapid-fire, and will not capture the lifetime of the hooked mongo operation. The after hook shouldn't fire until after the callback (cb) is called:

https://github.com/Automattic/mongoose/blob/master/lib/model.js#L453