Document.create callback called twice

[nickasd]

In the following code, both error 1 and error 2 get logged, which looks like the callback to doc.create is getting called twice, and both times the error is Error: Delete component '0' does not match deleted text 'a'. Some initial analysis done by @alecgibson in #162.

var ShareDB = require('sharedb');
var sharedb = new ShareDB();
var connection = sharedb.connect();
var doc = connection.get('files', '0');
doc.create({content: 'asdf'}, (error) => {
    if (error) {
        console.log('error 1');
        console.error(error);
    } else {
        var ops = [{p: 0, d: '0'}];
        var op = [{p: ['content'], t: 'text0', o: ops}];
        doc.submitOp(op, (error) => {
            if (error) {
                console.log('error 2');
                console.error(error);
            } else {
                console.log('success');
            }
        });
    }
});

[alecgibson]

My thoughts replicated for completeness:

I've had a very quick dig, and it looks like it has to do with the combination of _clearInflightOp and _hardRollback.

_clearInflightOp tries to call each of the callbacks before clearing the inflightOp. In this case, that includes calling a callback which will produce an error. The _hardRollback then also calls the create callback, which - as you correctly point out - means that we call the creation op callback twice.

We've got something like this happening:

• submit creation
• set creation to inflight op
• receive acknowledgement of creation
• call the creation op callback
• creation op callback includes a bad op submission
• bad op submission errors
• we attempt to hard rollback
• hard rollback tries to call the create callback again

I don't have a lot of time to think about how best to handle this right now - may be best to chat with @nateps and @ericyhwang in Wednesday's meeting. Potentially best to also move this to a new issue.

My first instinct is that when we invoke a callback, we should first dissociate it from the op it was attached to, so that we don't get this repeat call (that or mark it as called, so we don't try to call it again), but I don't know what the ramifications of that behaviour might be.

Actually, now thinking about it a bit more, perhaps we should be moving more towards having a light Callback class, which remembers if it was called or not, because we're already trying to keep track of that sort of thing anyway.

[ericyhwang]

Thanks Nick for writing a nice self-contained repro code, and Alec for doing the sleuthing!

Looking at the code for Doc. _clearInflightOp, which Alec helpfully linked, I noticed something interesting - this.inflightOp = null happens only after all the callbacks are called.

In the test code, the first callback submits another op, so at the point when _hardRollback is called, there is still an inflightOp present. That's what causes _hardRollback to then call the callback again.

Potential fix

I tested having _clearInflightOp do this.inflightOp = null prior to invoking callbacks, and that does fix the double-callback issue in the test code above. All the sharedb tests pass with the change, and actually, _hardRollback similarly clears out local op state first.

This is the diff in sharedb/lib/client/doc.js, if you want to try applying it locally in your installed node_modules and see if it fixes your original issue.

diff --git a/lib/client/doc.js b/lib/client/doc.js
index 95776db..f7a621f 100644
--- a/lib/client/doc.js
+++ b/lib/client/doc.js
@@ -920,9 +920,11 @@ Doc.prototype._hardRollback = function(err) {
 };
 
 Doc.prototype._clearInflightOp = function(err) {
-  var called = callEach(this.inflightOp.callbacks, err);
-
+  var inflightOp = this.inflightOp;
   this.inflightOp = null;
+
+  var called = callEach(inflightOp.callbacks, err);
+
   this.flush();
   this._emitNothingPending();

I'd still like to check with @nateps on Wednesday, to see if he can think of any subtle issues with clearing this.inflightOp first prior to calling callbacks.

[alecgibson]

@ericyhwang I think that seems like a pretty good solution to me. The other thing that suddenly struck me is that this kind of "smells" a bit - we're getting synchronous behaviour leaking into an asynchronous action. Maybe the "real" solution is something like this?

diff --git a/lib/client/doc.js b/lib/client/doc.js
index 95776db..26288c4 100644
--- a/lib/client/doc.js
+++ b/lib/client/doc.js
@@ -658,16 +658,18 @@ Doc.prototype._submit = function(op, source, callback) {
     if (this.type.normalize) op.op = this.type.normalize(op.op);
   }

+  var doc = this;
   try {
     this._pushOp(op, callback);
     this._otApply(op, source);
   } catch (error) {
-    return this._hardRollback(error);
+    return process.nextTick(function () {
+      doc._hardRollback(error);
+    });
   }

   // The call to flush is delayed so if submit() is called multiple times
   // synchronously, all the ops are combined before being sent to the server.
-  var doc = this;
   process.nextTick(function() {
     doc.flush();
   });

[alecgibson]

I've done a bit more digging and there's a related issue we should address. If I use the code I outlined above, the following test case still fails (NB: all other tests pass):

  it('issue test', function (done) {
    var connection = this.backend.connect();
    var doc = connection.get('files', '0');
    doc.create({ content: 'asdf' }, (error) => {
      if (error) return done(error);
      var ops = [{ p: 0, d: '0' }];
      var op = [{ p: ['content'], t: 'text0', o: ops }];
      doc.submitOp(op, (error) => {
        expect(error).to.be.ok();
        done();
      });
    });
  });

It fails because an error gets emitted outside of the callbacks. This is because we get something like the following:

• submit creation
• creation success
• submit bad op
• bad op pushed onto pendingOps
• op sent to server (although I can't figure out what's triggering this???)
• _otApply throws, which triggers a _hardRollback
• _hardRollback handles all the callbacks
• bad op returned from server with an error, but no callbacks left to call, so it emits

[ericyhwang]

Fix for this was just published in [email protected]

Closing this out now!