Proof of Concept Insights - (Apparent) Race condition on disconnecting animated nodes

[bentobox19]

Context

The following exception is being thrown at random during E2E tests:

Exception thrown while executing UI block: 'parentNode' is a required parameter

__44-[RCTUIManager flushUIBlocksWithCompletion:]_block_invoke
    RCTUIManager.m:1201
__44-[RCTUIManager flushUIBlocksWithCompletion:]_block_invoke.498
__RCTExecuteOnMainQueue_block_invoke
____detox_sync_dispatch_wrapper_block_invoke
_dispatch_call_block_and_release
_dispatch_client_callout
_dispatch_main_queue_drain
_dispatch_main_queue_callback_4CF
__CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__
__CFRunLoopRun
CFRunLoopRunSpecific
GSEventRunModal
-[UIApplication _run]
__detox_sync_UIApplication_run
UIApplicationMain
main
start_sim
0x0
0x0

Investigation

Building and running the E2E tests

detox build -c ios.sim.debug
detox test -c ios.sim.debug -l trace

Logging of the application

• Command

/usr/bin/xcrun simctl spawn 7BC04173-BF0C-43FD-B02A-0D7DCF1B4893 log stream --level debug --style compact --predicate 'process == "MetaMask"'

• We find the cause of the exception to be at RCTNativeAnimatedNodesManager.m:140.

2022-08-02 23:02:31.998 Df MetaMask[84277:10fd37] (Foundation) *** Assertion failure in -[RCTNativeAnimatedNodesManager disconnectAnimatedNodes:childTag:](), /Users/bentobox/Documents/dev/mm/mobile/node_modules/react-native/Libraries/NativeAnimation/RCTNativeAnimatedNodesManager.m:140

2022-08-02 23:02:31.998 E  MetaMask[84277:10fd37] [com.facebook.react.log:native] Exception thrown while executing UI block: 'parentNode' is a required parameter

• The code at that function is

- (void)disconnectAnimatedNodes:(nonnull NSNumber *)parentTag
                       childTag:(nonnull NSNumber *)childTag
{
  RCTAssertParam(parentTag);
  RCTAssertParam(childTag);

  RCTAnimatedNode *parentNode = _animationNodes[parentTag];
  RCTAnimatedNode *childNode = _animationNodes[childTag];

  RCTAssertParam(parentNode);
  RCTAssertParam(childNode);

  [parentNode removeChild:childNode];
  [childNode setNeedsUpdate];
}

• The line RCTAssertParam(parentNode); is a failing assertion. We further explore by adding logs, and rebuilding the RN app.

#import <React/RCTLog.h>
- (void)disconnectAnimatedNodes:(nonnull NSNumber *)parentTag
                       childTag:(nonnull NSNumber *)childTag
{
  
  RCTLogInfo(@"disconnectAnimatedNodes (Tag) - %@ - %@ +", parentTag, childTag);

  RCTAssertParam(parentTag);
  RCTAssertParam(childTag);

  RCTAnimatedNode *parentNode = _animationNodes[parentTag];
  RCTAnimatedNode *childNode = _animationNodes[childTag];

  RCTLogInfo(@"disconnectAnimatedNodes (parentNode) - %@ - %@ +", parentNode, childNode);

  RCTAssertParam(parentNode);
  RCTAssertParam(childNode);

  [parentNode removeChild:childNode];
  [childNode setNeedsUpdate];
}

• However there is not a lot of evidence for a race condition.
• After some investigation, we find the caller of this function to be at ./node_modules/react-native/Libraries/NativeAnimation/Nodes/RCTStyleAnimatedNode.m:disconnectAnimatedNodes.

  __removeChild(child: AnimatedNode): void {
    const index = this._children.indexOf(child);
    if (index === -1) {
      console.warn("Trying to remove a child that doesn't exist");
      return;
    }
    if (this.__isNative && child.__isNative) {
      NativeAnimatedHelper.API.disconnectAnimatedNodes(
        this.__getNativeTag(),
        child.__getNativeTag(),
      );
    }
    this._children.splice(index, 1);
    if (this._children.length === 0) {
      this.__detach();
    }
  }

• After adding a log (yarn watch will just rebuild the bundle) and restart the test we find the start of a proof:
• Notice the one that produces the exception

2022-08-03 03:06:04.656 I  MetaMask[63634:158457] [com.facebook.react.log:native] b. disconnectAnimatedNodes - (null) - (null) +

• Let's see the error

2022-08-03 04:06:17.676 I  MetaMask[66774:1610a2] [com.facebook.react.log:native] disconnectAnimatedNodes (Tag) - 11502 - 11503 +
2022-08-03 04:06:17.677 I  MetaMask[66774:1610a2] [com.facebook.react.log:native] disconnectAnimatedNodes (Node) - (null) - (null) +

