JackAdams / meteor-transactions

App level transactions for Meteor + Mongo
http://transactions.taonova.com/
MIT License
113 stars 16 forks source link

Update with $addToSet and $set modifiers does not get reversed correctly #13

Closed rjsmith closed 9 years ago

rjsmith commented 9 years ago

Hi, I think I have found a bug relating to processing updates which have multiple modifiers (my example has a $addToSet and a $set in the same collection.update() statement that is wrapped in a tx transaction)

I added some console logging to the makeUpdate function to see what is going on .. please see trace below:

command: $addToSet
updateMap: { performanceRequirementBTPairs:
   { requirementId: 'umwhud3Wu5xsJEFZ3',
     baselineParameterId: 'H3ukkaC3A2YL7STyk',
     targetParameterId: 'yweWLmfTjHs6ExLRu' } }
inverse op:  { command: '$pull',
  data:
   { performanceRequirementBTPairs:
      { requirementId: 'umwhud3Wu5xsJEFZ3',
        baselineParameterId: 'H3ukkaC3A2YL7STyk',
        targetParameterId: 'yweWLmfTjHs6ExLRu' } } }
Pushed update command to stack: mei6bjnaGCsNCWhspwith updateData:{"command":"$addToSet","data":{"performanceRequirementBTPairs":{"requirementId":"umwhud3Wu5xsJEFZ3","baselineParameterId":"H3ukkaC3A2YL7STyk","targetParameterId":"yweWLmfTjHs6ExLRu"}}}
command: $set
updateMap: { lastUpdated: Fri Mar 13 2015 18:48:19 GMT+0000 (GMT),
  lastUpdatedBy: 'mWqohERNZKkTqS4k6' }
inverse op:  { command: '$set',
  data:
   { lastUpdated: Fri Mar 13 2015 18:48:19 GMT+0000 (GMT),
     lastUpdatedBy: 'mWqohERNZKkTqS4k6' } }
Pushed update command to stack: mei6bjnaGCsNCWhspwith updateData:{"command":"$set","data":{"lastUpdated":"2015-03-13T18:48:19.685Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}

Beginning commit with transaction_id: mei6bjnaGCsNCWhsp
**makeUpdates updates:{"$addToSet":{"performanceRequirementBTPairs":{"requirementId":"umwhud3Wu5xsJEFZ3","baselineParameterId":"H3ukkaC3A2YL7STyk","targetParameterId":"yweWLmfTjHs6ExLRu"}},"$set":{"lastUpdated":"2015-03-13T18:48:19.685Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}
**makeUpdates updateData:{"command":"$set","data":{"lastUpdated":"2015-03-13T18:48:19.685Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}
**makeUpdates inverseData:{"command":"$set","data":{"lastUpdated":"2015-03-13T18:48:19.596Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}
pushToRecord:{"update":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.685Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]},"inverse":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.596Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]}}
Executed update
**makeUpdates updates:{"$addToSet":{"performanceRequirementBTPairs":{"requirementId":"umwhud3Wu5xsJEFZ3","baselineParameterId":"H3ukkaC3A2YL7STyk","targetParameterId":"yweWLmfTjHs6ExLRu"}},"$set":{"lastUpdated":"2015-03-13T18:48:19.685Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}
**makeUpdates updateData:{"command":"$set","data":{"lastUpdated":"2015-03-13T18:48:19.685Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}
**makeUpdates inverseData:{"command":"$set","data":{"lastUpdated":"2015-03-13T18:48:19.596Z","lastUpdatedBy":"mWqohERNZKkTqS4k6"}}
pushToRecord:{"update":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.685Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]},"inverse":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.596Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]}}
Executed update
Commit reset transaction manager to clean state

You can see that makeUpdate is called twice (correctly) from the commit function. But, each invocation has the same updateData and inverse arguments (both from the 2nd update item).

This is the resulting tx.Transaction document:

txDoc:{"_id":"mei6bjnaGCsNCWhsp","context":{"partitionId":"uGzdkFRYveuTMtjd2","name":"IET-VVB1Q50","tag":"A-IET"},"description":"ietAttachPerfReqt","items":{"updated":[{"collection":"iet","_id":"iuqg7gmaFipQmbjL3","update":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.685Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]},"inverse":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.596Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]}},{"collection":"iet","_id":"iuqg7gmaFipQmbjL3","update":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.685Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]},"inverse":{"command":"$set","data":[{"key":"lastUpdated","value":"2015-03-13T18:48:19.596Z"},{"key":"lastUpdatedBy","value":"mWqohERNZKkTqS4k6"}]}}]},"timestamp":1426272499679,"user_id":"mWqohERNZKkTqS4k6"}

You can see that the $addToSet update has disappeared, and replaced with a duplicate copy of the $set update.

My guess is that there is a problem in binding / capturing the arguments when the makeUpdate calls are added to the _executionStack list in the Transact.prototype.update function at line https://github.com/JackAdams/meteor-transactions/blob/master/lib/transactions_common.js#L571

It's weird, because the actual committed updates work OK (they come from the updates array, which is OK?), but the transaction data recorded in tx.Transactions uses the updateData andinversearguments (which are wrong for the first update), which is why the subsequenttx.undo()` in my test only reverses the second original update item , and not the first.

JackAdams commented 9 years ago

Wow! Thanks for identifying this. A nasty little bug with closures and changing of the surrounding data context. I did reproduce it (thanks to your thorough analysis above) and have just released a new version of the package (0.6.16) with the fix.