dalgard / meteor-viewmodel

Minimalist VM for Meteor
24 stars 2 forks source link

Binding twice after reconnect #20

Open KoenLav opened 8 years ago

KoenLav commented 8 years ago

Hi Kristian,

We are happily using your package for a while now. But since a while it seems that events are binded to HTML nodes twice after Meteor reconnects.

Have you seen this problem before?

Where is the code located which binds the event (within your package)? Maybe I can take a look ;)

dalgard commented 8 years ago

It is important that unbind isn't called twice when bind is. It must have something to do with some detail in onRefreshed, onDestroyed or onInvalidate. One of those hooks must fail to fire in your special situation.

KoenLav commented 8 years ago

I'm pretty sure unbind is 'working' (partially), because the .off() is being called (and the listeners are, if only very briefly, detached).

However I think that because the accompanying Nexus is not removed more than one listener is added when bind is called.

dalgard commented 8 years ago

Right. So the view's onViewReady hook calls the bind function of both the old and the new nexus. That makes sense. That means unbind ought to somehow unregister bind from onViewReady (after which the nexus will be garbage collected instead of bound again).

dalgard commented 8 years ago

The weird thing is that this problem only occurs sometimes. There must be something special going on with onViewReady that differs in your case.

KoenLav commented 8 years ago

In List.remove I do console.log(this, items) when it was called from unbind using this.view[ViewModel.nexusesKey].remove(this)

Then I get temp1 and temp2 and use temp1.indexOf(temp2) and get -1.

Because: temp1 contains two Nexuses with selector vm-bind-id 258 and 287, but temp2 contains one Nexus with selector vm-bind-id 128.

I'm fairly sure all these issues are related to the vm-bind-id being changed, for some reason.

dalgard commented 8 years ago

The vm-bind-id attribute should change every time the view is refreshed – it is expected behavior. It's the only way the {{bind}} helper can be used in that special way that we use it.

KoenLav commented 8 years ago

I see, but because it is changed before/during unbind is running the object passed to remove does not match any of the objects in the list (I think).

dalgard commented 8 years ago

Other places that would be interesting to inspect are view._callbacks and view._domrange.attachedCallbacks.

dalgard commented 8 years ago

I've continuously profiled the usage examples for memory leaks and made sure there wasn't any, so I'm surprised that the library is bleeding nexuses in your case.

But I guess I haven't profiled any cases where a view is refreshed the way that it is in yours.

It would be helpful with a reduced test case that demonstrates this bug, but I know it isn't always a simple thing to do.

KoenLav commented 8 years ago

I don't have time to create a test-case currently (can only spend a couple of minutes at a time), but maybe tonight or tomorrow :)

I will keep working on trying to debug it though.

dalgard commented 8 years ago

:+1:

KoenLav commented 8 years ago

I've pinpointed the issue to the Tracker.afterFlush function in the onReady function; it fires twice.

dalgard commented 8 years ago

Nice find!

KoenLav commented 8 years ago

Which makes perfect sense, since the onReady function also gets called twice, apparently.

dalgard commented 8 years ago

I may not be able to look into it more until tomorrow, but I'm sure we will be able to fix this within a very short timeframe.

KoenLav commented 8 years ago

Great to hear, I've got a few more minutes today ;)


Continuing:

Which makes perfect sense again, since the element has had two nexuses attached to it. I'm not sure whether Tracker.afterFlush is the 'right' method to use here.

Anyhow I'm confident I got closer to the source of the issue, so I'm going to all changes and restart at onReady/Tracker.afterFlush.

KoenLav commented 8 years ago

Ok, I noticed something:

We have a list of 30 elements experiencing this issue, but sometimes some of the elements will result in a double bind whereas others will not... "Race condition-like" behavior.

It seems some things are just not completed in the expected order, but which things I don't know yet.

KoenLav commented 8 years ago

Also when I reconnect a second time some elements' viewmodel functions will fire twice whereas others will fire thrice.

KoenLav commented 8 years ago

Monkey patched the bug by adding

    if (!view.afterFlushSet) {
      Tracker.afterFlush(callback);

      view.afterFlushSet = true;
    }

