saving/sync broken

[anpc]

UPDATE: It seems that whenever one page was opened in 2 places (by you or another person),
and you edited the first line, the other editor could become corrupt and silently fail to save subsequent edits.
THIS BUG HAS BEEN THERE FOR ABOUT HALF A YEAR. You may have lost a lot :-(

Email me beni.cherniavsky@gmail.com and I'll try to help. Unfortunately if loss occurred, I'm afraid nothing was sent to the servers, so not sure I'll be able to help.

I've found and fixed the bug; this issue will remain open until I add a second layer of protection (#56) from future similar bugs...

---

[written from Anat's name but actually by @cben]
In this case I believe I haven't lost edits but syncing did fail — silently — which is a scary data loss scenario!

• I started writing on my computer.
• Then I also opened same doc on Beni's computer and edited there.
• JS console on my computer started showing lot's of Both operations have to have the same base length errors. It seems that changes from Beni's computer do appear on mine.
• my computer's flaky internet connection went and came several times during this time...
• Trying to edit on my computer added new kinds of errors, notably sendOperation() called with invalid operation. — and did not reflect the edit on Beni's.
• Beni's JS console is still clean.

...
firebase.js:43 Uncaught Error: Both operations have to have the same base length
render-math.js:277 20491.784s change Object
firebase.js:43 Uncaught Error: Both operations have to have the same base length
render-math.js:277 20492.923s change Object
firebase.js:43 Uncaught Error: Both operations have to have the same base length
render-math.js:277 20498.173s change Objectfrom: CodeMirror.Posorigin: "cmrt-353"removed: Array[1]text: Array[2]to: CodeMirror.Pos__proto__: Object
firebase.js:43 Uncaught Error: Both operations have to have the same base length
3070 console messages are not shown.
render-math.js:277 20902.045s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "cmrt-354", removed: Array[1]}
render-math.js:277 20902.292s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "cmrt-355", removed: Array[1]}
2firebase.js:43 Uncaught Error: Both operations have to have the same base length
firebase.js:56 WebSocket connection to 'wss://s-dal5-nss-33.firebaseio.com/.ws?v=5&ns=mathdown' failed: Error in connection establishment: net::ERR_NETWORK_CHANGED
firebase.js:59 WebSocket connection to 'wss://s-dal5-nss-33.firebaseio.com/.ws?v=5&ns=mathdown&s=zqxI1NLKUeDK274eQUsNbwFOrkPHmNhW' failed: WebSocket is closed before the connection is established.
firebase.js:70 GET https://s-dal5-nss-33.firebaseio.com/.lp?id=1193443&pw=3EKOFbF5GQ&ser=98754…pudWxsLCJzbiI6IkIxYyJ9XSwiaCI6IjVFOHZTOEpaU1JObVIxUnRKbmlKUHNiajRDND0ifX19 net::ERR_CONNECTION_TIMED_OUT
.lp?dframe=t&id=1193443&pw=3EKOFbF5GQ&ns=mathdown:5 Synchronous XMLHttpRequest on the main thread is deprecated because of its detrimental effects to the end user's experience. For more help, check http://xhr.spec.whatwg.org/.
.lp?dframe=t&id=1193443&pw=3EKOFbF5GQ&ns=mathdown:6 GET https://s-dal5-nss-33.firebaseio.com/.lp?disconn=t&id=1193443&pw=3EKOFbF5GQ 
firebase.js:70 GET https://s-dal5-nss-33.firebaseio.com/.lp?id=1193443&pw=3EKOFbF5GQ&ser=98754…JPZ1cvdXNlcnMvLUpvLTV4bjI2UDFOU2hDd0pFYmgvY29sb3IiLCJkIjoiI2ZmZDZiMyJ9fX0. net::ERR_CONNECTION_TIMED_OUT
firebase.js:70 GET https://s-dal5-nss-33.firebaseio.com/.lp?start=t&ser=90668494&cb=2000&v=5&ns=mathdown net::ERR_CONNECTION_TIMED_OUT
render-math.js:277 22782.053s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "+input", removed: Array[1]}
firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.firepad.js:1673 assertfirepad.js:1430 firepad.FirebaseAdapter.FirebaseAdapter.sendOperationfirepad.js:2383 firepad.EditorClient.EditorClient.sendOperationfirepad.js:2087 firepad.Client.Synchronized.applyClientfirepad.js:2052 firepad.Client.Client.applyClientfirepad.js:2352 firepad.EditorClient.EditorClient.onChangefirepad.js:2275 EditorClient.editorAdapter.registerCallbacks.changefirepad.js:4293 firepad.RichTextCodeMirrorAdapter.RichTextCodeMirrorAdapter.triggerfirepad.js:4176 firepad.RichTextCodeMirrorAdapter.RichTextCodeMirrorAdapter.onChangefirepad.js:4370 obj.(anonymous function)firepad.js:48 clazz.triggerfirepad.js:3510 firepad.RichTextCodeMirror.RichTextCodeMirror.onCodeMirrorChange_firepad.js:4003 obj.(anonymous function)codemirror.js:7507 CodeMirror.signalcodemirror.js:2302 endOperation_finishcodemirror.js:2193 endOperationscodemirror.js:2176 endOperationcodemirror.js:2650 readInputcodemirror.js:2736 (anonymous function)
render-math.js:277 22785.437s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "+delete", removed: Array[1]}
firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.
render-math.js:277 22786.235s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "+input", removed: Array[1]}
firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.
render-math.js:277 22787.310s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "+input", removed: Array[1]}
firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.
render-math.js:277 22787.911s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "+input", removed: Array[1]}
firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.
render-math.js:277 22788.987s change Object {from: CodeMirror.Pos, to: CodeMirror.Pos, text: Array[1], origin: "+input", removed: Array[1]}
firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.

