Duplicate 'subscribe' callbacks

[canadaduane]

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

[canadaduane]

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

[canadaduane]

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)

[canadaduane]

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