• We want to find out when the parent was deleted

2022-08-03 04:06:17.666 I  MetaMask[66774:1610db] [com.facebook.react.log:javascript] '__removeChild', 10446, 11502

Early Conclusions

• This call was issued before the call within RN. We believe, in parallel there is another call to get rid of the object, which produces the result to RCTAnimatedNode *parentNode = _animationNodes[parentTag]; to be null. More investigation is needed to find the real root cause. For now this is the issued fix

- (void)disconnectAnimatedNodes:(nonnull NSNumber *)parentTag
                       childTag:(nonnull NSNumber *)childTag
{
  RCTAssertParam(parentTag);
  RCTAssertParam(childTag);

  RCTAnimatedNode *parentNode = _animationNodes[parentTag];
  RCTAnimatedNode *childNode = _animationNodes[childTag];

  // Temporary patch!
  // There is a race condition after removing
  // the promise polifill and transform-regenerator.
  //
  // We'll set the investigation of the root cause
  // as technical debt.
  //
  // The caller is at node_modules/react-native/Libraries/
  //   /Animated/nodes/AnimatedWithChildren.js:__removeChild
  if (parentNode) {
    [parentNode removeChild:childNode];
  }

  if (childNode) {
    [childNode setNeedsUpdate];
  }
}

Further Facts

• Different experiments were performed to determine the root cause of the exception.

Testing different patches over main

• We took the main branch, and by only applying this patch into it we were able to obtain the error

diff --git a/node_modules/metro-react-native-babel-preset/src/configs/main.js b/node_modules/metro-react-native-babel-preset/src/configs/main.js
index caa45fe..8eeb742 100644
--- a/node_modules/metro-react-native-babel-preset/src/configs/main.js
+++ b/node_modules/metro-react-native-babel-preset/src/configs/main.js
@@ -174,16 +174,6 @@ const getPreset = (src, options) => {
     extraPlugins.push([require("@babel/plugin-transform-react-jsx-self")]);
   }

-  if (!options || options.enableBabelRuntime !== false) {
-    extraPlugins.push([
-      require("@babel/plugin-transform-runtime"),
-      {
-        helpers: true,
-        regenerator: !isHermes
-      }
-    ]);
-  }
-
   return {
     comments: false,
     compact: true,
@@ -196,7 +186,6 @@ const getPreset = (src, options) => {
       {
         plugins: [
           ...defaultPluginsBeforeRegenerator,
-          isHermes ? null : require("@babel/plugin-transform-regenerator"),
           ...defaultPluginsAfterRegenerator
         ].filter(Boolean)
       },

• Further investigation including the patch react-native+0.66.3.patch, which ,among other things, comments the promise polifill gave the following results.

  • Commenting only the promise polifill makes the exception appear.
  • Removal only of @babel/plugin-transform-runtime won't make the exception appear.
  • Removal only of @babel/plugin-transform-regenerator makes the exception appear.

• It is important to stress the fact that these are tests over a patched main branch. These three patches are fundamental to the working of ses in the react native contect.

Stack trace of __removeChild

• Obtainable with console.log(new Error().stack);

• Needs further study.

Error@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:7802:32
__removeChild@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:75008:32
__detach@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:78559:32
__removeChild@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:75017:24
__detach@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:78342:32
_attachProps@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:78062:38
UNSAFE_componentWillReceiveProps@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:78127:28
callComponentWillReceiveProps@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:20553:52
updateClassInstance@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:20725:42
updateClassComponent@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:24627:45
beginWork$1@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:29655:29
performUnitOfWork@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:29066:29
workLoopSync@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:29005:28
renderRootSync@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:28981:25
performSyncWorkOnRoot@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:28742:40
performSyncWorkOnRoot@[native code]
flushSyncCallbacks@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:19068:36
flushSyncCallbacksOnlyInLegacyMode@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:19049:29
batchedUpdates$1@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:28790:47
batchedUpdates@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:16630:36
notify@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:603478:14
notifyNestedSubs@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:603549:28
handleChangeWrapper@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:603554:27
handleChangeWrapper@[native code]
dispatch@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:550882:17
update_bg_state_cb@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:553331:32
@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:376859:19
forEach@[native code]
notify@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:376858:39
update@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:376881:20
@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:432894:22
generatorResume@[native code]
fulfilled@http://localhost:8081/index.bundle?platform=ios&dev=true&minify=false&modulesOnly=false&runModule=true&app=io.metamask.MetaMask:432776:30
promiseReactionJob@[native code]

[leotm]

prev/old screenshots for reference (and sim rec)

[leotm]

closing as related e2e tests fixed since/currently in

• feat: SES lockdown v0.18.8 (iOS JSC) MetaMask/metamask-mobile#6586