Add session idle timeout and description of "cursor not found" to docs about queries

[Cooya]

Do you want to request a feature or report a bug?
Report a bug

What is the current behavior?
I recently bumped my Mongoose version from 5.5.7 to 5.9.6 and I spotted a issue with cursors.
The error is MongoError: cursor id XXX not found (even with cursor.addCursorFlag('noCursorTimeout', true).

If the current behavior is a bug, please provide the steps to reproduce.
You can reproduce the bug by running this script (for a few hours) :

const mongoose = require('mongoose');

const sleep = seconds => new Promise(resolve => setTimeout(resolve, seconds * 1000));

(async () => {
	await mongoose.connect('mongodb://localhost/test', { useCreateIndex: true, useNewUrlParser: true, useUnifiedTopology: true, poolSize: 10 });

	const Doc = mongoose.model('Test',  new mongoose.Schema({
		counter: { type: Number, default: 0 }
	}));

	for(let i = 0; i < 10000; ++i)
		await (new Doc()).save();

	const cursor = Doc.find({}).cursor();
	cursor.addCursorFlag('noCursorTimeout', true);
	await cursor.eachAsync(async doc => {
		doc.counter++;
		await doc.save();
		console.log(`Doc ${doc._id} saved, sleeping for 10 seconds...`);
		await sleep(10);
	});
	await cursor.close();
})();

What is the expected behavior?
The error must not occur.

What are the versions of Node.js, Mongoose and MongoDB you are using?
Node v12.16.1
Mongoose v5.9.6
MongoDB v4.0.16

I think the error has to do with the MongoDB idle session timeout (https://docs.mongodb.com/manual/reference/method/cursor.noCursorTimeout/) but I am no expert.

[AbdelrahmanHafez]

Having to wait for a few hours to reproduce the issue, that's my favorite kinds of issues 😄

I'll run the script for 1,000 documents, it should take ~3 hours, hopefully that will be enough to reproduce the issue.

[AbdelrahmanHafez]

Ran this (1,000 docs = ~3 hours) with no luck in reproducing the issue.

const mongoose = require('mongoose');
const { Schema } = mongoose;

mongoose.connect('mongodb://localhost/test', { useCreateIndex: true, useNewUrlParser: true, useUnifiedTopology: true, poolSize: 10 });

const userSchema = new Schema({ counter: { type: Number, default: 0 } });
const User = mongoose.model('User', userSchema);

async function run () {
  await User.deleteMany();

  const users = Array(1000).fill({});

  await User.create(users);

  const cursor = User.find({}).cursor();
  cursor.addCursorFlag('noCursorTimeout', true);

  await cursor.eachAsync(async doc => {
    doc.counter++;
    await doc.save();
    console.log(`Doc ${doc._id} saved, sleeping for 10 seconds...`);
    await sleep(10);
  });

  console.log('Done with documents, closing cursor...');
  await cursor.close();
  console.log('Closed cursor.');
}

function sleep (seconds) {
  return new Promise(resolve => setTimeout(resolve, seconds * 1000));
}

run().catch(console.error);

<omitted 1,000 docs here>
Done with documents, closing cursor...
Closed cursor.

[Cooya]

Thank you for helping me with this issue.
You have to make it last longer because last time I ran the script, the error occurred after 3.5 hours.
In my production code, the error occurs approximately every 1 hour with the cursor processing a few dozens of thousands documents.

[AbdelrahmanHafez]

Running the original script would take ~28 hours which isn't an actionable way to demonstrate the issue.

Let's leave this open for now, hopefully someone facing the issue will come up with a script that reproduces the issue in a more actionable manner.

[Cooya]

If you increase the sleeping time up to 30 seconds, the error will occur after ~1 hour, which is much shorter.

[AbdelrahmanHafez]

Using a delay of 40 seconds causes the script to throw an error after some time.

I don't know if socketTimeoutMS should apply to cursors, even when noCursorTimeout is set to true, but I suspect that increasing socketTimeoutMS to 50 seconds will fix the issue. I'll run it and post the results.

MongoError: cursor id 877968452135 not found
    at MessageStream.messageHandler (gh8720\node_modules\mongodb\lib\cmap\connection.js:261:20)
    at MessageStream.emit (events.js:311:20)
    at processIncomingData (gh8720\node_modules\mongodb\lib\cmap\message_stream.js:144:12)
    at MessageStream._write (gh8720\node_modules\mongodb\lib\cmap\message_stream.js:42:5)
    at doWrite (_stream_writable.js:441:12)
    at writeOrBuffer (_stream_writable.js:425:5)
    at MessageStream.Writable.write (_stream_writable.js:316:11)
    at Socket.ondata (_stream_readable.js:714:22)
    at Socket.emit (events.js:311:20)
    at addChunk (_stream_readable.js:294:12)
    at readableAddChunk (_stream_readable.js:275:11)
    at Socket.Readable.push (_stream_readable.js:209:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:186:23) {
  ok: 0,
  errmsg: 'cursor id 877968452135 not found',
  code: 43,
  codeName: 'CursorNotFound',
  name: 'MongoError',
  [Symbol(mongoErrorContextSymbol)]: { isGetMore: true }
}

[AbdelrahmanHafez]

So, running this with socketTimeoutMS: 50000 makes the app throw an error after 1 hour.

Currently testing whether this is a mongoose issue or if it happens when running with the native mongodb driver.

[AbdelrahmanHafez]

So, running the native driver version of this:

const { MongoClient } = require('mongodb');

const delayInSeconds = 40;

const startDate = new Date();

async function run () {
  try {
    const connection = await MongoClient.connect('mongodb://localhost/gh8720', { useNewUrlParser: true, useUnifiedTopology: true, poolSize: 10, socketTimeoutMS: 50000 });
    const User = connection.db('gh8720').collection('users');

    await User.deleteMany();

    const users = Array.from({ length: 1000 }).map((_, i) => ({ counter: 0, _id: i + 1 }));

    await User.insertMany(users);


    const cursor = User.find().addCursorFlag('noCursorTimeout', true);

    while (await cursor.hasNext()) {
      const doc = await cursor.next();
      await User.updateOne({ _id: doc._id }, { $set: { counter: doc.counter + 1 } });

      console.log(`Saved ${doc._id}, sleeping for ${delayInSeconds} seconds...`);

      await sleep(delayInSeconds);
    }


    console.log('Closing cursor...');
    await cursor.close();
    console.log('Closed cursor successfully.');
  } catch (err) {
    console.log(err);
  }

  console.log(`Started at: ${startDate}, finished at: ${new Date()}`);
}


function sleep (seconds) {
  return new Promise(resolve => setTimeout(resolve, seconds * 1000));
}

run().catch(console.error);

[AbdelrahmanHafez]

Yep, as I guessed, it's an underlying library issue.

Running with the native driver has the same issue, for some reason after exactly 1 hour, 7 minutes, 20 seconds.

I created an issue on jira, let's follow up there.

[Cooya]

Thank you for taking in charge 👍
Is it exactly 1 hour, 7 minutes, 20 seconds every time you run it ?

[AbdelrahmanHafez]

Happy to help.

Yep, there isn't anything special about the time 1 hour 7 minutes 20 seconds, though.

The issue happens because of this (includes a possible fix).

TL;DR:
The session expires after 30 minutes if no commands are being sent to the MongoDB even if noCursorTimeout is set to true.

Note that a cursor works in batches, so if your first batch (101 documents) in this case take more than 30 minutes, when the cursor tries to fetch the new the session has already expired, and Mongo will throw an error. The fix is to explicitly start a session, and refresh it before it expires, for more on that, check out the link provided.

[Cooya]

Ok so I guessed right in the first place.
I did not know the cursor default batch size was 101, which explains the threshold time of 4040 seconds.
To fix the issue, I can :

• execute the command refreshSessions from time to time while processing the cursor
• reduce the cursor default batch size to fit under the session idle timeout of 30 minutes
• downgrade my Mongoose version (that's what I have done temporarily)

[AbdelrahmanHafez]

Yep, your guess was correct!
I don't know how downgrading mongoose could fix the issue, knowing that this happens on the mongo side of things, but if it fixes it, who am I to ask?

If I were you, I would refresh the session every 29 minutes, reducing the default batch size doesn't seem optimal because it might impact performance negatively.

Do you need any further assistance with this issue?

[Cooya]

Yes I don't know why neither, but if the issue comes from MongoDB, it probably downgrades the MongoDB version used as well.

Wouldn't it be nice to mention the Session Idle Timeout in the Mongoose documentation ? This way people would be aware that this issue could happen.

[AbdelrahmanHafez]

I don't think mongoose nor the driver can control the version of the database they're connected to, weird behavior indeed.

I don't know if the right place to put this is mongoose documentation, this is a purely MongoDB's issue. Curious to know what @vkarpov15 thinks about this.

[Cooya]

It's not possible that the issue appears after the upgrade of the driver ?
With Mongoose v5.5.7 (MongoDB driver v.3.2.3), I confirm that the timeout error does not occur.

[AbdelrahmanHafez]

Actually, after re-reading the MongoDB docs, it specifies that this behavior is implemented in the drivers and the shell.

Starting in MongoDB 3.6, MongoDB drivers and the mongo shell associate all operations with a server session, with the exception of unacknowledged write operations.

So, yes. That's probably the case.

[vkarpov15]

Might be worth mentioning https://docs.mongodb.com/manual/reference/method/cursor.noCursorTimeout/#session-idle-timeout-overrides-nocursortimeout in the query docs. Admittedly keeping a cursor idle for 30 minutes is not a common use case, but something to make sure people are aware of.