search

wix / Detox

Gray box end-to-end testing and automation framework for mobile apps
https://wix.github.io/Detox/
MIT License
11.24k stars 1.92k forks source link

Test stuck on 'The app is busy with the following tasks: • Run loop "Main Run Loop" is awake' #4547

Open crazyvan opened 3 months ago

crazyvan commented 3 months ago

What happened?

I have a test which taps a button:

 await contactDetailsScreen.submitButton.tap();

Its onPress handler dispatches redux actions which eventually send requests to a server, Detox waits for these to complete which is fine and then the test is stuck and the following expectation times out:

 await waitFor(contactDetailsScreen.emailErrorMessage)
                    .toBeVisible()
                    .withTimeout(timeout.thirtySecondsMillis);

On iOS the output is:

20:04:33.972 detox[29339] i The app is busy with the following tasks:
• Run loop "Main Run Loop" is awake.
• There are 2 work items pending on the dispatch queue: "Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)".
20:04:43.981 detox[29339] i The app is busy with the following tasks:
• Run loop "Main Run Loop" is awake.
• There are 2 work items pending on the dispatch queue: "Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)".
20:04:53.988 detox[29339] i The app is busy with the following tasks:
• Run loop "Main Run Loop" is awake.
• There are 2 work items pending on the dispatch queue: "Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)".
20:04:54.068 detox[29339] E ContactDetails screen - enter email that already exists, mobile that is not allowlisted and submit triggers form validation
  error: Test Failed: Timed out while waiting for expectation: TOBEVISIBLE WITH MATCHER(id == “email-error-message”) TIMEOUT(30s)

  HINT: To print view hierarchy on failed actions/matches, use log-level verbose or higher.
20:04:54.070 detox[29339] i Organic registration: test form validation, screen navigation and components [FAIL]

 FAIL  e2e/tests/organicRegistration.e2e.ts (100.898 s)
  Organic registration
    ✕ test form validation, screen navigation and components (67226 ms)

  ● Organic registration › test form validation, screen navigation and components

    Test Failed: Timed out while waiting for expectation: TOBEVISIBLE WITH MATCHER(id == “email-error-message”) TIMEOUT(30s)

    HINT: To print view hierarchy on failed actions/matches, use log-level verbose or higher.

      215 |                 await waitFor(contactDetailsScreen.emailErrorMessage)
      216 |                     .toBeVisible()
    > 217 |                     .withTimeout(timeout.thirtySecondsMillis);
          |                      ^
      218 |
      219 |                 await expect(contactDetailsScreen.mobileErrorMessage).toBeVisible();
      220 |                 await expect(contactDetailsScreen.dobErrorMessage).not.toBeVisible();

Similarly on Android emu the output is:

20:12:04.052 detox[29758] B ContactDetails screen - enter email that already exists, mobile that is not allowlisted and submit triggers form validation
20:12:10.366 detox[29758] i s_glBindAttribLocation: bind attrib 0 name position
s_glBindAttribLocation: bind attrib 1 name color
s_glBindAttribLocation: bind attrib 2 name localCoord

