extension-redis can unload document being loaded for new client connection

[james-atticus]

Description

During a provider client reconnect, we're observing that before/afterUnloadDocument hooks are being called twice, after which the Yjs document is destroyed and updates from the client are silently lost.

Logging from the reconnect showing before/afterUnloadDocument being called immediately after the document is loaded:

Later logs where Sync/Update messages are received but there are no corresponding out messages to the client nor Document X changed log messages:

Steps to reproduce the bug

I haven't been able to reproduce it directly, but I'm pretty sure the bug is caused by the debounced logic in extension-redis:

1. Client disconnects
2. onDisconnect hooks are called (and awaited, as of #587) a. The Redis hook resolves immediately, even though it starts a timeout to unsub
3. onClose is called, document is unloaded because there are no active connections
4. Client reconnects, calling setUpNewConnection -> createDocument
5. Document is not loaded, so loadDocument is called a. Document is added to instance with this.documents.set(documentName, document) b. onLoadDocument hooks are called
6. At some point during the async onLoadDocument hooks, the Redis onDisconnect timeout triggers a. It calls this.instance.documents.get(documentName), which returns the new document being loaded b. There are no active connections for the document, so it is unloaded (connectionCount: 0 in screenshots above)
7. loadDocument -> createDocument finish running
8. setUpNewConnection calls createConnection -> new Connection -> this.document.addConnection(this)
9. Updates come in from client (connectionCount: 1 in screenshots above) however it's already too late

You can reproduce the broken state by adding an extension:

afterLoadDocument: async (data) => {
    data.instance.unloadDocument(data.document);
},

Expected behavior

extension-redis does not call unloadDocument for the newly loaded document. #831 made it so the extension used the latest document from the Hocuspocus instance, rather than the one passed into the hook, which strikes me as odd.

Environment?

• Hocuspocus version: 2.15.3

[james-atticus]

I've got a proposed fix up at https://github.com/ueberdosis/hocuspocus/pull/972, however I think there might still be a bug with how the Redis onDisconnect hook is set up. It's delaying the unsub "to allow last minute syncs", however the function resolves immediately meaning the document is still being destroyed here.

Rather than immediately resolving from the onDisconnect hook in the Redis extension, would it make sense to instead resolve after the disconnectDelay timeout? Eg:

  public onDisconnect = async ({ documentName, document }: onDisconnectPayload) => {
    // Delay the disconnect procedure to allow last minute syncs to happen
    return new Promise(resolve => {
      setTimeout(() => {
        // Do nothing, when other users are still connected to the document.
        if (document.getConnectionsCount() > 0) {
          resolve(undefined)
          return
        }

        // Time to end the subscription on the document channel.
        this.sub.unsubscribe(this.subKey(documentName), (error: any) => {
          if (error) {
            console.error(error)
          }
        })

        resolve(undefined)
      }, this.configuration.disconnectDelay)
    })
  }

[james-atticus]

Hey @janthurau, appreciate your input on this one. Is the PR and/or fix above something you'd be happy to merge?

[janthurau]

I've created a PR to change the unloading logic to utilize the before/after unloadDocument hooks (I believe they didnt exist when the Redis extension was build initially), that should probably fix the issue: https://github.com/ueberdosis/hocuspocus/pull/1007