On line 63 in base.js, but have yet to find the cause of the Nexuses not being removed.

KoenLav commented 8 years ago

Never mind, this causes other issues for the elements which were not problematic earlier...

KoenLav commented 8 years ago

Ok, what happens at the remove stage:

  1. A new Nexus is added and thus the vm-bind-id is changed.

List of Nexus.selectors: [vm-bind-id='250'] [vm-bind-id='282']

  1. The old Nexus should be removed, the remove function returns true (as in it has removed something), but instead the new Nexus is removed

Resulting in the new list of Nexus.selectors: [vm-bind-id='250']

  1. A few miliseconds later, something magic happens; a new Nexus is added to the list of nexuses: Resulting in the final list of Nexus.selectors: [vm-bind-id='250'] [vm-bind-id='334']

These two Nexuses together cause the double triggering of the viewmodel functions.

KoenLav commented 8 years ago

Ok, I further pinpointed the issue: unbinding works as expected in our scenario, it is the binding however which gets executed twice and messes things up (probably for the same reason Tracker.afterFlush gets called twice).

KoenLav commented 8 years ago

Would it help to know that these elements are rendered within a loop within a loop?

KoenLav commented 8 years ago
{{#each category}}
    {{#each products}}
        {{> productTemplate}}
    {{/each}}
{{/each}}

Simplified representation (these are actually split over two templates).

dalgard commented 8 years ago

I think it's an interesting perspective that we might be dealing with a race condition. Is it always the exact same elements that get the duplicate bindings?

KoenLav commented 8 years ago

Yes, but as I said it's a list of 30-something elements and there are times when elements 23 and 24 (for instance) are unaffected but the others are affected (which supports the view of 'race condition-like' circumstances).

dalgard commented 8 years ago

If I understand you correctly, it is not always the exact same set of elements that gets affected?

KoenLav commented 8 years ago

It's 30-something elements which all make use of the same template, most of the times all of them are affected but on rare occasions some of them are unaffected.

So you are right in saying that not always all of the elements in the set are affected, but the phenomena is always limited to a subset of this specific set of elements.

dalgard commented 8 years ago

My guess is that Meteor.reconnect() triggers a Tracker flush, which coincides with some or all elements being in a temporary state where the onReady or other event are supposed to happen before (or possibly after – I forget) an already scheduled flush.

The solution would be something along the lines of what you tried earlier. Hmm...

dalgard commented 8 years ago

If you set a breakpoint on this line and look in the call stack, does that part of onReady ever get called directly by the Nexus constructor, or is it always inside a call to autorun (= irrelevant)?

KoenLav commented 8 years ago

Following the code down the rabbit hole:

For now I ended up at the bindHelper function of the viewModel which, apparently, gets called twice every time reconnect is called (for these elements).

However right after bindHelper is called for the second time the onDestroyed which resulted from the first bindHelper is called. The onDestroyed calls from the first bindHelper calls unbind on the element, but removing the Nexus returns false (I guess because the second bindHelper has already fired and changed the vm-bind-id of the element, causing a mismatch somewhere down the road).

I'm not sure why these elements are so rapidly re-rendered (possibly because GroundDB causes some computation to invalidate twice, rather than just once, on a reconnect), but I guess this could occur in other scenario's as well.

So I think we should make sure that when binding a helper any previously existing binding on the same element originating from the same Blaze helper should be properly removed.

KoenLav commented 8 years ago

The order of events:

bindHelper ONE viewmodel.js:512 newNexus nexus.js:114 ===== nexus.js:103 onDestroyed nexus.js:300 unbind nexus.js:313 false <== cannot remove nexus for some reason base.js:66 afterFlush nexus.js:255 bind <== we are binding here viewmodel.js:483 click: addProduct viewmodel.js:510 =====

bindHelper TWO viewmodel.js:512 newNexus nexus.js:114 ===== base.js:66 afterFlush nexus.js:255 bind <== we are ALSO binding here

Looking back at my previous reply I'm not sure whether unbind ==> false is the issue, it might rather be the fact that afterFlush is called twice resulting in two binds.

KoenLav commented 8 years ago

Working on that breakpoint now

dalgard commented 8 years ago

For sure, it could happen in other scenarios – thanks again for taking the time to debug this. I'll look into the reason why do_unbind evaluates to false.

The {{bind}} helper being triggered twice is expected behavior – dynamic attributes are re-run when anything about the element changes, which is the reason for many of the tricky maneuvers employed by the library.

Just to be sure, you are using the latest version 1.0.2, right?

KoenLav commented 8 years ago

I'm not really used to working with the stack directly, but the when I set a breakpoint on that line and look in the Chrome DevTools the second line says "nexus.js:111" which is this.onReady(this.bind) in the Nexus constructor.

KoenLav commented 8 years ago

The false I mention there is not the do_unbind, it is the result of this.view[ViewModel.nexusesKey].remove(this);

dalgard commented 8 years ago

The nexuses list on the view is only for debugging and doesn't affect the bindings.

KoenLav commented 8 years ago

Do you think I should focus on why this.view[ViewModel.nexusesKey].remove(this) returns false or rather on why the bindHelper is called twice.

There are two differences between elements that don't have the erronous behavior and those who do. For elements that have the bug:

KoenLav commented 8 years ago

I see, if that is the case then Nexus.remove(this) a few lines earlier would probably also return false. I'll look into that.

dalgard commented 8 years ago

It's weird if it returns false, but those two lines have no bearing on the bindings themselves, they only track what is currently on the page for debugging purposes.

dalgard commented 8 years ago

The bind helper being called twice is expected behavior and only causes problems when the previous binding isn't unbound properly before each subsequent call.

KoenLav commented 8 years ago

Nexus.remove(this) also returns false.

But I see your point.

I do still think the afterFlush ==> bind being called twice is the culprit. Every time reconnect is called the previous binding is removed, but two new ones are added due to the afterFlush being triggered twice.

afterFlush should never trigger a bind if the previous bind has not yet been removed, I guess.

KoenLav commented 8 years ago

Actually I'm 100% sure this is the issue.

Even though Nexus.remove(this) returns false, before that the eventListener is removed so that should be fine (in terms of functionality, not in terms of memory leaks).

However because afterFlush is set twice (because it is bound in two different computations, one for the first triggering of bindHelper and another for the second) it is executed twice, but this shouldn't happen.

I'm still not sure whether afterFlush is the right 'tool for the job' (but I'm not sufficiently equipped to think of a better alternative).

dalgard commented 8 years ago

Here's another idea: unbind accidentally runs before bind does, which would explain why Nexus.remove(this) returns false – it can't be removed from the global list, because it hasn't been added to it yet (which happens in bind).

The first unbind ought to run after the first bind, of course.

Don't pay too much attention to the multiple calls to bind/unbind, by the way – it's the only way that the library can be guaranteed to work in all situations and what makes it especially robust, in all modesty. Except in your case, of course ;)

dalgard commented 8 years ago

I wonder whether view.onViewDestroyed sometimes runs before view.onViewReady? If the view is destroyed immediately, is the unbind callback run right away when registered? In that case, the value of view.isRendered and view.isDestroyed is important...

dalgard commented 8 years ago

Still wish I had a test case ;)

dalgard commented 8 years ago

To muddle the image, list.add and list.remove will both trigger a Tracker flush.

dalgard commented 8 years ago

Have we established exactly which hook is responsible for running unbind? Is it onRefreshed, onDestroyed, or onInvalidate?

KoenLav commented 8 years ago

onDestroyed

KoenLav commented 8 years ago

I am using these console.logs:

this.onRefreshed(function() {
  if (Meteor.checkElement(view)) {
    console.log("onRefreshed")
  }

  that.unbind()
});

// Unbind element on view destroyed
this.onDestroyed(function() {
  if (Meteor.checkElement(view)) {
    console.log("onDestroyed")
  }

  that.unbind()
});

// Unbind element on computation invalidation
this.onInvalidate(function() {
  if (Meteor.checkElement(view)) {
    console.log("onDestroyed")
  }

  that.unbind(true)
});

In the Nexus constructor.