20:12:20.273 detox[29758] i The app seems to be idle
20:12:30.276 detox[29758] i The app seems to be idle
20:12:40.283 detox[29758] i The app seems to be idle
20:12:40.352 detox[29758] E ContactDetails screen - enter email that already exists, mobile that is not allowlisted and submit triggers form validation
  error: Test Failed: 30.0sec timeout expired without matching of given matcher: (view has effective visibility <VISIBLE> and view.getGlobalVisibleRect() covers at least <75> percent of the view's area)
20:12:40.353 detox[29758] i Organic registration: test form validation, screen navigation and components [FAIL]

 FAIL  e2e/tests/organicRegistration.e2e.ts (99.066 s)
  Organic registration
    ✕ test form validation, screen navigation and components (49995 ms)

  ● Organic registration › test form validation, screen navigation and components

    Test Failed: 30.0sec timeout expired without matching of given matcher: (view has effective visibility <VISIBLE> and view.getGlobalVisibleRect() covers at least <75> percent of the view's area)

      215 |                 await waitFor(contactDetailsScreen.emailErrorMessage)
      216 |                     .toBeVisible()
    > 217 |                     .withTimeout(timeout.thirtySecondsMillis);
          |                      ^
      218 |
      219 |                 await expect(contactDetailsScreen.mobileErrorMessage).toBeVisible();
      220 |                 await expect(contactDetailsScreen.dobErrorMessage).not.toBeVisible();

      at tests/organicRegistration.e2e.ts:217:22

Test Suites: 1 failed, 1 total
Tests:       1 failed, 1 total
Snapshots:   0 total
Time:        99.448 s, estimated 101 s

I've tried the following which didn't make a difference and the output was the same:

await device.disableSynchronization();
await contactDetailsScreen.submitButton.tap();
await device.enableSynchronization();

What was the expected behaviour?

No response

Was it tested on latest Detox?

Help us reproduce this issue!

No response

In what environment did this happen?

Detox version: 20.25.1 React Native version: 0.71.12 Has Fabric (React Native's new rendering system) enabled: no Node version: 22.5.1 Device model: iPhone 15 iOS version: 17.5 macOS version: Sonoma 14.6.1 Xcode version: 15.4 Test-runner (select one): jest

Detox logs

Detox logs ``` 20:15:13.055 detox[29962] E ws-client tap 20:15:13.056 detox[29962] i ws-client send message data: {"type":"invoke","params":{"target":{"type":"Class","value":"com.wix.detox.espresso.DetoxAssertion"},"method":"waitForAssertMatcher","args":[{"type":"Invocation","value":{"target":{"type":"Class","value":"androidx.test.espresso.Espresso"},"method":"onView","args":[{"type":"Invocation","value":{"target":{"type":"Class","value":"com.wix.detox.espresso.DetoxMatcher"},"method":"matcherForTestId","args":["email-error-message",{"type":"boolean","value":false}]}}]}},{"type":"Invocation","value":{"target":{"type":"Class","value":"com.wix.detox.espresso.DetoxMatcher"},"method":"matcherForSufficientlyVisible","args":[{"type":"Integer","value":75}]}},{"type":"Double","value":30}]},"messageId":53} 20:15:13.056 detox[29962] B ws-client undefined with timeout (30000 ms) data: { "target": { "type": "Class", "value": "com.wix.detox.espresso.DetoxAssertion" }, "method": "waitForAssertMatcher", "args": [ { "type": "Invocation", "value": { "target": { "type": "Class", "value": "androidx.test.espresso.Espresso" }, "method": "onView", "args": [ { "type": "Invocation", "value": { "target": { "type": "Class", "value": "com.wix.detox.espresso.DetoxMatcher" }, "method": "matcherForTestId", "args": [ "email-error-message", { "type": "boolean", "value": false } ] } } ] } }, { "type": "Invocation", "value": { "target": { "type": "Class", "value": "com.wix.detox.espresso.DetoxMatcher" }, "method": "matcherForSufficientlyVisible", "args": [ { "type": "Integer", "value": 75 } ] } }, { "type": "Double", "value": 30 } ] } stack: /e2e/tests/organicRegistration.e2e.ts:217:22 processTicksAndRejections (node:internal/process/task_queues:95:5) RUNS e2e/tests/organicRegistration.e2e.ts 20:15:13.056 detox[29959] i ws-server@61235 get data: {"type":"invoke","params":{"target":{"type":"Class","value":"com.wix.detox.espresso.DetoxAssertion"},"method":"waitForAssertMatcher","args":[{"type":"Invocation","value":{"target":{"type":"Class","value":"androidx.test.espresso.Espresso"},"method":"onView","args":[{"type":"Invocation","value":{"target":{"type":"Class","value":"com.wix.detox.espresso.DetoxMatcher"},"method":"matcherForTestId","args":["email-error-message",{"type":"boolean","value":false}]}}]}},{"type":"Invocation","value":{"target":{"type":"Class","value":"com.wix.detox.espresso.DetoxMatcher"},"method":"matcherForSufficientlyVisible","args":[{"type":"Integer","value":75}]}},{"type":"Double","value":30}]},"messageId":53} 20:15:13.056 detox[29959] i ws-server@61351 send data: { "type": "invoke", "params": { "target": { "type": "Class", "value": "com.wix.detox.espresso.DetoxAssertion" }, "method": "waitForAssertMatcher", "args": [ { "type": "Invocation", "value": { "target": { "type": "Class", "value": "androidx.test.espresso.Espresso" }, "method": "onView", "args": [ { "type": "Invocation", "value": { "target": { "type": "Class", "value": "com.wix.detox.espresso.DetoxMatcher" }, "method": "matcherForTestId", "args": [ "email-error-message", { "type": "boolean", "value": false } ] } } ] } }, { "type": "Invocation", "value": { "target": { "type": "Class", "value": "com.wix.detox.espresso.DetoxMatcher" }, "method": "matcherForSufficientlyVisible", "args": [ { "type": "Integer", "value": 75 } ] } }, { "type": "Double", "value": 30 } ] }, 20:15:13.189 detox[29962] i child-process:SPAWN_STDERR s_glBindAttribLocation: bind attrib 0 name position s_glBindAttribLocation: bind attrib 1 name color s_glBindAttribLocation: bind attrib 2 name localCoord 20:15:23.056 detox[29962] i ws-client send message data: {"type":"currentStatus","params":{},"messageId":54} RUNS e2e/tests/organicRegistration.e2e.ts 20:15:23.057 detox[29959] i ws-server@61235 get data: {"type":"currentStatus","params":{},"messageId":54} 20:15:23.057 detox[29959] i ws-server@61351 send data: { "type": "currentStatus", "params": {}, "messageId": 54 } 20:15:23.059 detox[29959] i ws-server@61351 get data: {"messageId":54,"type":"currentStatusResult","params":{"status":{"app_status":"idle"}}} 20:15:23.059 detox[29959] i ws-server@61235 send data: { "messageId": 54, "type": "currentStatusResult", "params": { "status": { "app_status": "idle" } 20:15:23.059 detox[29962] i ws-client get message data: {"messageId":54,"type":"currentStatusResult","params":{"status":{"app_status":"idle"}}} 20:15:23.061 detox[29962] i ws-client:APP_STATUS The app seems to be idle 20:15:33.062 detox[29962] i ws-client send message data: {"type":"currentStatus","params":{},"messageId":55} RUNS e2e/tests/organicRegistration.e2e.ts 20:15:33.063 detox[29959] i ws-server@61235 get data: {"type":"currentStatus","params":{},"messageId":55} 20:15:33.063 detox[29959] i ws-server@61351 send data: { "type": "currentStatus", "params": {}, "messageId": 55 } 20:15:33.065 detox[29959] i ws-server@61351 get data: {"messageId":55,"type":"currentStatusResult","params":{"status":{"app_status":"idle"}}} 20:15:33.065 detox[29959] i ws-server@61235 send data: { "messageId": 55, "type": "currentStatusResult", "params": { "status": { "app_status": "idle" } 20:15:33.065 detox[29962] i ws-client get message data: {"messageId":55,"type":"currentStatusResult","params":{"status":{"app_status":"idle"}}} 20:15:33.065 detox[29962] i ws-client:APP_STATUS The app seems to be idle 20:15:43.066 detox[29962] i ws-client send message data: {"type":"currentStatus","params":{},"messageId":56} RUNS e2e/tests/organicRegistration.e2e.ts 20:15:43.067 detox[29959] i ws-server@61235 get data: {"type":"currentStatus","params":{},"messageId":56} 20:15:43.067 detox[29959] i ws-server@61351 send data: { "type": "currentStatus", "params": {}, "messageId": 56 } 20:15:43.079 detox[29959] i ws-server@61351 get data: {"messageId":56,"type":"currentStatusResult","params":{"status":{"app_status":"idle"}}} 20:15:43.080 detox[29959] i ws-server@61235 send data: { "messageId": 56, "type": "currentStatusResult", "params": { "status": { "app_status": "idle" } 20:15:43.080 detox[29962] i ws-client get message data: {"messageId":56,"type":"currentStatusResult","params":{"status":{"app_status":"idle"}}} 20:15:43.080 detox[29962] i ws-client:APP_STATUS The app seems to be idle RUNS e2e/tests/organicRegistration.e2e.ts 20:15:43.148 detox[29959] i ws-server@61351 get data: {"messageId":53,"type":"testFailed","params":{"details":"30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area)"}} 20:15:43.148 detox[29959] i ws-server@61235 send data: { "messageId": 53, "type": "testFailed", "params": { "details": "30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area)" 20:15:43.149 detox[29962] i ws-client get message data: {"messageId":53,"type":"testFailed","params":{"details":"30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area)"}} 20:15:43.149 detox[29962] E ws-client undefined with timeout (30000 ms) error: Test Failed: 30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area) 20:15:43.149 detox[29962] E user ContactDetails screen - enter email that already exists, mobile that is not allowlisted and submit triggers form validation error: Test Failed: 30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area) 20:15:43.149 detox[29962] B artifacts-manager onTestFnFailure args: ({"error":{"name":"DetoxRuntimeError"}}) 20:15:43.149 detox[29962] E artifacts-manager onTestFnFailure 20:15:43.149 detox[29962] E lifecycle test_fn error: Test Failed: 30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area) 20:15:43.150 detox[29962] B artifacts-manager onTestDone args: ({"title":"test form validation, screen navigation and components","fullName":"Organic registration test form validation, screen navigation and components","status":"failed","invocations":1,"timedOut":false}) 20:15:43.150 detox[29962] i artifact:ARTIFACT_STOP stopping ADBLogcatRecording 20:15:43.150 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 shell "date +\"%m-%d %T.000\"" 20:15:43.182 detox[29962] i child-process:EXEC_SUCCESS 08-08 20:15:42.000 20:15:43.183 detox[29962] i child-process:SPAWN_KILL sending SIGINT to: /Users/horiaivan/Library/Android/sdk/platform-tools/adb -s emulator-5554 shell logcat -T "08-08 20:14:52.000" --pid=15731 -f /sdcard/201436754_1.log 20:15:43.184 detox[29962] i child-process:SPAWN_END /Users/horiaivan/Library/Android/sdk/platform-tools/adb -s emulator-5554 shell "logcat -T \"08-08 20:14:52.000\" --pid=15731 -f /sdcard/201436754_1.log" terminated with SIGINT 20:15:43.184 detox[29962] E artifacts-manager onTestDone 20:15:43.185 detox[29962] E lifecycle test form validation, screen navigation and components 20:15:43.185 detox[29962] i lifecycle Organic registration: test form validation, screen navigation and components [FAIL] 20:15:43.185 detox[29962] B lifecycle afterAll 20:15:43.185 detox[29962] B device terminateApp args: () 20:15:43.185 detox[29962] B artifacts-manager onBeforeTerminateApp args: ({"deviceId":"emulator-5554","bundleId":"uk.co.credabilityapptest"}) 20:15:43.185 detox[29962] E artifacts-manager onBeforeTerminateApp 20:15:43.186 detox[29962] i child-process:SPAWN_KILL sending SIGINT to: /Users/horiaivan/Library/Android/sdk/platform-tools/adb -s emulator-5554 shell am instrument -w -r -e detoxServer ws://localhost:61234 -e detoxSessionId 23b69f67-0dc4-5891-a197-13f8dc3ec26b -e debug false uk.co.credabilityapptest.test/androidx.test.runner.AndroidJUnitRunner 20:15:43.186 detox[29962] i artifact:ARTIFACT_SAVE saving ADBLogcatRecording to: artifacts/android.emu.debug.2024-08-08 19-14-36Z/✗ Organic registration test form validation, screen navigation and components/device.log 20:15:43.187 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 pull "/sdcard/201436754_1.log" "artifacts/android.emu.debug.2024-08-08 19-14-36Z/✗ Organic registration test form validation, screen navigation and components/device.log" 20:15:43.187 detox[29962] i child-process:SPAWN_END /Users/horiaivan/Library/Android/sdk/platform-tools/adb -s emulator-5554 shell am instrument -w -r -e detoxServer ws://localhost:61234 -e detoxSessionId 23b69f67-0dc4-5891-a197-13f8dc3ec26b -e debug false uk.co.credabilityapptest.test/androidx.test.runner.AndroidJUnitRunner terminated with SIGINT 20:15:43.187 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 shell "am force-stop uk.co.credabilityapptest" 20:15:43.188 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 reverse --remove tcp:61234 20:15:43.200 detox[29962] i child-process:EXEC_SUCCESS 20:15:43.210 detox[29962] i child-process:EXEC_SUCCESS /sdcard/201436754_1.log: 1 file pulled, 0 skipped. 160.2 MB/s (790528 bytes in 0.005s) 20:15:43.210 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 shell "rm \"/sdcard/201436754_1.log\"" 20:15:43.241 detox[29962] i child-process:EXEC_SUCCESS 20:15:43.242 detox[29962] i artifact:ARTIFACT_SAVE saving ADBLogcatRecording to: artifacts/android.emu.debug.2024-08-08 19-14-36Z/emulator-5554 2024-08-08 19-15-43Z.startup.log 20:15:43.242 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 pull "/sdcard/201436754_0.log" "artifacts/android.emu.debug.2024-08-08 19-14-36Z/emulator-5554 2024-08-08 19-15-43Z.startup.log" RUNS e2e/tests/organicRegistration.e2e.ts 20:15:43.266 detox[29959] i ws-server app exited session 23b69f67-0dc4-5891-a197-13f8dc3ec26b 20:15:43.266 detox[29959] i ws-server@61235 send data: { "type": "appDisconnected" 20:15:43.266 detox[29962] i ws-client get message data: {"type":"appDisconnected"} 20:15:43.267 detox[29962] i child-process:EXEC_SUCCESS /sdcard/201436754_0.log: 1 file pulled, 0 skipped. 97.5 MB/s (266240 bytes in 0.003s) 20:15:43.267 detox[29962] i child-process:EXEC_CMD "/Users/horiaivan/Library/Android/sdk/platform-tools/adb" -s emulator-5554 shell "rm \"/sdcard/201436754_0.log\"" 20:15:43.296 detox[29962] i child-process:EXEC_SUCCESS 20:15:43.296 detox[29962] B artifacts-manager onTerminateApp args: ({"deviceId":"emulator-5554","bundleId":"uk.co.credabilityapptest"}) 20:15:43.296 detox[29962] E artifacts-manager onTerminateApp 20:15:43.296 detox[29962] E device terminateApp 20:15:43.296 detox[29962] E lifecycle afterAll 20:15:43.297 detox[29962] B artifacts-manager onRunDescribeFinish args: ({"name":"Organic registration"}) 20:15:43.297 detox[29962] E artifacts-manager onRunDescribeFinish 20:15:43.297 detox[29962] E lifecycle Organic registration 20:15:43.297 detox[29962] B artifacts-manager onRunDescribeFinish args: ({"name":"ROOT_DESCRIBE_BLOCK"}) 20:15:43.297 detox[29962] E artifacts-manager onRunDescribeFinish 20:15:43.298 detox[29962] E lifecycle run the tests 20:15:43.309 detox[29962] B lifecycle tear down environment 20:15:43.309 detox[29962] B artifacts-manager onBeforeCleanup args: () 20:15:43.309 detox[29962] i child-process:EXEC_SUCCESS 20:15:43.310 detox[29962] i artifact:ARTIFACT_SAVE saving FileArtifact to: artifacts/android.emu.debug.2024-08-08 19-14-36Z/detox_pid_29962.json.log { append: true } 20:15:43.310 detox[29962] i artifact:ARTIFACT_SAVE saving FileArtifact to: artifacts/android.emu.debug.2024-08-08 19-14-36Z/detox_pid_29962.log { append: true } 20:15:43.310 detox[29962] E artifacts-manager onBeforeCleanup RUNS e2e/tests/organicRegistration.e2e.ts 20:15:43.311 detox[29962] i ipc dispatching event to primary-29959 /tmp/detox.primary-29959 : deallocateDevice , { deviceCookie: { id: 'emulator-5554', adbName: 'emulator-5554', name: 'emulator-5554 (pixel8api34)' } } RUNS e2e/tests/organicRegistration.e2e.ts 20:15:43.311 detox[29959] i ipc received event of : deallocateDevice { deviceCookie: { id: 'emulator-5554', adbName: 'emulator-5554', name: 'emulator-5554 (pixel8api34)' } } 20:15:43.312 detox[29959] B device@0 free: emulator-5554 data: {} 20:15:43.313 detox[29962] i ipc ## received events ##554 20:15:43.313 detox[29962] i ipc detected event deallocateDeviceDone {} 20:15:43.313 detox[29962] E lifecycle tear down environment 20:15:43.313 detox[29962] E lifecycle e2e/tests/organicRegistration.e2e.ts FAIL e2e/tests/organicRegistration.e2e.ts (66.677 s) Organic registration ✕ test form validation, screen navigation and components (50209 ms) ● Organic registration › test form validation, screen navigation and components Test Failed: 30.0sec timeout expired without matching of given matcher: (view has effective visibility and view.getGlobalVisibleRect() covers at least <75> percent of the view's area) 215 | await waitFor(contactDetailsScreen.emailErrorMessage) 216 | .toBeVisible() > 217 | .withTimeout(timeout.thirtySecondsMillis); | ^ 218 | 219 | await expect(contactDetailsScreen.mobileErrorMessage).toBeVisible(); 220 | await expect(contactDetailsScreen.dobErrorMessage).not.toBeVisible(); at tests/organicRegistration.e2e.ts:217:22 Test Suites: 1 failed, 1 total Tests: 1 failed, 1 total Snapshots: 0 total Time: 66.724 s, estimated 100 s ```

Device logs

Device logs ``` paste logs here! ```

More data, please!

detox.log detox.trace.json emulator-5554 2024-08-08 19-15-43Z.startup.log

mat1asl0pez commented 3 months ago

Happening to me as well. I tap a button and then react a screen and I can't interact with the elements on that screen.

await element(by.id('my_button')).tap() await element(by.id('my_field')).typeText('abc')

19:40:08.680 detox[35206] i The app is busy with the following tasks:
• There are 1 work items pending on the dispatch queue: "Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)".
• Run loop "Main Run Loop" is awake.
• 1 enqueued native timers:
  - Timer # 1:
    + Fire date: none.
    + Time until fire: 0.000.
    + Repeat interval: 0.
    + Is recurring: YES.

I added await device.disableSynchronization()/enableSynchronization() on several places but still no resolution.

detox ver 20.24.0 device iphone 15 ios 17.5

petemusicpancake commented 1 month ago

Same here. My tests are not working, stuck with an error "The app has not responded to the network requests below: (id = -1000) isReady: {} "

ebrimasamba commented 3 weeks ago

Any solution to this, am having the same problem. The moment you tap the button that should send a network request it shows this:

12:01:38.726 detox[34139] i The app is busy with the following tasks: • 1 enqueued native timers: