I'm trying to implement some sort of Optimist Concurrency Control for a backend based on node & mongo.
Assuming the following:
User collection structured as such
{
"_id" : ObjectId,
"username" : String,
"password" : String,
"firstName" : String,
"lastName" : String,
"userData": {
"comments": []
},
"__occ": Number
}
A Comment collection structured as such
{
"_id" : ObjectId,
"text" : String
}
My backend defines a route to create new Comment and, once created, adds its ID to its creator's userData.comments array.
To test this route I created a small script which calls the route 10 times to create 10 Comments (using a for loop, nothing fancy)
I started to use mongoose but I had concurrency issues so I tried to use the native mongodb driver instead since I read that Mongo operations on a single document are supposed to be atomic
To do so I used the __occ field to flag the status of a document and modified my update request to (1) query on the _id plus __occ field ; (2) add a {$inc{ "__occ": 1}} to increment the version number. If an update fails, I assume that I had a conflict, so I reload the object and try again. (see code below)
I basically can't get the thing to work, having various weirdness happening. Most of the time after a few successful iterations (1 or 2), a load (see console.log() with "BGCHECK #2.2" flag) returns an old (i.e. low __occ number) object yet the next update succeed and my comments array is messed up since all the changed made in the meantime are overwritten.
On the 10 new comments I was expecting, I have 4 or 5 once the loop completes (yet I have no exceptions whatsoever and never more than 10 top retries)
What am I doing wrong?
Edited sample "weirdness" when suddenly a find() returns an 'older' object. Message 'BGCHECK #2.2' is supposedly printed after I reload the object from the mongo DB to get the 'latest' values (first number is the timestamp of the console.log()) Last 4 lines are interesting: I had a 5 elements array which was returned twice already by the find() and then I somehow loose the last 2 entries A similar situation also occurs once on line 16 when I loose one element ("575e500df16b51b3f64994c7")
1465798669701 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994b9 to set => self.__occ = 0 => concurrency error => new object __occ=1 set = (#1 elts, ["575e500df16b51b3f64994b8"])
1465798669708 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c7 to set => self.__occ = 0 => concurrency error => new object __occ=1 set = (#1 elts, ["575e500df16b51b3f64994b8"])
1465798669712 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c6 to set => self.__occ = 0 => concurrency error => new object __occ=1 set = (#1 elts, ["575e500df16b51b3f64994b8"])
1465798669714 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c8 to set => self.__occ = 0 => concurrency error => new object __occ=1 set = (#1 elts, ["575e500df16b51b3f64994b8"])
1465798669722 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cb to set => self.__occ = 0 => concurrency error => new object __occ=1 set = (#1 elts, ["575e500df16b51b3f64994b8"])
1465798669725 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cd to set => self.__occ = 0 => concurrency error => new object __occ=2 set = (#2 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9"])
1465798669726 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994ca to set => self.__occ = 0 => concurrency error => new object __occ=2 set = (#2 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9"])
1465798669728 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c9 to set => self.__occ = 0 => concurrency error => new object __occ=2 set = (#2 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9"])
1465798669732 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cc to set => self.__occ = 0 => concurrency error => new object __occ=2 set = (#2 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9"])
1465798669741 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c7 to set => self.__occ = 1 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669750 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c6 to set => self.__occ = 1 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669752 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c8 to set => self.__occ = 1 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669758 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cb to set => self.__occ = 1 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669764 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994ca to set => self.__occ = 2 => concurrency error => new object __occ=4 set = (#4 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994c7"])
1465798669772 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c9 to set => self.__occ = 2 => concurrency error => new object __occ=4 set = (#4 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994c7"])
1465798669778 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cc to set => self.__occ = 2 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669792 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c8 to set => self.__occ = 3 => concurrency error => new object __occ=4 set = (#4 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994cc"])
1465798669794 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c6 to set => self.__occ = 3 => concurrency error => new object __occ=4 set = (#4 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994cc"])
1465798669798 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cb to set => self.__occ = 3 => concurrency error => new object __occ=4 set = (#4 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994cc"])
1465798669815 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994ca to set => self.__occ = 4 => concurrency error => new object __occ=5 set = (#5 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994cc","575e500df16b51b3f64994c6"])
1465798669825 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c9 to set => self.__occ = 4 => concurrency error => new object __occ=5 set = (#5 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994cc","575e500df16b51b3f64994c6"])
1465798669838 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994cb to set => self.__occ = 4 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669864 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994ca to set => self.__occ = 5 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669869 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c9 to set => self.__occ = 5 => concurrency error => new object __occ=3 set = (#3 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd"])
1465798669940 >>> BGCHECK #2.2 OCC >>> Trying to add 575e500df16b51b3f64994c9 to set => self.__occ = 3 => concurrency error => new object __occ=4 set = (#4 elts, ["575e500df16b51b3f64994b8","575e500df16b51b3f64994b9","575e500df16b51b3f64994cd","575e500df16b51b3f64994ca"])
PS: I can share more detailed logs or anything if useful
Code from the various pieces I mentioned
Test script
const when = require('when');
const request = require('request-promise');
let promiseArray = [];
for (let i = 0; i < 10; i++) {
promiseArray.push($createComment("Test comment #"+i));
}
return when.all(promiseArray).then(function(array) {
// do something with array
}
function $createComment(text) {
let options = {
method: "POST",
uri: "<uri>",
json: true
};
return request(optionsToMyRoute);
}
Backend code
app.post("<uri>", function(req, res, next() {
// do create Comment
const commentId = // id of the comment I just created; no issue here so I'm skipping that code
const creator = // User class that adds a few methods including addToSet & dbAddToSet (see below)
creator.addToSet("userData.comments", commentId);
});
User class
// User objects have the same properties as the underlying's Collection (_id, __v, userData.comments, ...)
User.prototype.addToSet = function(property, value) {
const self = this;
function $addToSet(dbObj, retries) {
if (retries === undefined) retries = 100;
return dbObj.dbAddToSet(property, value, options).then(
function(valuesAddedList) {
return when.resolve(valuesAddedList);
}, function(err) {
if (err instanceof ConcurrencyDBError) { // Own Error class to identify & handle conflicts
let $refreshedObject = self._convert(err.object); // convert a JSON into a proper User object
const $dbObjProp = u.getProperty(dbObj, property);
const $refreshedObjProp = u.getProperty($refreshedObject, property);
debug("::ADDTOSET::$ADDTOSET::LOG Concurrency error trying to add %s to {__v: %d, set: #%s elts} => retrying with refreshed object {__v: %d, set: #%d elts} (retries=%d)", value, dbObj.__v, $dbObjProp ? $dbObjProp.length : "na", $refreshedObject.__v, $refreshedObjProp ? $refreshedObjProp.length : "na", retries);
if (retries > 0) {
return $addToSet($refreshedObject, retries-1);
} else {
err.message += " => max number of retries reached, failing";
}
}
// else
const message = err.message || "::ADDTOSET::$ADDTOSET::ERROR Unexpected error";
return when.reject(GenericError.create(message, err)); // GenericError is a simple Error wrapper
}
);
}
return $addToSet(self);
}
User.prototype.dbAddToSet = function(property, value, options) {
var self = this;
// Use __occ to ensure we have the proper version of the object
const $id = new ObjectID(self._id);
const query = {
'_id': $id,
'__occ': self.__occ
};
const update = {
'$addToSet': {},
'$inc': {'__occ': 1}
};
let defer = when.defer();
console.log("\t%s >>> BGCHECK #1 >>> Trying to add %s to set => self.__occ = %d, self.set = (#%s elts, %j) (query=%j, update=%j)", Date.now(), value, self.__occ, $property ? $property.length: "na", $property, query, update);
self.$getMongoCollection().updateOne(query, update, { w: "majority", j: true }, function(err, result) {
if (err) return defer.reject(err);
const updateResult = result.result; // Expect a {ok, n, nModified}
if ((updateResult.ok == 1) && (updateResult.n == 0)) {
console.log("\t%s >>> BGCHECK #2.1 OCC >>> Trying to add %s to set => self.__occ = %d => concurrency error, loading new object", Date.now(), value, self.__occ);
self.$getMongoCollection().find({_id: $id}).toArray(function(err, results) {
if (err) return when.reject(err);
const obj = results[0];
// >>> debug
let $objProp = u.getProperty(obj, property);
console.log("\t%s >>> BGCHECK #2.2 OCC >>> Trying to add %s to set => self.__occ = %d => concurrency error => new object __occ=%d set = (#%s elts, %j)", Date.now(), value, self.__occ, obj.__occ, $objProp ? $objProp.length : "na", $objProp);
// <<< debug
return defer.reject(new ConcurrencyDBError(util.format("Concurrency error trying to update Object with __occ == %d", self.__occ), obj));
});
} else {
console.log("\t%s >>> BGCHECK #3 OK >>> Trying to add %s to set => self.__occ = %d => successfull, self.set = (#%s elts, %j) (updateResult=%j)", Date.now(), value, self.__occ, $property ? $property.length: "na", $property, updateResult);
return defer.resolve(true);
}
});
return defer.promise;
}
function $getMongoCollection() {
// returns a properly initialized Mongo collection
}
