Closed canadaduane closed 1 year ago
One of the callbacks happens in DocFrontend (if this line is commented out, I receive ONE callback):
https://github.com/automerge/hypermerge/blob/master/src/DocFrontend.ts#L139
The other happens as a result of RepoFrontend receiving a LocalPatchMsg
(Again, if this line is commented out, I receive ONE callback, albeit slightly different):
https://github.com/automerge/hypermerge/blob/master/src/RepoFrontend.ts#L243
Screenshot of logs (Note that "chat doc change
" is my app getting a subscribe
callback):
(Below is the same logs as above, but copy/pasted for findability):
queue:repo:metadata:readyQ subscribe +0ms
repo:backend swarm.join v5Dp 3i4x +68ms
queue:repo:actor:Qv5Dp subscribe +0ms
hyperm1 State Transitions: 2
hypermerge:front change complete doc=v5DpPKt4Bru3jzYMmWHVxLcXy65xHrST8RZWp7wdVYp seq=2 +1ms
chat doc change { text:
Text {
elems:a"
[Symbol(_objectId)]: '91214d6c-c356-49a6-bba5-c0e756b38afc',
[Symbol(_maxElem)]: 1 } } +655ms
repo:backend documentNotify LocalPatchMsg +596ms
repo:backend LocalPatchMsg +3
repo:front PatchMsg true v5DpPKt4Bru3jzYMmWHVxLcXy65xHrST8RZWp7wdVYp +665ms
chat doc change { text:
Text {
elems: [ [Object] ],
[Symbol(_objectId)]: '91214d6c-c356-49a6-bba5-c0e756b38afc',
[Symbol(_maxElem)]: 1 } } +5ms
hypermerge:front docId=v5DpPKt4Bru3jzYMmWHVxLcXy65xHrST8RZWp7wdVYp task=patch time=0ms +6ms
repo:backend ActorSync v5DpPKt4Bru3jzYMmWHVxLcXy65xHrST8RZWp7wdVYp +0ms
repo:backend change found xxx id=v5Dp seq=2 +0ms
repo:backend applyremotechanges 1 +0ms
repo:backend documentNotify RemotePatchMsg +1ms
repo:backend RemotePatchMsg +0ms
repo:front PatchMsg true v5DpPKt4Bru3jzYMmWHVxLcXy65xHrST8RZWp7wdVYp +1ms
hypermerge:front docId=v5DpPKt4Bru3jzYMmWHVxLcXy65xHrST8RZWp7wdVYp task=patch time=0ms +1ms
Here are stack traces from the two code paths that lead to a newState()
call in DocFrontend
:
via a handle.change
event emitter:
Trace
at DocFrontend.newState (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:113:17)
at Queue.changeQ.subscribe.fn (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:137:22)
at Handle.DocFrontend.change [as changeFn] (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:39:26)
at Handle.change (/Users/dujohnson/tmp/hypermerge/dist/Handle.js:71:18)
at EventEmitter.<anonymous> (/Users/dujohnson/medici/local-first/chat-line/lib/index.js:66:21)
at EventEmitter.emit (events.js:189:13)
at handle (/Users/dujohnson/tmp/neat-input/index.js:141:17)
at ReadStream.onkeypress (/Users/dujohnson/tmp/neat-input/index.js:194:9)
at ReadStream.emit (events.js:189:13)
at emitKey (/Users/dujohnson/tmp/neat-input/node_modules/keypress/index.js:406:12)
via a DocBackend.applyLocalChange
:
Trace
at DocFrontend.newState (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:113:17)
at bench (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:78:26)
at DocFrontend.bench (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:156:9)
at DocFrontend.patch (/Users/dujohnson/tmp/hypermerge/dist/DocFrontend.js:65:18)
at Queue.RepoFrontend.receive (/Users/dujohnson/tmp/hypermerge/dist/RepoFrontend.js:201:33)
at DocBackend.RepoBackend.documentNotify [as notify] (/Users/dujohnson/tmp/hypermerge/dist/RepoBackend.js:151:37)
at bench (/Users/dujohnson/tmp/hypermerge/dist/DocBackend.js:144:22)
at DocBackend.bench (/Users/dujohnson/tmp/hypermerge/dist/DocBackend.js:158:9)
at Queue.localChangeQ.subscribe.change (/Users/dujohnson/tmp/hypermerge/dist/DocBackend.js:139:18)
at DocBackend.applyLocalChange (/Users/dujohnson/tmp/hypermerge/dist/DocBackend.js:55:31)
From @pvh (slack comment):
when a change happens locally we first make an immediate optimistic front-end change. this has to trigger a callback for subscribers to let them know to re-render. then the change message is pushed to the backend which does a full reconciliation against the CRDT which replies with a definitive Patch message.
it's possible that there is an opportunity to optimize this so that we only send the second if the first was incorrect, but i rather suspect this is what you're seeing
When I call
handle.subscribe
with a callback, the callback is being called twice when I expect it to be called once per change.I think this may be the same issue as failing test mentioned in #18