Bug: The rollback function attempts to _changeItemState on items that do not exist in the database

[chrisbobbe]

Two error messages:

Transaction (...) was cancelled after being inactive for 5 seconds.

Exception in setTimeout callback: MongoError: Cannot create field 'state' in element {4: null}

The second is very puzzling, and I think it can be handled better. More importantly, my transaction failed and was incorrectly rolled back.

The cause of the second error message:

My own code threw an unrelated error after performing some inserts, updates, and deletes, but before tx.commit was called. Some of these inserts, updates, and deletes were called with instant: true, and some weren't. From looking at transactions-common.js, I can see that the instant operations are recorded in the database as soon as they are called, whereas non-instant operations are not recorded in the database until tx.commit is called. All operations, whether instant or not, are recorded in memory on the server in self._items. This means that there is some time, between performing an operation and calling tx.commit, during which the server's record of performed operations might contain more items than the transaction document in the database. But in my case, and due to my own code error, tx.commit was never called, so this difference in record-keeping persisted. It persisted beyond the 5-second inactivity timeout, which called rollback, and this became a problem.

The rollback method uses self._items as its record of operations that need to be reversed. rollback attempted to loop over 6 items, 4 of which weren't recorded in the database because they weren't done instantly (remember the difference I just described). The following was called 6 times, once for each item stored in self._items:

      self._changeItemState({
        txid: self._transaction_id,
        index: (items.length - 1) - index, // Because order was reversed for rollback
        state: "rolledBack"
      });

_changeItemState writes to the transaction document like so:

Transact.prototype._changeItemState = function (data) {
  // Need to make a write to the transaction record, marking this action as `done`
  var m = {};
  m["items." + data.index + ".state"] = data.state;
  Transactions.update({_id: data.txid}, {$set: m});
}

Looking at the intended behavior, the first write to the transaction document will be to index 5 of the items array, because the rollbacks are done in reverse order. Next will be 4, then 3, and so on, down to 0. Since items[5] does not exist in the database, however, the array will have to be expanded from containing 2 items to containing 6 items, making index 5 available. Mongo seems to do this automatically by writing null to indexes 2, 3, and 4, and writing to index 5 correctly. So far, no error. But on the next iteration of the loop, it's time to write to items[4]. Do you see the problem? Right -- items[4] is now null, and you can't write a property such as .state to null. Read the second error message again, and this time it should make sense!

The solution:

The most obvious thing I should have done is not write buggy code. And yet it happened, triggering an incomplete rollback of the transaction, and a very cryptic error message. Can someone comment on the feasibility of somehow getting self._items to sync up with the items array on the transactions document in the database, even when commit doesn't get called? Perhaps this can be done at the beginning of the rollback function?

[JackAdams]

Thank you for the comprehensive analysis of the problem and my apologies for the weakness in the package. This certainly needs addressing. If possible, can I take a look at the database record (in the tx.transactions collection) for this particular transaction? Also, just to confirm, you're still using tx.softDelete = false; (the default setting), right?

[chrisbobbe]

Thanks so much for your quick response, and for this very useful package! Yes, we are using the default tx.softDelete = false.

If it's relevant, we are using Simple Schema, and I can send you the schemas for all of our collections if you would like. We made sure each of them includes the following (see #2):

    'transaction_id': {
        type: String,
        regEx: SimpleSchema.RegEx.Id,
        optional: true
    },
    deleted: {
        type: Number,
        optional: true
    }

I'd be happy to share the document in tx.transactions, but it is fairly large and I'd rather avoid searching manually for any sensitive information that we would not like to post publicly, if possible. Is there a way I can send this data to you privately?

[JackAdams]

This is just a for-the-record, and has no impact on the issue at hand, but at some stage I changed the schema for deleted from unix timestamp to ISO Date. So the package tries to extend the simpleSchema definitions automatically for each collection with:

deleted: {
  type: Date,
  label: "Deleted",
  optional: true
},
transaction_id: {
  type: String,
  label: "transaction_id",
  optional: true
}

That's all right about sending the document in tx.transactions. I think I've got a pretty good idea of what's happening, based on your thorough description above.

Not sure when I'll be able to roll out a fix - I'm pretty slammed at the moment - but it's now on the to-do list.

[chrisbobbe]

Oh nice! So I don't have to manually extend my schemas with that, it sounds like.

Let me know if you have a general idea of what should be done, and I can try to put together a pull request.

[JackAdams]

Right. The package should automatically extend any schema for you.

I'm going to try to reproduce the error with test and then go from there.

I'd thought the whole items array was written to the database at the start of a transaction, regardless of whether the writes are instant or have been made or not made, meaning it was always consistent with the in-memory version, but it seems this isn't always the case.

Let me do some poking around and I'll give a call out if I could use some help.

[chrisbobbe]

Thank you! Please let me know if I can help out at all.