Animation callback is called too early

[pronebird]

[reactxp@1.0.2 web]

Hi,

I have a collapsible component that reverses the direction of animation basically reusing the same Animated.Value, calling stop on active Animation and creating a new animation. Easy right?

So after the recent rewrite of animations for web the last interpolated value is picked up properly but I experience some weird issue when the animation completion callback is called way too early and that's only the case when I interrupt the active animation and start the new one using the same existing value.

That's a tiny piece that runs animation in response to prop change in componentDidUpdate

// either use active value or create a new one
const fromValue = this.state.animatedValue || Animated.createValue(this._containerHeight);

// new value for animation
const toValue = this.props.height === 'auto' ? this._contentHeight : this.props.height;

// stop active animation
if(this._animation) {
  this._animation.stop();
}

console.log('FromValue: ', fromValue._value, 'ToValue: ', toValue);

// create new animation
const animation = Animated.timing(fromValue, {
  toValue: toValue,
  duration: this.props.animationDuration,
  easing: Animated.Easing.InOut(),
});

// save new active animation
this._animation = animation;

// save newly animated value
this.setState({
  animatedValue: fromValue,
}, () => {
  // sanity check
  if(this._animation === animation) {
    animation.start(this._onAnimationEnd);
  }
});

This is the animation completion callback:

// reset height after transition to let element layout naturally
// if animation finished without interruption
console.log('FINISHED ANIMATION ', finished);
if(this.props.height === 'auto' && finished) {
  this.setState({
    animatedValue: null,
  });
}

Finally render method:

const { height: _height, children, animationDuration: _animationDuration, ...otherProps } = this.props;

const styles = [];
if(this.state.animatedValue !== null) {
  const sizeStyle = Styles.createAnimatedViewStyle({
    overflow: 'hidden',
    height: this.state.animatedValue,
  });
  styles.push(sizeStyle);
}

console.log('RENDER WITH HEIGHT: ', this.state.animatedValue && this.state.animatedValue._value);

return (
  <Animated.View { ...otherProps } style={ styles } onLayout={ this._containerLayoutDidChange }>
    <View onLayout={ this._contentLayoutDidChange }>
      { children }
    </View>
  </Animated.View>
);

Here is a dropbox link with video screencast: https://www.dropbox.com/s/iorbcqxboup3id9/AnimationCallbackBug.mov?dl=0

If you prefer to read the entire source code which is about 100 LOC it's publicly available at: https://github.com/mullvad/mullvadvpn-app/blob/accordion-reactxp/app/components/Accordion.js

What I visually observe is basically the duration is kind of preserved between transitions so when I break one animation at 75% and run the other, the next animation reports completion { finished: true } after the remaining time left from the prior animation.

[forward animation] =>
0%+++++++++++++++++++++++++++++++++++++++++++++---------------100%
                                              // stop() at 75%
[backward animation] <=
0%------------------------------+++++++++++++++---------------100%
                                          // runs 75% - 50% and breaks

[erictraut]

I think I understand what's happening, but I'll need your help to confirm my theory. I suspect that you're passing a duration of 0ms, and the CSS engine is substituting some non-zero value like 100ms. The ReactXP animation is firing the completion call after 0ms.

You're inappropriately accessing the private method __getValue() which is private and not guaranteed to return what you expect. This also won't work on RN.

I've added a bunch of extra unit tests to verify that ReactXP's animated implementation is doing the right thing with regard to the completion callback when an animation is stopped and started, and it is working as expected.

[pronebird]

@erictraut thanks for trying to understand the issue. I just pushed another commit that caps the duration at 100ms – just in case so I never bump into 0s. It didn't help :/

I think there is something going on, I see callbacks fire way before animation finished. I'll continue tomorrow, I've added some logging in the code for debug purposes.

[erictraut]

OK, I have another theory. The web animation implementation in ReactXP normally relies on the CSS transition event to report when the animation is complete. However, this event is not implemented on all browser and is unreliable on others. To deal with this, the implementation also sets a timer for 10ms after it expects the animation to complete. It stashes the ID for this timer in the DOM, associated with the element that's being animated. If the animation is stopped, it determines whether it should ignore the timer by looking up the timer ID in the DOM. If you are curious about the implementation, look in the file web/animated/executeTransition.ts.

Your code is calling setState, which is forcing a re-render, which is probably updating the DOM. This means the timer ID is getting lost. It's generally a bad idea to re-render while there are pending animations because DOM updates can mess with animations.

If my theory is correct, you can fix the problem by eliminating your setState calls. They aren't necessary. You can store your animatedValue variable as an instance variable and initialize it the class constructor. My general rule of thumb is that a variable should be part of a component's state only if a change in the value requires a re-render.

[pronebird]

I had impression that the worst case scenario is I never got a callback invoked in case of re-render, i.e Animated.View could have simply cancelled animation on unmount. I like your theory though so I'll try to fix this in the morning.

I wonder if I should prevent the component from re-rendering even when I receive the new prop, because in my case the height of the component is driven by a prop and currently I update the animation from componentDidUpdate.

[erictraut]

