Post hooks called outside request context

[rkreienbuehl]

We use koajs as backend server. Therefore I used node-cls and wrote a small middleware to access context related data:

export async function contextMiddleware(ctx: Context, next) {
  cls.debug = true;
  const context: IGlobalContext = cls.create('request-context');
  context.id = uuidv4();
  context.ctx = ctx;

  await context.start();
  await next();
  cls.exit('request-context');
}

In pre hooks I can access the context data with const context = cls.get('request-context'); as expected (but only if it's the first line inside the middleware function, otherwise some async calls are already finished and destroyed their context on the stack and the chain is broken). This issue I can handle.

But when I use post hooks, the stack chain refers to outside the context. To trace the issue, I modified the getContext(ns) function from `node-cls:

function getContext(ns) {
  if (cls.debug)
    log(JSON.stringify(stack));
	let asyncId = ah.executionAsyncId();
	while(asyncId) {
		let current = stack[asyncId];
    if (cls.debug) {
      log('asyncID: ' + asyncId);
      log(JSON.stringify(current));
    }
		if (!current)
			return;
		if (current.contexts[ns])
			return current.contexts[ns];
		asyncId = current.parent;
	}
}

To test I have the following middleware:

schema.post('insertMany', async function (docs, next ) {
    const context = cls.get('request-context');
    console.log(context.id);

    next();
  });

When making a request, using the insertMany() method on a model an error is thrown TypeError: Cannot read property 'id' of undefined because the context is unknown.

In my test the stack looks like this:

{
    '4': { contexts: {}, id: 4, parent: 1 },
    '5': { contexts: {}, id: 5, parent: 1 },
    '6': { contexts: {}, id: 6, parent: 1 },
    '8': { contexts: {}, id: 8, parent: 1 },
    '19': { contexts: {}, id: 19, parent: 1 },
    '22': { contexts: {}, id: 22, parent: 1 },
    '25': { contexts: {}, id: 25, parent: 1 },
    '33': { contexts: {}, id: 33, parent: 1 },
    '36': { contexts: {}, id: 36, parent: 1 },
    '37': { contexts: {}, id: 37, parent: 1 },
    '39': { contexts: {}, id: 39, parent: 1 },
    '43': { contexts: {}, id: 43, parent: 1 },
    '44': { contexts: {}, id: 44, parent: 1 },
    '46': { contexts: {}, id: 46, parent: 1 },
    '50': { contexts: {}, id: 50, parent: 1 },
    '51': { contexts: {}, id: 51, parent: 1 },
    '53': { contexts: {}, id: 53, parent: 1 },
    '57': { contexts: {}, id: 57, parent: 1 },
    '64': { contexts: {}, id: 64, parent: 1 },
    '74': { contexts: {}, id: 74, parent: 73 },
    '75': { contexts: {}, id: 75, parent: 1 },
    '77': { contexts: {}, id: 77, parent: 1 },
    '78': { contexts: {}, id: 78, parent: 1 },
    '88': { contexts: {}, id: 88, parent: 40 },
    '90': { contexts: {}, id: 90, parent: 47 },
    '92': { contexts: {}, id: 92, parent: 54 },
    '94': { contexts: {}, id: 94, parent: 76 },
    '170': { contexts: {}, id: 170, parent: 64 },
    '182': { contexts: {}, id: 182, parent: 64 },
    '194': { contexts: {}, id: 194, parent: 187 },
    '197': { contexts: {}, id: 197, parent: 192 },
    '253': { contexts: {}, id: 253, parent: 194 },
    '258': { contexts: {}, id: 258, parent: 197 },
    '297': { contexts: {}, id: 297, parent: 273 },
    '307': { contexts: {}, id: 307, parent: 303 },
    '318': { contexts: {}, id: 318, parent: 313 },
    '350': { contexts: {}, id: 350, parent: 318 },
    '353': { contexts: {}, id: 353, parent: 307 },
    '356': { contexts: {}, id: 356, parent: 75 },
    '358': { contexts: {}, id: 358, parent: 356 },
    '364': { contexts: {}, id: 364, parent: 75 },
    '365': { contexts: {}, id: 365, parent: 364 },
    '366': { contexts: {}, id: 366, parent: 364 },
    '369': { contexts: {}, id: 369, parent: 366 },
    '370': { contexts: {}, id: 370, parent: 366 },
    '371': { contexts: [Object], id: 371, parent: 370 },
    '372': { contexts: {}, id: 372, parent: 371 },
    '373': { contexts: {}, id: 373, parent: 369 },
    '374': { contexts: {}, id: 374, parent: 373 },
    '376': { contexts: {}, id: 376, parent: 372 },
    '377': { contexts: {}, id: 377, parent: 376 },
    '378': { contexts: {}, id: 378, parent: 377 },
    '379': { contexts: {}, id: 379, parent: 377 },
    '380': { contexts: {}, id: 380, parent: 377 },
    '381': { contexts: {}, id: 381, parent: 377 },
    '382': { contexts: {}, id: 382, parent: 381 },
    '383': { contexts: {}, id: 383, parent: 380 },
    '384': { contexts: {}, id: 384, parent: 382 },
    '385': { contexts: {}, id: 385, parent: 382 },
    '386': { contexts: {}, id: 386, parent: 382 },
    '387': { contexts: {}, id: 387, parent: 382 },
    '388': { contexts: {}, id: 388, parent: 382 },
    '390': { contexts: {}, id: 390, parent: 388 },
    '391': { contexts: {}, id: 391, parent: 387 },
    '392': { contexts: {}, id: 392, parent: 386 },
    '393': { contexts: {}, id: 393, parent: 385 },
    '394': { contexts: {}, id: 394, parent: 384 },
    '395': { contexts: {}, id: 395, parent: 379 },
    '410': { contexts: {}, id: 410, parent: 197 },
    '411': { contexts: {}, id: 411, parent: 197 },
    '412': { contexts: {}, id: 412, parent: 197 },
    '413': { contexts: {}, id: 413, parent: 197 },
    '414': { contexts: {}, id: 414, parent: 197 },
    '415': { contexts: {}, id: 415, parent: 411 }
  }

So the request-context is stored in entry 371.
The debug log from node-cls shows:

asyncID: 411
{"contexts":{},"id":411,"parent":197}
asyncID: 197
{"contexts":{},"id":197,"parent":192}
asyncID: 192
undefined

It seems that the post hooks are called from a separate async chain. Is there a way to fix that?

[vkarpov15]

Try the workaround in this comment: #7292 (comment) . There is some unfortunate issues with how CLS libraries handle Node's TCP sockets that we haven't been able to work around.

[vkarpov15]

I was still able to repro this issue in Mongoose 8:

const Koa = require('koa');
const mongoose = require('mongoose');
const { v4: uuidv4 } = require('uuid');
const cls = require('node-cls');

const app = new Koa();

async function contextMiddleware(ctx, next) {
  const context = cls.create('request-context');
  context.id = uuidv4();
  context.ctx = ctx;

  await context.start();
  await next();
  cls.exit('request-context');
}

app.use(contextMiddleware);

mongoose.connect('mongodb://localhost:27017/koa-mongoose');
const TestSchema = new mongoose.Schema({ name: String });

// Add pre hook (context will be available here)
TestSchema.pre('insertMany', function (next) {
  const context = cls.get('request-context');
  if (context) {
    console.log('Pre Hook - Context ID:', context.id);
  }
  next();
});

// Add post hook (context may not be available here)
TestSchema.post('insertMany', function (docs, next) {
  const context = cls.get('request-context');
  if (context) {
    console.log('Post Hook - Context ID:', context.id);
  } else {
    console.log('Post Hook - Context not available');
  }
  next();
});

const TestModel = mongoose.model('Test', TestSchema);

// Define a route to trigger the insertMany operation
app.use(async (ctx) => {
  try {
    await TestModel.insertMany([{ name: 'Test1' }, { name: 'Test2' }]);
    ctx.body = 'Documents inserted';
  } catch (err) {
    ctx.body = 'Error inserting documents';
    console.error(err);
  }
});

// Start the server
app.listen(3000, () => {
  console.log('Server running on http://localhost:3000');
});

Output:

Server running on http://localhost:3000
Pre Hook - Context ID: 5db18a8e-651a-4969-99c4-365d1bc66233
Post Hook - Context not available

As a workaround, you can use Node's built-in AsyncLocalStorage, which does work:

const Koa = require('koa');
const mongoose = require('mongoose');
const { v4: uuidv4 } = require('uuid');
const { AsyncLocalStorage } = require('async_hooks');

const app = new Koa();

const asyncLocalStorage = new AsyncLocalStorage();

async function contextMiddleware(ctx, next) {
  const context = { id: uuidv4(), ctx };

  // Run each request within an AsyncLocalStorage context
  await asyncLocalStorage.run(context, async () => {
    await next();
  });
}
app.use(contextMiddleware);

mongoose.connect('mongodb://localhost:27017/test');
const testSchema = new mongoose.Schema({ name: String });

// Pre hook: Accessing context data
testSchema.pre('insertMany', function (next) {
  const context = asyncLocalStorage.getStore();
  if (context) {
    console.log('Pre Hook - Request ID:', context.id);
  } else {
    console.log('Pre Hook - No context found');
  }
  next();
});

// Post hook: Accessing context data
testSchema.post('insertMany', function (docs, next) {
  const context = asyncLocalStorage.getStore();
  if (context) {
    console.log('Post Hook - Request ID:', context.id);
  } else {
    console.log('Post Hook - No context found');
  }
  next();
});

const TestModel = mongoose.model('Test', testSchema);

// Route to test insertMany
app.use(async (ctx) => {
  await TestModel.insertMany([{ name: 'Test 1' }, { name: 'Test 2' }]);
  ctx.body = 'Data inserted';
});

// Start the Koa server
const PORT = 3000;
app.listen(PORT, () => {
  console.log(`Server is running on http://localhost:${PORT}`);
});
                                        

Output:

Server is running on http://localhost:3000
Pre Hook - Request ID: d945f5a1-75aa-41e6-ac2b-636566e9f767
Post Hook - Request ID: d945f5a1-75aa-41e6-ac2b-636566e9f767

We will investigate and see if there's anything we can do re: node-cls

[vkarpov15]

I did some digging and the same issue from 2021 persists: node-cls simply cannot retain context when TCP streams are involved.

For example, context is defined here but lost here. Deep in the internals of the MongoDB Node driver where it handles writing to socket and then reading back off the socket.

I'm going to close this issue, I don't think it is worth digging any further since Node's built-in AsyncLocalStorage works as expected and offers a fairly straightforward alternative.