Parallel calls to performed to MongoDB hang-up without entering middleware

7 min read Original article ↗

Do you want to request a feature or report a bug?
Reporting a Bug

What is the current behavior?
Currently, I am connected to a replica-set and am performing various read and write operations. On further exploring, I found out that the replica-set has an election time when the primary step's down. During the down time any read and write calls return an error, so the aim is to ensure that any queries fired during the election-time which result in an error are re-fired.

Now a Test Schema has been defined, and along with an error middleware has been defined for the schema for save operation. Now the expectation is that when the query is fired and an error occurs the error middleware should be called, which works perfectly for single calls, but fails when multiple parallel requests are made and are put in hold via Promise.all()

The script I am using to generate the error is as follows:

const mongoose = require('mongoose');
const {MongoError, isRetryableError: isRetryableMongoError} = require('mongodb-core/lib/error');

const config = {
	uri: 'mongodb://mongo-node1:27018,mongo-node2:27019,mongo-node3:27020/test?replicaSet=rs0&w=majority&retryWrites=true'
};

const options = {
	autoIndex: true,
	// sets how many times to try reconnecting
	reconnectTries: Number.MAX_VALUE, // alternatively set it to a lower value
	// sets the delay between every retry (milliseconds)
	reconnectInterval: 1000,
	// If not connected, return errors immediately rather than waiting for reconnect
	bufferMaxEntries: 0,
	// The maximum number of sockets the MongoDB driver will keep open for this connection.
	poolSize: 100,
	// Wait time before killing the idle connection
	socketTimeoutMS: 15000,
	useCreateIndex: true,
	// Use the new url string parser
	useNewUrlParser: true,
	useFindAndModify: false
};

mongoose.set('bufferCommands', false);
mongoose.set('debug', true);

function sleep(timeout) {
	console.log('Sleep for ms: ' + timeout);
	return new Promise((resolve) => {
		return setTimeout(() => {
			console.log('Wake up after ms: ' + timeout);
			resolve();
		}, timeout);
	});
}

async function orm() {

	await connectToMongo();

	mongoose.connection.on('error', console.error.bind(console, 'Connection Error: '));
	mongoose.connection.on('open', console.log.bind(console, 'connection open:'));
	mongoose.connection.on('disconnecting', console.log.bind(console, 'connection disconnecting:'));
	mongoose.connection.on('disconnected', console.log.bind(console, 'connection disconnected:'));
	mongoose.connection.on('close', console.log.bind(console, 'connection close:'));
	mongoose.connection.on('reconnected', console.log.bind(console, 'connection reconnected:'));
	mongoose.connection.on('reconnectFailed', console.log.bind(console, 'connection reconnectFailed:'));
	mongoose.connection.on('connected', (...args) => console.log('Connection Open', ...args));
	mongoose.connection.on('fullsetup', (...args) => console.log('fullsetup Connection Open', ...args));
	mongoose.connection.on('all', (...args) => console.log('all Connection Open', ...args));
	mongoose.connection.on('left', (type) => console.log('-> left', type));
	mongoose.connection.on('joined', (type) => console.log('-> joined', type));

	let TestSchema = new mongoose.Schema({answer: Number}, {collection: 'Test'});

	TestSchema.post('save', async function (err, doc, next) {
		this.isNew = true;
		console.log('save Error middleware');
		if (isRetryableError(err)) {
			await sleep(10000);
			err.retry = true;
		}
	});

	TestSchema.post('findOne', async function (err, result, next) {
		// @done
		console.log('find one Error middleware');
		if (isRetryableError(err)) {
			await sleep(5000);
			err.retry = true;
		}
	});

	let Test = mongoose.model('Test', TestSchema);
	let promiseResolve = [];

	console.log('Sleep Now');
	await sleep(10000);
	console.log('Awake');

	try {
		for (let i = 0; i < 500; i++) {
			// await loadIt(i); // ------------ This works
			promiseResolve.push(loadIt(i));	// ---------------- This fails
			// loadIt(i);	// ---------------- This also fails
		}
		const result = await Promise.all(promiseResolve);
		console.log('I need to be printed in the output');
		console.log(result);
	} catch (err) {
		console.log('Inside the Catch');
		console.error(err);
	}

	async function connectToMongo() {
		let result = await mongoose.connect(config.uri, options);
		console.log(result);
		console.log('MongoDB Connection has been established successfully.');
		return result;
	}

	async function loadIt(iteration) {

		let result = {read: true, write: true};

		let test = new Test({answer: iteration});
		return await save(test, 0);

		// return await findOne(Test, {answer: iteration}, 0);
	}

}