[anpc]

More important than fixing this particular sync problem would be (A) testing and/or (B) indication whenever edits don't get saved (for whatever reason) — #56

[cben]

Let's see the stack trace on the later error:

firepad.js:1673 Uncaught Error: sendOperation() called with invalid operation.
firepad.js:1673 assert
firepad.js:1430 firepad.FirebaseAdapter.FirebaseAdapter.sendOperation
firepad.js:2383 firepad.EditorClient.EditorClient.sendOperation
firepad.js:2087 firepad.Client.Synchronized.applyClient
firepad.js:2052 firepad.Client.Client.applyClient
firepad.js:2352 firepad.EditorClient.EditorClient.onChange
firepad.js:2275 EditorClient.editorAdapter.registerCallbacks.change
firepad.js:4293 firepad.RichTextCodeMirrorAdapter.RichTextCodeMirrorAdapter.trigger
firepad.js:4176 firepad.RichTextCodeMirrorAdapter.RichTextCodeMirrorAdapter.onChange
firepad.js:4370 obj.(anonymous function)
firepad.js:48 clazz.trigger
firepad.js:3510 firepad.RichTextCodeMirror.RichTextCodeMirror.onCodeMirrorChange_
firepad.js:4003 obj.(anonymous function)
codemirror.js:7507 CodeMirror.signal
codemirror.js:2302 endOperation_finish
codemirror.js:2193 endOperations
codemirror.js:2176 endOperation
codemirror.js:2650 readInput
codemirror.js:2736 (anonymous function)

This sounds somewhat like https://github.com/firebase/firepad/issues/101 [literal so GH won't spam that issue], which was fixed 1.5 years ago. It's probably not exactly it, and the root cause is probably the "same base length" error.
Anyway, if I have to debug Firepad, it's hard to defend my sticking with old firebase & firepad just because that firebase.js was accidentally open sourced (#4).
But I also don't want to upgrade stuff blindly. I need more tests.

[cben]

This is horrific.
Opening a page from 2 tabs reliably breaks sync for me.

It's likely that silent edit loss has been going on for users for don't know how long :-(

firebase.js:43 Uncaught TypeError: Cannot read property 'line' of undefined
...
Uncaught Error: sendOperation() called with invalid operation.

[cben]

pushing prominent warning on top linking to this bug...

[cben]

progress: Cannot read property 'line' of undefined is coming from my render-math.js and is probably the root cause.
(being my fault is much more comforting than being Firepad's fault :-))

Tip to future self: firebase-debug.js is really useful in that it dumps stack on "Uncaught" exceptions it catches.

[cben]

OK, conclusions:

This has been broken for half a year

caused cben/CodeMirror-MathJax@475901c where I made 2 drunk-idiot-level bugs

• Editing first line of the document would AFAICT immediately break saving in any other browser instance having same page open simultaneously.
  • It seems that the window where you made the edit remains working, so if you didn't collaborate (nor had same page in multiple browser tabs) you were safe. But I don't entirely understand how my exception was breaking firepad and why it doesn't break the window where you made the edit — so can't be sure you were safe.
  • Just having your cursor in the first line when another browser instance is editing the page may have caused problems. I think not — the change has to include first line — but I'm not 100% sure.

[cben]

I've pushed a fix but I'm leaving this bug open (and the warning on top leading here) until I implement #56 to reliably warn any user whose specific saving doesn't work.

[cben]

Good news: reproducing the problem (for #56) proved quite hard. Firepad is much more stubborn than I expected in sending and receiving changes even when there are exceptions :-)
This means that not as much data has been lost.

• Going back to the buggy CM-MJ wasn't enough; it seems firebase-debug.js not only reports but also tolerates exceptions better, and I only managed to reproduce with the non-debug firepad.js.
• It's easy to start getting exceptions but that doesn't mean we're not saving!
• The direct exception from clearOurMarksInRange -> rangesOverlap -> posCmp is TypeError: Cannot read property 'line' of undefined (Chrome) / a is undefined (Firefox). In itself, that's not a problem yet.
• It takes some editing, apparently from both sides, to start getting Error: Both operations have to have the same base length from Firepad. This is in principle bad news but in practice, we're still saving!
• Only when you see Error: sendOperation() called with invalid operation. firepad.js:1673:12 then you're really borked.
  • And even then, you're still probably receiving changes, only not sending yours.