Invalid operation error

[iclems]

We've released Firepad in a new product which is broadly used with thousands of users using it on a daily basis and I'm getting a bunch of "The base length of the second operation has to be the target length of the first operation".

I'll update to the latest Firepad (and CodeMirror, maybe) but I wonder if you guys have already had this and would have any clue as to where this could be coming from.

Many thanks

[mikelehen]

Ack. Unfortunately, this is kind of a generic error that starts happening once things have gone wrong. Often times there's a prior exception that breaks firepad's state and so you start getting that error. Seeing the callstack would at least give a hint as to at what stage the error is happening (on user edits or remote edits).

We have had issues with mismatched firepad / CodeMirror versions (CodeMirror 4 changed their events and then CodeMirror 5 broke because we had a hardcoded check for 4 in the version number). So upgrading firepad is definitely a good idea.

Holler if you get more details.

[cben]

I've had such errors when I my own buggy code listened to CodeMirror's change event and sometimes crashed with an exception (which CM handlers should never do). Firepad didn't expect applying changes to CodeMirror to throw, which after some more edits could lead to a corrupted firebad. https://github.com/cben/mathdown/issues/85 contains my debugging. I can reliably reproduce and give more stack traces if it's helpful...

Try using firebase-debug.js instead of firebase.js - it logs a nice warning with a stacktrace if any firebase event handler throws an exception (which includes exceptions thrown by firepad).

---

P.S. Beware that such errors might mean that user's edits are no longer saved, with no indication to the user. Especially if you also see Error: sendOperation() called with invalid operation errors. I'm working on future-proofing myself from similar bugs by indicating to users their edits are not being saved — whatever the reason. Firepad's synced event is not necessarily reliable when corrupted [see https://groups.google.com/d/topic/firepad-io/s1aTZXZniAM/discussion, and https://github.com/cben/mathdown/issues/56 for work in progress on periodically comparing a Firepad.Headless's reconstruction to current editor content — basically works but requires debouncing]

[iclems]

Thanks for the details. Our issue is indeed that sendOperation() called with invalid operation start being thrown and the user keeps typing while others don't see (obviously) what he does.

I'm adding additional error catching to get a better understanding of what's happening on our side. Will let you know.

[vincentwoo]

I see this error occasionally, too, but have never been able to reliably reproduce it. It does worry me, a bit.

[iclems]

Now that we have a larger user base using it daily, I could actually add some additional logging when it happens with the pending operations to try to figure out at least if there seems to be a pattern. Do you guys have any other suggestion of logging which could helps us figure it out? Le lun. 10 août 2015 à 18:43, Vincent Woo [email protected] a écrit :

I see this error occasionally, too, but have never been able to reliably reproduce it. It does worry me, a bit.

— Reply to this email directly or view it on GitHub https://github.com/firebase/firepad/issues/194#issuecomment-129668713.

[mikelehen]

@iclems I'd try to at least get the callstack, in addition to the operations. Even with that, it may be hard to track down, but it's a start. I'd also try to make sure there aren't any exceptions happening prior to this. So if you don't have any global exception catching / reporting, you might want to add it.

Best case scenario would be to find a way to reproduce it though. Maybe you can detect the error and then ask the user what they were doing or something.

[corwin-of-amber]

