Hook function cannot access request-context variables

[mtbnunu]

When using await approach, request context variables returns undefined in pre find* hooks

I have noticed that it is accessible inside
pre save

on related note, if using callback approach, the context variables are not accessible inside the callback function.
This may or may not be related to mongoose code, but with combination of original issue it creates bigger problem since neither approach works perfectly when having to access the context variable both in pre hook and with the result.

I did find a closed ticket maked cannot reproduce but I was able to modify the given sample code to reproduce the issue:

Thanks!

const assert = require("assert");
const mongoose = require("mongoose");
mongoose.set("debug", true);

const httpContext = require("express-http-context");
const superagent = require("superagent");
const express = require("express");

const GITHUB_ISSUE = `gh7292`;
const connectionString = `mongodb://localhost:27017/${GITHUB_ISSUE}`;
const { Schema } = mongoose;

run()
	.then(() => console.log("done"))
	.catch(error => console.error(error.stack));

async function run() {
	await mongoose.connect(connectionString);
	await mongoose.connection.dropDatabase();

	const app = express();

	app.use(httpContext.middleware);

	const userSchema = new Schema({ name: String });

	userSchema.pre("find", function(next) {
		console.log(httpContext.get("test"));
		next();
	});

	const User = mongoose.model("User", userSchema);

	app.get("/", async (req, res) => {
		httpContext.set("test", "42");
		const user = await User.find({});
		res.json({ ok: 1 });
	});

	await app.listen(3003);

	await superagent.get("http://localhost:3003/");

	console.log("done");
	process.exit(0);
}

[email protected] [email protected] [email protected]

Originally posted by @mtbnunu in #7001 (comment)

[mhombach]

You are perfectly able to access httpContext and you are doing it correct. But you are missing the real issue here and that is, that httpContext.get("test") is really undefined. This has nothing to do with the context. If you change console.log(httpContext.get("test")); to console.log(JSON.stringify(httpContext)); you will see, that you are able to access the variable.
Why your specific httpContext.get("test") is undefined in general, is out of my scope and also has nothing to do with mongoose ;) I don't know the express-http-context-library. You may check your other code and find your real issue here, but it is not related to the scope of mongoose-hooks :)

[vkarpov15]

Thanks for reporting, will investigate ASAP

@mhombach this is an issue we should look into. Enough people use CLS / request context style libs, we should be able to support them 👍

[vkarpov15]

@mtbnunu I opened up an issue in the underlying cls-hooked library. I managed to identify a potential issue but I'll wait to see if it is expected behavior or not before really digging into it. Looks like there's some unexpected behavior with await and custom thenables. In the meantime, the workaround is easy, just use exec() to get a real promise to await on.

	app.get("/", async (req, res) => {
		httpContext.set("test", "42");
		const user = await User.find({}).exec(); // <-- Change here
		res.json({ ok: 1 });
	});

[vkarpov15]

Looks like superagent switched how they do promises a while back: ladjs/superagent@43aaa4a . Will investigate whether this helps us

[vkarpov15]

Looks like superagent's approach doesn't help with this particular issue. Will look into cls-hooked more later.

[vkarpov15]

I looked some more at cls-hooked and haven't been able to make any headway. The issue seems to apply to all custom thenables, not just Mongoose. The workaround is easy, just use .exec(). I'm going to close this for now.

Related to #7398 and other issues. Perhaps we can make queries extend Promise in the future and solve this issue without using .exec()

[jatinb92]

@mtbnunu I opened up an issue in the underlying cls-hooked library. I managed to identify a potential issue but I'll wait to see if it is expected behavior or not before really digging into it. Looks like there's some unexpected behavior with await and custom thenables. In the meantime, the workaround is easy, just use exec() to get a real promise to await on.

	app.get("/", async (req, res) => {
		httpContext.set("test", "42");
		const user = await User.find({}).exec(); // <-- Change here
		res.json({ ok: 1 });
	});

@vkarpov15 What about .populate, which makes internal find call?

[vkarpov15]

@jatinb92 .populate() uses exec() under the hood:

mongoose/lib/model.js

Line 4524 in d4c8859

query.exec(callback);

. Does it not work for you with cls-hooked?

[jatinb92]

@vkarpov15 @mtbnunu This workaround works for

1.await Model.find().exec()
2.await Model.findOne().exec()
3. await (await Model.findOne().exec()).populate('model').execpopulate();

But not with

1.(await Model.find().exec()).populate('model').execpopulate(); // because find returns an array and so we have to explicitily woork on all the rows one by one.
2.Model.find.populate.exec(function (err, data) {} ) // in this case it works with Model.find but not with the popoulate

Also, can you provide a way by which we can make .exec() or returning a promise type in the output of Query function( find /findone) mandatory.

[vkarpov15]

I can confirm that context gets lost in the below script:

