[RN postmortem] `AppWillTerminateWithError` as a response to `isReady` action conceals the crash error message

Open d4vidi opened this issue 3 years ago • 0 comments

AppWillTerminateWithError as a response to isReady action conceals the crash error message

What happened?

See the sequence of network requests in the logs and re-read the description. Looks like we have a bug there.

What was the expected behaviour?

It should have printed a regular app crash error message and reported it to Jest.

Was it tested on latest Detox?

[X] I have tested this issue on the latest Detox release and it still reproduces.

Did your test throw out a timeout?

[X] I have followed the instructions under Identifying which synchronization mechanism causes us to wait too much.

Help us reproduce this issue!

No response

In what environment did this happen?

Detox version: 19.x.x React Native version: 0.67.x Node version: 14.x Device model: Android version: Test-runner (select one): jest-circus / jest+jasmine / mocha / other

Detox logs

[
  {
    '__filename': 'DetoxConnection.js',
    'trackingId': 'app',
    'sessionId': '9f0ec921-92a1-e1ab-8972-f929baa7b017',
    'role': 'app',
    'level': 10,
    'event': 'WSS_SEND_TO',
    'msg': '{"type":"isReady","params":{},"messageId":-1000}',
    'time': '2022-07-19T13:39:16.675Z',
    'v': 0
  },
  {
    '__filename': 'AsyncWebSocket.js',
    'url': 'ws://localhost:57026',
    'level': 10,
    'event': 'WS_MESSAGE',
    'msg': '{"messageId":-10000,"type":"AppWillTerminateWithError","params":{"errorDetails":"@Thread detox.primary(340):\\njava.lang.RuntimeException: .... Check device logs for full details!"}}\n ',
    'time': '2022-07-19T13:39:21.861Z',
    'v': 0
  },
  {
    '__filename': 'ArtifactsManager.js',
    'level': 10,
    'event': 'ARTIFACTS_LIFECYCLE',
    'fn': 'onBeforeTerminateApp',
    'deviceId': 'emulator-10874',
    'bundleId': 'com.app',
    'msg': 'artifactsManager.onBeforeTerminateApp({ deviceId: \'emulator-10874\', bundleId: \'com.app\' })',
    'time': '2022-07-19T13:39:26.863Z',
    'v': 0
  },
  {
    '__filename': 'spawn.js',
    'event': 'SPAWN_KILL',
    'level': 10,
    'signal': 'SIGINT',
    'msg': 'sending SIGINT to: /Users/yaroslavs/Library/Android/Sdk/platform-tools/adb -s emulator-10874 shell am instrument -w -r -e detoxServer ws://localhost:57026 -e detoxSessionId 9f0ec921-92a1-e1ab-8972-f929baa7b017 -e injected-cookie <DATA> -e engineMockServerPort MjM1OQ== -e detoxURLOverride platform/club/0008218e-2eba-4dac-a769-172aea9f6f62 -e debug false com.app.test/com.app.CustomJUnitRunner',
    'time': '2022-07-19T13:39:26.865Z',
    'v': 0
  },
  {
    '__filename': 'spawn.js',
    'fn': 'spawnAndLog',
    'command': '/Users/yaroslavs/Library/Android/Sdk/platform-tools/adb -s emulator-10874 shell am instrument -w -r -e detoxServer ws://localhost:57026 -e detoxSessionId 9f0ec921-92a1-e1ab-8972-f929baa7b017 -e injected-cookie <DATA> -e engineMockServerPort MjM1OQ== -e detoxURLOverride platform/club/0008218e-2eba-4dac-a769-172aea9f6f62 -e debug false com.app.test/com.app.CustomJUnitRunner',
    'trackingId': 106,
    'cpid': 32328,
    'level': 20,
    'event': 'SPAWN_END',
    'signal': 'SIGINT',
    'code': null,
    'msg': '/Users/yaroslavs/Library/Android/Sdk/platform-tools/adb -s emulator-10874 shell am instrument -w -r -e detoxServer ws://localhost:57026 -e detoxSessionId 9f0ec921-92a1-e1ab-8972-f929baa7b017 -e injected-cookie <DATA> -e engineMockServerPort MjM1OQ== -e detoxURLOverride platform/club/0008218e-2eba-4dac-a769-172aea9f6f62 -e debug false com.app.android.dev.test/com.app.CustomJUnitRunner terminated with SIGINT',
    'time': '2022-07-19T13:39:26.866Z',
    'v': 0
  },
  {
    '__filename': 'exec.js',
    'fn': 'execWithRetriesAndLogs',
    'cmd': '"/Users/yaroslavs/Library/Android/Sdk/platform-tools/adb" -s emulator-10874 shell "am force-stop com.app.android.dev"',
    'trackingId': 111,
    'level': 20,
    'event': 'EXEC_CMD',
    'msg': '"/Users/yaroslavs/Library/Android/Sdk/platform-tools/adb" -s emulator-10874 shell "am force-stop com.app.android.dev"',
    'time': '2022-07-19T13:39:26.867Z',
    'v': 0
  },
  {
    '__filename': 'ArtifactsManager.js',
    'level': 10,
    'event': 'ARTIFACTS_LIFECYCLE',
    'fn': 'onHookFailure',
    'error': { 'name': 'DetoxRuntimeError' },
    'hook': 'beforeEach',
    'msg': 'artifactsManager.onHookFailure({\n  error: DetoxRuntimeError: Failed to run application on the device\n  \n  HINT: Most likely, your tests have timed out and called detox.cleanup() ...\n  hook: \'beforeEach\'\n})',
    'time': '2022-07-19T13:39:26.914Z',
    'v': 0
  }
]

