[BUG] Syncer timing issue can lead to temporary loss of tiddlers

[Jermolene]

Introduction

This is a long standing issue with the syncer code. It manifests itself as a tiddler completely disappearing in the middle of editing, to be replaced by a "Missing tiddler". After a period of tens of seconds, the tiddler reappears.

We have had occasional reports over the years of tiddlers disappearing and reappearing but they have proved difficult to replicate until a recent bug report received privately by @Jermolene. It took a lot of debugging but by adding lots more logging (in d77eee2, 646620f, ad98853 and afd7155), we were able to figure out what was going on, and replicate the problem at will.

The Bug

The problem is really fundamental to the way that the syncer is currently architected. There are two entirely independent subsystems to the syncer:

• A task state machine that determines chooses the next task to be performed. Highest priority is that any tiddlers that have changed locally are saved or deleted on the server. This is done using asynchronous methods on the syncadaptor. The next priority is to process any outstanding load requests from the server. The state machine waits for the completion of each task before initiating the next one
• A much simpler state machine that intermittently polls the server for the list of skinny tiddlers. Any tiddlers that are found on the server but are not present locally have a "load" task queued up for them, and any tiddlers that have been deleted on the server but are still present locally are immediately deleted

The problem is that the two state machines can overlap in unexpected ways. For example, it is possible for the following sequence to occur:

1. Syncer initiates a getSkinnyTiddlers request
2. User modifies a tiddler
3. Syncer initiates a save request for that tiddler
4. Syncer receives results of getSkinnyTiddlers and sees that the new tiddler is not present on the server, and so deletes the local copy
5. The save request completes successfully
6. Syncer initiates another getSkinnyTiddlers request
7. Syncer receives results of second call to getSkinnyTiddlers, which includes the new tiddler thus triggering a load of that tiddler

The detail is illustrated by the annotated version of the enhanced logs below.

Proposed Fix

It is proposed to unify the two independent syncer state machines into one. This will serialise both types of requests to the server, making it impossible for the problems discussed above to occur. A pull request is being prepared.

Annotated Bug Logs

It starts with the syncer performing a “save” task on “test-sync-tiddler-154” that the user has just saved. In these two steps we dispatch the save task, but we haven’t yet heard back from the server.

2023 11 9 13:57:18.149: Chosen next task SAVE test-sync-tiddler-154
2023 11 9 13:57:18.149: Dispatching 'save' task: test-sync-tiddler-154

Then the syncer decides to request the skinny tiddler list from the server (aka requesting tiddlers.json). This is to find out if there are any new or changed tiddlers on the server that we need to load. Again, at this point we’ve only dispatched the request to the server, we haven’t yet got the results back.

2023 11 9 13:57:18.152: Retrieving skinny tiddler list

Then we get back the results from saving "test-sync-tiddler-154” to the server. The server gives us back the server revision number which we can later use to determine if this tiddler is changed on the server.

2023 11 9 13:57:21.111: Updating tiddler info in SaveTiddlerTask.run for test-sync-tiddler-154 {"changeCount":4,"adaptorInfo":{"bag":"default"},"revision":"4","timestampLastSaved":"2023-11-09T18:57:21.111Z"}
2023 11 9 13:57:21.158: Dirty status was true

The syncer now chooses the next task that needs sending to the server, and chooses a “delete” task on "Draft of 'test-sync-tiddler-154’”. It dispatches the request to the server.

2023 11 9 13:57:21.189: Chosen next task DELETE Draft of 'test-sync-tiddler-154'
2023 11 9 13:57:21.189: Dispatching 'delete' task: Draft of 'test-sync-tiddler-154'

The syncer gets the confirmation from the server that the tiddler has been deleted, and so it deletes the information that it held about "Draft of 'test-sync-tiddler-154’” on the server.

2023 11 9 13:57:21.550: Deleting tiddler info in DeleteTiddlerTask.run for Draft of 'test-sync-tiddler-154'

Here we see the syncer decide that there are no other changes that need to be synced to the server

2023 11 9 13:57:21.616: Dirty status was false
2023 11 9 13:57:21.653: Chosen next task null
2023 11 9 13:57:21.682: Dirty status was false

And now here’s the bit that puts a spanner in the works: we now get the response to retrieving the skinny tiddler list. The response is stale, though, because it includes old information about the tiddler "Draft of 'test-sync-tiddler-154’”.

This causes the syncer to queue up a load task for "Draft of 'test-sync-tiddler-154’”, which gets picked up in a few lines.

2023 11 9 13:57:22.927: Updating tiddler info in syncer.storeTiddler for Draft of 'test-sync-tiddler-154' {"revision":"60","adaptorInfo":{"bag":"default"},"changeCount":400}

And now finally we get the failed attempt to load "Draft of 'test-sync-tiddler-154’”.

2023 11 9 13:57:24.994: Chosen next task LOAD Draft of 'test-sync-tiddler-154'
2023 11 9 13:57:24.995: Dispatching 'load' task: Draft of 'test-sync-tiddler-154'
2023 11 9 13:57:25.078: Dirty status was false
2023 11 9 13:57:25.260: Sync error while processing load of 'Draft of 'test-sync-tiddler-154'': XMLHttpRequest error code: 404

[Jermolene]

I've pushed a draft PR with a fix in #7843