If my theory is correct, I have a potential fix in the animation code. Let me know if your change eliminates the problem.

[pronebird]

OK so I did as you suggested, a few points:

1. No re-renders. Basically for demo purposes I disabled re-rendering and any setState. The animatedValue is created in constructor in that case and reused during the lifetime of the component.

shouldComponentUpdate() {
  return false;
}

2. Prop changes are processed in componentWillReceiveProps:

componentWillReceiveProps(nextProps: AccordionProps) {
    if(this.props.height !== nextProps.height) {
      console.warn('Animate prop: ' + this.props.height + ' -> ' + nextProps.height + ' @ ' + nextProps.animationDuration + 'ms');
      this._animateHeightProp(nextProps.height, nextProps.animationDuration);
    }
  }

3. Height updates are synchronous, so the previous animation is stopped before the next one is started:

_animationCount = 0;

_animateHeightProp(nextHeight: number | 'auto', animationDuration: number) {
  // call stop to get updated fromValue._value
  if(this._animation) {
    console.warn('[%d] Stop animation', this._animationCount);
    this._animation.stop();
  }

  const fromValue = this._animatedValue || Animated.createValue(this._containerHeight);
  const toValue = nextHeight === 'auto' ? this._contentHeight : nextHeight;

  // calculate the animation duration based on travel distance
  // note: _getValue() is private.
  const primitiveFromValue = parseInt(fromValue._getValue());
  const multiplier = Math.abs(toValue - primitiveFromValue) / Math.max(1, this._contentHeight);
  const duration = Math.max(100, Math.ceil(animationDuration * multiplier));

  this._animationCount += 1;
  const newAnimationIndex = this._animationCount;

  console.warn('[%d] Animate from %d to %d with duration %d', newAnimationIndex, primitiveFromValue, toValue, duration);

  const animation = Animated.timing(fromValue, {
    toValue: toValue,
    easing: Animated.Easing.InOut(),
    duration: duration,
    useNativeDriver: true,
  });

  this._animation = animation;
  this._animatedValue = fromValue;

  animation.start(({ finished }) => {
    console.warn('Finished animation %d, finished = %s', newAnimationIndex, finished);
  });
}

The log from dev tools (with timestamps):

12:36:19.745 Accordion.js:57 RENDER
12:36:42.255 Accordion.js:57 RENDER
12:36:42.258 Accordion.js:57 RENDER
12:36:42.261 Accordion.js:57 RENDER
12:36:42.268 Accordion.js:57 RENDER
12:36:42.270 Accordion.js:57 RENDER
12:36:42.273 Accordion.js:57 RENDER

12:36:44.870 Accordion.js:44 Animate prop: 0 -> auto @ 2500ms
12:36:44.870 Accordion.js:97 [1] Animate from 0 to 228 with duration 2500
12:36:52.946 Accordion.js:44 Animate prop: auto -> 0 @ 2500ms
12:36:52.946 Accordion.js:81 [1] Stop animation

12:36:52.946 Accordion.js:97 [2] Animate from 228 to 0 with duration 2500
12:36:54.305 Accordion.js:44 Animate prop: 0 -> auto @ 2500ms
12:36:54.305 Accordion.js:81 [2] Stop animation
12:36:54.306 Accordion.js:112 Finished animation 2, finished = false

12:36:54.306 Accordion.js:97 [3] Animate from 98 to 228 with duration 1426
12:36:55.188 Accordion.js:44 Animate prop: auto -> 0 @ 2500ms
12:36:55.189 Accordion.js:81 [3] Stop animation
12:36:55.189 Accordion.js:112 Finished animation 3, finished = false

12:36:55.190 Accordion.js:97 [4] Animate from 186 to 0 with duration 2040
12:36:55.459 Accordion.js:112 Finished animation 4, finished = true
12:36:56.539 Accordion.js:44 Animate prop: 0 -> auto @ 2500ms
12:36:56.539 Accordion.js:81 [4] Stop animation

12:36:56.539 Accordion.js:97 [5] Animate from 0 to 228 with duration 2500
_animateHeightProp @ Accordion.js:97
componentWillReceiveProps @ Accordion.js:45
callComponentWillReceiveProps @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:6389
updateClassInstance @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:6575
updateClassComponent @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:7848
beginWork @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:8225
performUnitOfWork @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:10224
workLoop @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:10288
callCallback @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:542
invokeGuardedCallbackDev @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:581
invokeGuardedCallback @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:438
renderRoot @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:10366
performWorkOnRoot @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:11014
performWork @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:10967
batchedUpdates @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:11086
batchedUpdates @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:2330
dispatchEvent @ ~/redacted/app/node_modules/react-dom/cjs/react-dom.development.js:3421

12:36:57.241 Accordion.js:112 Finished animation 5, finished = true
(anonymous) @ Accordion.js:112
(anonymous) @ ~/redacted/app/node_modules/reactxp/dist/web/Animated.js:214
(anonymous) @ ~/redacted/app/node_modules/reactxp/dist/web/Animated.js:504
arrayEach @ ~/redacted/app/node_modules/lodash/_arrayEach.js:15
forEach @ ~/redacted/app/node_modules/lodash/forEach.js:38
(anonymous) @ ~/redacted/app/node_modules/reactxp/dist/web/Animated.js:502
finish @ ~/redacted/app/node_modules/reactxp/dist/web/animated/executeTransition.js:63