async function save(instance, level = 1) {
	level++;
	try {
		console.log('Saving Now' + 'Level: ' + level);
		await instance.save();
		console.log('Saved' + 'Level: ' + level);
	} catch (error) {
		console.log('Got an Error: ' + error.toString() + 'Level: ' + level);
		if (error.retry) {
			console.log('Retrying the Error mentioned above' + 'Level: ' + level);
			try {
				console.log('Recurring call to the save method' + 'Level: ' + level);
				const result = await save(instance, level);
				console.log('Done recurring call');
				level--;
				return result;
			} catch (error) {
				console.log('Inside Recurring Call catch with error: ' + error.toString() + 'Level: ' + level);
				if (isDuplicateKeyError(error)) {
					console.log('Yes, it\'s a duplicate key error, I\'ll be returning control to the main caller' + 'Level: ' + level);
					level--;
					return instance;
				}
				level--;
				throw error;
			}
		} else {
			console.log('Cannot Retry the above mentioned error' + 'Level: ' + level);
		}
		console.log('Now I\'ll throw the main error: ' + error.toString() + 'Level: ' + level);
		level--;
		throw error;
	}
	level--;
	console.log('4 - Returning the call');
	return instance;
}

async function findOne(query, condition, level = 1) {
	level++;
	try {
		console.log('Find One Now' + 'Level: ' + level);
		let result = await query.findOne(condition);
		console.log('4 - Returning the call');
		return result;
	} catch (error) {
		console.log('Got an Error: ' + error.toString() + 'Level: ' + level);
		if (error.retry) {
			console.log('Recurring call to the save method' + 'Level: ' + level);
			let result = await findOne(query, condition, level);
			console.log('Yes, got the result from err, I\'ll be returning control to the main caller' + 'Level: ' + level);
			level--;
			return result;
		} else {
			console.log('Cannot Retry the above mentioned error' + 'Level: ' + level);
		}
		console.log('Now I\'ll throw the main error: ' + error.toString() + 'Level: ' + level);
		level--;
		throw error;
	}
}

orm();

function isRetryableError(error) {
	// Should be retryable mongo error
	// OR Should be a transient network error - errorLabels: [ 'TransientTransactionError' ],
	// OR shoulod have the string regex
	// // MongoError: no connection available for operation and number of stored operation > 0
	// // MongoError: no connection available to server mongo-node1:27018
	return isMongoError(error) && (
		isRetryableMongoError(error)
		|| isTransientError(error)
		|| (/no connection available for operation/).test(error)
		|| (/no connection available to server/).test(error)
	);
}

function isTransientError(error) {
	return isMongoError(error) && error.hasErrorLabel('TransientTransactionError');
}

function isMongoError(error) {
	return error instanceof Error && error instanceof MongoError;
}

function isDuplicateKeyError(error) {
	return isMongoError(error) && error.code === 11000;
}

If the current behavior is a bug, please provide the steps to reproduce.
Have a replica-set in place, and install Mongoose v5.6.12
To generate the issue,

  1. Run the existing code,
  2. When it starts printing Saving NowLevel: 1, force a the primary node in the replica-set to step down using rs.stepDown()
  3. After step-down the console message save Error middleware present in the schema error middleware would be printed indicating an error in the query performed.
    Note: The replica-set primary node needs to step-down before the first SavedLevel: 1 console message is printed. If the time for that seems to less, then you can increase the loop iteration to 1000 or a greater number

What is the expected behavior?
The expectation is that since 500 save(or any other call: find/remove~same scenario) calls are being made, based on the for-loop, 500 error messages would be printed, and consecutively continue processing ahead, but this doesn't happen, only the first error message is printed and the execution hangs. The remaining promises never resolve, resulting in the execution waiting at:

const result = await Promise.all(promiseResolve);

Actual Output on step-down of Replica:

Mongoose: Test.insertOne({ _id: ObjectId("5d6f7c57610b5802ed81a80c"), answer: 499, __v: 0 }, { session: null })
connection disconnected:
-> left primary
save Error middleware
Sleep for ms: 10000
-> joined primary
Connection Open
connection reconnected:
-> joined secondary
Wake up after ms: 10000
Got an Error: MongoError: no connection available to server mongo-node1:27018Level: 1
Retrying the Error mentioned aboveLevel: 1
Recurring call to the save methodLevel: 1
Saving NowLevel: 2
Mongoose: Test.insertOne({ _id: ObjectId("5d6f7c57610b5802ed81a619"), answer: 0, __v: 0 }, { session: null })
SavedLevel: 2
4 - Returning the call
Done recurring call

Expected:

Mongoose: Test.insertOne({ _id: ObjectId("5d6f7c57610b5802ed81a80c"), answer: 499, __v: 0 }, { session: null })

//////////////////////////////////////////////
save Error middleware
Sleep for ms: 10000
///////////////////////////////////////////// This block should be continuously repeated
-> joined primary
Connection Open
connection reconnected:
-> joined secondary
////////////////////////////////////////// Before the following block of Code
Wake up after ms: 10000
Got an Error: MongoError: no connection available to server mongo-node1:27018Level: 1
Retrying the Error mentioned aboveLevel: 1
Recurring call to the save methodLevel: 1
Saving NowLevel: 2
Mongoose: Test.insertOne({ _id: ObjectId("5d6f7c57610b5802ed81a619"), answer: 0, __v: 0 }, { session: null })
SavedLevel: 2
4 - Returning the call
Done recurring call

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version.

  • NodeJS: 12.9.0
  • Mongoose: 5.6.12 (From node_modules/mongoose/package.json)

The solution for retry strategy in try-catch is loosely based on the blog on How To Write Resilient MongoDB Applications