Device logs

07-19 16:39:20.950 11235 11377 E AndroidRuntime: FATAL EXCEPTION: detox.primary
07-19 16:39:20.950 11235 11377 E AndroidRuntime: Process: com.wix.android.dev, PID: 11235
07-19 16:39:20.950 11235 11377 E AndroidRuntime: java.lang.RuntimeException: java.util.concurrent.ExecutionException: com.facebook.react.uimanager.IllegalViewOperationException: Trying to resolve view with tag 3 which doesn't exist
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at androidx.test.espresso.Espresso.onIdle(Espresso.java:15)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.TestEngineFacade.awaitIdle(TestEngineFacade.kt:12)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.adapters.server.ReadyActionHandler.handle(DetoxActionHandlers.kt:25)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.adapters.server.ActionsExecutor$executeAction$$inlined$let$lambda$1.run(DetoxActionsDispatcher.kt:64)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Handler.handleCallback(Handler.java:873)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:99)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:193)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.adapters.server.ActionsExecutor$1.run(DetoxActionsDispatcher.kt:50)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at java.lang.Thread.run(Thread.java:764)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: Caused by: java.util.concurrent.ExecutionException: com.facebook.react.uimanager.IllegalViewOperationException: Trying to resolve view with tag 3 which doesn't exist
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at java.util.concurrent.FutureTask.report(FutureTask.java:123)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at java.util.concurrent.FutureTask.get(FutureTask.java:193)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at androidx.test.espresso.Espresso.onIdle(Espresso.java:10)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	... 8 more
07-19 16:39:20.950 11235 11377 E AndroidRuntime: Caused by: com.facebook.react.uimanager.IllegalViewOperationException: Trying to resolve view with tag 3 which doesn't exist
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.facebook.react.uimanager.NativeViewHierarchyManager.resolveView(SourceFile:102)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.reactnative.idlingresources.uimodule.NativeHierarchyManagerReflected.getViewClass(NativeHierarchyManagerReflected.kt:17)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.reactnative.idlingresources.uimodule.RN66Workaround.getUIOpView(RN66Workaround.kt:52)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.reactnative.idlingresources.uimodule.RN66Workaround.isScarceUISwitchCommandStuckInQueue(RN66Workaround.kt:26)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.reactnative.idlingresources.uimodule.UIModuleIdlingResource.checkIdle(UIModuleIdlingResource.kt:47)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.reactnative.idlingresources.DetoxBaseIdlingResource.isIdleNow(DetoxBaseIdlingResource.java:22)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.wix.detox.reactnative.idlingresources.uimodule.UIModuleIdlingResource.doFrame(UIModuleIdlingResource.kt:71)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.view.Choreographer$CallbackRecord.run(Choreographer.java:947)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.view.Choreographer.doCallbacks(Choreographer.java:761)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.view.Choreographer.doFrame(Choreographer.java:693)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:935)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Handler.handleCallback(Handler.java:873)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:99)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at androidx.test.espresso.base.Interrogator.loopAndInterrogate(Interrogator.java:14)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at androidx.test.espresso.base.UiControllerImpl.loopUntil(UiControllerImpl.java:8)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at androidx.test.espresso.base.UiControllerImpl.loopMainThreadUntilIdle(UiControllerImpl.java:17)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at androidx.test.espresso.Espresso$1.run(Espresso.java:1)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:458)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Handler.handleCallback(Handler.java:873)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:99)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:193)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:6669)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
07-19 16:39:20.950 11235 11377 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)
07-19 16:39:20.950 11235 11377 E DetoxCrashHandler: Crash detected!!! thread=detox.primary (340)
07-19 16:39:20.951 11235 11377 I DetoxWSClient: Sending out action 'AppWillTerminateWithError' (ID #-10000)

More data, please!

No response

Jul 24 '22 12:07 d4vidi