So there are first 7 renders in the log, most likely caused by the hierarchy above so ignore it, there are no animations running at that point.

Then I keep inverting animation back and forth, it's a snowball now. Everything should be fine since I always cancel previous animation but then look at this:

12:36:55.190 Accordion.js:97 [4] Animate from 186 to 0 with duration 2040
12:36:55.459 Accordion.js:112 Finished animation 4, finished = true

I start animation with 2040ms duration and it finishes 269ms later, it's about 10 times faster than I instructed it. The animation still runs visually on screen.

Also I modified executeTransition and added a few logs there, setTimeout watchdog fires correctly on time.

Here is the debug commit with the new code (I reworded some of log messages after I wrote this reply but that shouldn't matter)

https://github.com/mullvad/mullvadvpn-app/commit/1f445070fdf1b4c220fff3e52fed53d140530176

[pronebird]

Update: I commented out the watchdog timer in executeTransition.tsx (window.setTimeout part) and now I receive the animation "end" event on time.

Maybe that can help to pin point the problem.

I am also a little suspicious about Value.stopTransition that has a branch that calls to _updateTransition which can execute the transaction. I haven't verified this may actually happen but seems a little bit fragile to even assume it can. But I don't know much details about the reasons why startTransition and stopTransition both reuse the same branch.

I think what I observe is basically that the watchdog timer keeps running even after a call to animation.stop(), at this point Value.stopTransition already called the onEnd callback with { finished: false }.

However the timer keeps running and once it fires it calls the same finish function as onTransitionEnd which never happened so at this point the logic continues as if we received the transitionEnd event.

It then calls done() and returns execution back to AnimatedComponentGenerated._updateTransition which mistakenly calls onEnd callbacks and clears out all active animations.

When the most recent animation finishes and onEnd is being called, the AnimatedComponentGenerated is already in the invalid state since the watchdog timer had cleared all pending transitions.

Call tree:

• Animated.TimingFunction.start
  • Animated.Value.startTransition (calls to listeners)
  • AnimatedComponentGenerated.startTransition
    • AnimatedComponentGenerated._updateTransition
    • executeTransition (calls onEnd upon transitionEnd or timeout)
      • ExtendedTransition.onEnd({ finished: true })

Update 2:

I worked out a minimal patch and currently testing it, first results are positive: https://github.com/pronebird/reactxp/commit/a02584797d38c2375dfa9099ba114ace728fb623

My patch basically assigns a unique integer for each transition so when executeTransition callback is called it gives back the transitions it performed. Then I match the unique identifiers of activeTransitions with the ones performed by executeTransition.

If you pull my patch you can add the snippet below to print out identifiers of transitions already removed by Animated.TimingFunction.stop() (Put it before the loop that calls to transition.onEnd in executeTransition callback in _updateTransition):

let invalidTransitionIdentifiers = affectedTransitionIdentifiers.filter(function (transitionIdentifier) {
    for (var extendedTransition of completeTransitions) {
        if (extendedTransition.identifier === transitionIdentifier) {
            return false;
        }
    }
    return true;
});

if (invalidTransitionIdentifiers.length > 0) {
    console.warn('Invalid transition IDs: ', invalidTransitionIdentifiers.join(', '));
} else {
    console.warn('There are no invalid transition IDs.');
}

Also recorded a screencast to demonstrate the difference: https://www.dropbox.com/s/vib9euk65lee991/WatchdogEdgecaseFix.mov?dl=0

[erictraut]

Good analysis. I agree with your conclusion.

The mechanism you've added (using a unique transition ID) should solve the problem, but it shouldn't be necessary. There's already a similar mechanism in place within executeTransition. It uses timer IDs to guarantee uniqueness. I just noticed a bug in this code though. It calls done() unconditionally rather than calling it only when the timeoutId matches. That explains the behavior you're seeing.

I just pushed a fix. If you have a chance, please try it out. I haven't published it yet, so you'll need to build a new copy of reactxp yourself. To do so, clone the repo, execute "npm i" followed by "npm run build". Then copy the dist directory to your app ("cp -R ./dist/* [your app]/node_modules/reactxp/dist").

Once you confirm the fix, I'll publish a new version (1.1.0-rc.2).

[pronebird]

@erictraut Great solution! It works on my end.

Just one thing: executeTransition.ts references setTimeout and clearTimeout one using global namespace, the other using window.. It probably does not matter much, but for consistency and to avoid potentially crazy bugs (if we ever happen to run that code in some funny environment), it would be great to align them. 👍

Please push the 1.1.0-rc.2 🎉 🎉 🎉

[erictraut]

Good point. Turns out we were very inconsistent throughout the source base with respect to using window or global namespace. I cleaned it up.

I also published 1.1.0-rc.2.

[pronebird]

Resolved.