const assert = require("assert");
const mongoose = require("mongoose");
mongoose.set("debug", true);

const httpContext = require("express-http-context");
const superagent = require("superagent");
const express = require("express");

const GITHUB_ISSUE = `gh7292`;
const connectionString = `mongodb://localhost:27017/${GITHUB_ISSUE}`;
const { Schema } = mongoose;

run()
        .then(() => console.log("done"))
        .catch(error => console.error(error.stack));

async function run() {
        await mongoose.connect(connectionString, {
          useNewUrlParser: true,
          useUnifiedTopology: true
        });
        await mongoose.connection.dropDatabase();

        const app = express();

        app.use(httpContext.middleware);

        const userSchema = new Schema({ name: String });

        userSchema.pre("find", function(next) {
                console.log('Find', httpContext.get("test"));
                next();
        });

        const User = mongoose.model("User", userSchema);
        const Group = mongoose.model('Group', Schema({
          leader: { type: 'ObjectId', ref: 'User' }
        }));

        app.get("/", async (req, res) => {
                httpContext.set("test", "42");
                const user = await Group.find({}).populate('leader').exec();
                res.json({ ok: 1 });
        });

        const u = await User.create({ name: 'test' });
        await Group.create({ leader: u._id });

        await app.listen(3003);

        await superagent.get("http://localhost:3003/");

        console.log("done");
        process.exit(0);
}

I did some digging and the context loss isn't due to Mongoose, it gets lost deep in the mongodb driver. Context is fine here: https://github.com/mongodb/node-mongodb-native/blob/a053f4ea3f5ad1c8c8a581c449cf03dc252aeb06/lib/cmap/message_stream.js#L56, but is lost when you end up here: https://github.com/mongodb/node-mongodb-native/blob/a053f4ea3f5ad1c8c8a581c449cf03dc252aeb06/lib/cmap/message_stream.js#L39-L41.

My best guess is that cls-hooked doesn't have good support for duplex streams. Thankfully, this issue seems to go away if we use promises internally for cursor.toArray() here: https://github.com/aheckmann/mquery/blob/e68f8e17a32b57a472c1cfaeb5c992a3803c50a3/lib/collection/node.js#L30 .

Will dig into this more later - I'd like to avoid switching to using promises on a one-off basis.

[vkarpov15]

I have a few potential solutions, but they all seem a bit hacky. Here's some potential options:

1. Explicitly use Namespace#bind() from cls-hooked on find() and findOne() callbacks under the hood, perhaps in a plugin.

const httpContext = require("express-http-context");
const ns = httpContext.ns;
const _find = require('mquery').Collection.prototype.find;
require('mquery').Collection.prototype.find = function(match, options, cb) {
  return _find.call(this, match, options, ns.bind(cb));
};
const _findOne = require('mquery').Collection.prototype.findOne;
require('mquery').Collection.prototype.findOne = function(match, options, cb) {
  return _findOne.call(this, match, options, ns.bind(cb));
};

2. Switch mquery find() and findOne() to use promises

NodeCollection.prototype.find = function(match, options, cb) {
  this.collection.find(match, options, function(err, cursor) {
    if (err) return cb(err);

    try {
      // cursor.toArray(cb);
      cursor.toArray().then(res => cb(null, res), err => cb(err));
    } catch (error) {
      cb(error);
    }
  });
};

3. Add a ns option and make Mongoose core aware of cls-hooked

I'm thinking (1) is probably the way to go, just create an explicit plugin that helps bridge the gap between express-http-context and mongoose.

[vkarpov15]

I took a closer look and I managed to find a good workaround without any plugins. Turns out the issue is largely due to the fact that express-http-context uses Namespace#run() rather than Namespace#runPromise(). I'm not 100% sure why this makes a difference, but using runPromise() fixes all the issues. No need for .exec() even:

        app.get("/", async (req, res) => {
                httpContext.set("test", "42");
                await httpContext.ns.runPromise(async () => {
                  await User.find().exec();
                  await User.findOne(); // Doesn't lose context even without `exec()`!
                  await Group.find({}).populate('leader').exec();
                  res.json({ ok: 1 });
                });
        });

I think the way to go is to recommend using runPromise() if you're using Mongoose with cls-hooked and async functions. That's much cleaner than adding an ns option or adding a plugin that changes a bunch of internal implementation details.

TLDR; if you're having a problem with losing context in Mongoose internals, try wrapping your code in ns.runPromise().

[fredericosilva]

I had similar issue using opentelemetry, adapting your workaround did the magic.

const { context } = require('@opentelemetry/api');
const mquery = require('mquery');

['find', 'findOne'].forEach(op => {
    const original = mquery.Collection.prototype[op];
    mquery.Collection.prototype[op] = function(match, options, cb) {
        const ctx = context.active();
        return original.call(this, match, options, function() {
            context.with(ctx, () => cb(...arguments));
        });
    };
});