FWIW, the example in the docs (https://github.com/firebase/firepad/blob/master/examples/code.html) causes "invalid operation" when trying to insert an indented line (e.g. put your cursor after a "{" and press Enter). Right now, this example refers to Firepad 1.1.0. Bumping the version number to 1.1.1 solves the issue.

[mikelehen]

@corwin-of-amber Oops, thanks for the heads-up. I'll get that fixed up.

@iclems Any luck tracking this down?

[iclems]

Have updated everything to same CM/Firepad as github master. Seems fine for now. Will let you know if I get anything again

On Wed, Sep 2, 2015 at 4:43 PM Michael Lehenbauer [email protected] wrote:

@corwin-of-amber https://github.com/corwin-of-amber Oops, thanks for the heads-up. I'll get that fixed up.

@iclems https://github.com/iclems Any luck tracking this down?

— Reply to this email directly or view it on GitHub https://github.com/firebase/firepad/issues/194#issuecomment-137107845.

[mikelehen]

Cool. I'll close this out for now. Holler if you continue to see issues.

[iclems]

I just got a new report, and there was this time indeed an error which happened a bit before:

1. Error: transaction failed: Data returned contains a string greater than 10485760 utf8 bytes in prose… (thrown by Firebase: throw new Error(errorPrefix + "contains a string greater than " + fb.core.util.validation.MAX_LEAF_SIZE_ + " utf8 bytes " + path.toError {snip})

2. After that, Error: sendOperation() called with invalid operation.

[mikelehen]

Interesting... Thanks for passing along! That means a single operation was >10mb, I guess. I guess I should add logic in firepad to split up large ops or something. I'll open a new issue. I'm curious if this was a real use case or somebody doing something unusual though. :-)

[vincentwoo]

I'm going to reopen this issue because I see it routinely on firepad head and I don't think its the transaction size thing.

[vincentwoo]

To add - I think I see the base length mismatch a lot more on mobile devices or older browsers. Could it be string encoding issues?

[mikelehen]

Maybe... but it could also be lots of other things. When you say you "see it routinely", are you talking about crashes (well, exceptions) getting reported back to you? Is this the only exception you see? As I told Clement (and turned out to be the case for him), I generally see this exception after something else has already failed and left things in a bad state. :-/

[vincentwoo]

Yes, we catch these exceptions. They don't generally coincide with other exceptions, so I don't think it's a post-crash thing. Is it possible to amend the firepad code to log more data about this state?

[mikelehen]

Well, it'd be easy to log the two operations. https://github.com/firebase/firepad/blob/master/lib/text-operation.js#L299

But usually the operations aren't very interesting. All you can verify is that indeed they are not valid to be composed together. It might be more interesting to:

1. Try to capture the state of the firepad. What's the reference to the data, and what is the current operation number?
2. Try to capture what user interaction led to the error (undo, inserting a letter, deleting a selection, etc.). Then we could look for patterns.

But I'm not sure the best way to approach that. You certainly can't get that information at the site of the exception. You'd need something much higher-up that is handling the exception...

I forgot to ask. Do you have example callstacks? That might narrow the search for the culprit a little.

[vincentwoo]

Here's an example callstack (obviously the stuff is munged but you can see the general flow):

This one is the client trying to process a remote op, but you also see ones where the client's assert fails for the op it's trying to prepare to send.

Error: Both operations have to have the same base length
  at zb(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:7521:1)
  at Db(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:7674:128)
  at ? (/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:8706:21)
  at ? (/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11050:13)
  at n.e.FirebaseAdapter.n.handlePendingReceivedRevisions_(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11068:49)
  at n.e.trigger(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:10641:72)
  at serverAdapter.registerCallbacks.operation(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11228:98)
  at i.e.Client.e.applyServer(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11179:62)
  at i.e.Client.i.applyServer(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11203:71)
  at e.TextOperation.t.transform(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:10818:64)

[mikelehen]

Hrm. It'd be nice to see the top of the stack. :-/ I'm curious if there are unsynced user edits that are being combined with the server updates. If not, then there's a chance just replaying the firepad history would reproduce the problem.

On Mon, Sep 28, 2015 at 6:18 PM, Vincent Woo [email protected] wrote:

Here's an example callstack (obviously the stuff is munged but you can see the general flow):

This one is the client trying to process a remote op, but you also see ones where the client's assert fails for the op it's trying to prepare to send.

Error: Both operations have to have the same base length at zb(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:7521:1) at Db(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:7674:128) at ? (/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:8706:21) at ? (/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11050:13) at n.e.FirebaseAdapter.n.handlePendingReceivedRevisions_(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11068:49) at n.e.trigger(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:10641:72) at serverAdapter.registerCallbacks.operation(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11228:98) at i.e.Client.e.applyServer(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11179:62) at i.e.Client.i.applyServer(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:11203:71) at e.TextOperation.t.transform(/assets/application-306d8e65e19bd4432b5cf81bbcc94aceb7742970c00a1a705391b754066de96a.js:10818:64)

— Reply to this email directly or view it on GitHub https://github.com/firebase/firepad/issues/194#issuecomment-143916898.

[vincentwoo]

We're still consistently seeing these errors. I haven't had time to debug in depth. Is there any chance we can get some time from you to really dig into them? You MUST be getting some of these traces from the demo Firepad page, no?

https://app.getsentry.com/share/issue/31303537392e313139323139343333/

[vincentwoo]

User reports on the topic usually go to the effect of "everything is running fine, but then one person can keep typing with no indication that their text is not being synced, other party can't see changes made as they are not being written to Firebase."

[mikelehen]

:cry:

We don't have crash reporting on the demo sites, sorry. If anybody could provide a repro I'd be more than happy to dig in. Without that the only thing I could do is try to add debugging info of some kind to try to help narrow it down from the reports being seen in the field, but this isn't really straightforward (usually the real problem happened in the past).

In general this error means that somehow the operation we generated from a codemirror change event is inconsistent with the state we think the firepad is in.

I've usually seen this error immediately following some other exception that caused us to fail to sync a change (leaving us in an invalid state). So that'd be the first thing to check (that the sessions hitting this exception didn't hit any previous exception) if you haven't already.

[vincentwoo]

Is there a general change we can make to have the syncing be less brittle? Can we do a, "okay, taking a step back, let's try to resync from scratch"

[mikelehen]

Not really, at least nothing robust / clean.

I mean, you could detect the exception and just re-initialize firepad from scratch. You'll lose whatever change(s) triggered the exception, but that's probably better than the existing behavior.

Beyond that, you could try to diff the current codemirror contents with the remote firepad contents and assume you should send an operation to get the remote version in sync with your local version, but then you're going to potentially destroy other people's concurrent edits.

I wouldn't feel comfortable putting either of these changes directly into firepad, since it's really a poor bandaid over the problem.

If you really want to track it down, you could add rigorous debug logging. E.g. Track every change to codemirror and to firebase and send the log back to your server if we hit the exception. Then we can maybe recreate the problem. But I think there's still probably only like 50% chance that'll be successful. It could be browser-specific or a timing issue or something that we won't reproduce.

Sorry I don't have a better answer.

[vincentwoo]

I'm seeing it across most major browsers these days. I'll uh, look into logging... everything.

[mikelehen]

Can you tell if it happens with a particular coding language? One possibility is that CodeMirrors change events are being fired (or not fired) incorrectly. I could imagine a bug in some auto-indenting feature or something... If CodeMirror forgets to notify us of a change or has wrong arguments in the change event, that would cause this.

For what it's worth, there's an examples/hammer.html file in the firepad repo that just makes random edits. I occasionally run it in several browsers at the same time. When there were actual bugs in the firepad syncing code, it was very useful for finding them...

You could try running hammer.html with the latest CodeMirror and maybe turn on different language modes and see if anything turns up. To make it even better, I guess it'd be good if it could simulate other things that a user might do (indent blocks of code, reformat code, etc.)

[vincentwoo]

That was a good hypothesis, but I checked the errors against language and they seem pretty evenly distributed across our normal language distribution.

Proposal: What if the change listener didn't rely on the before change arguments, but recomputed from editor.getValue() every time? Would that be more robust?

[mikelehen]

I'm not sure. I remember that code was kinda' hairy and I can't dig into it right now. If you come up with an alternate (perhaps more robust way) of computing the operation, great. And perhaps the thing to do then (if you can tolerate it) would be to actually compute it both ways and throw a new, different exception if they don't match... that way we can get closer to the root problem.

[iclems]

@vincentwoo if you come up with a modified firepad version with full logging for this, we could also apply it on our side to gather info faster. We have thousands of users using Firepad on a daily basis and a few of these every week as well.

Just yesterday, we also got a "undefined: Error: Firebase (2.2.9) INTERNAL ASSERT FAILED: sendRequest call when we're not connected…" don't know if that one also has the same root?

[vincentwoo]

@iclems - I'm super busy, is there any chance I can pay you cash money to do a deep dive on all firepad-sync related errors and fix this once and for all?