search

wix / Detox

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

iOS test running on Bitrise randomly gets blocked waiting for synchronization, not enough information to debug it #4604

Open jzaefferer opened 1 month ago

jzaefferer commented 1 month ago

What happened?

When running our iOS tests of a React Native app on Bitrise, sometimes tests time out, with the output showing it endlessly waits for the synchronization to resolve. Mostly it looks like this:

07:46:42.555 detox[27767] i The app is busy with the following tasks:
• Run loop "Main Run Loop" is awake.
• There are 1 work items pending on the dispatch queue: "Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)".
• The event "Runloop Perform Block" is taking place with object: "Main Run Loop".

We use debugSynchronization: 20000,, so this is logged every 20s.

I've read https://wix.github.io/Detox/docs/troubleshooting/synchronization/#identifying-which-synchronization-mechanism-causes-us-to-wait-too-much and https://github.com/wix-incubator/DetoxSync/blob/master/StatusDocumentation.md, but didn't find anything there that would help resolve this.

This issue occurs in maybe 1% of all runs, so we can't reproduce it. We have a lot of runs every day, so this costs us a lot of time to check out whenever it occurs.

What was the expected behaviour?

If waiting for synchronization never resolves, at least provide better information on what it's actually waiting for, to have a chance of addressing it.

Was it tested on latest Detox?

Did your test throw out a timeout?

Help us reproduce this issue!

No response

In what environment did this happen?

Detox version: 20.26.2 (not latest, but I don't want to try it with the beta release) React Native version: 0.75.2 Has Fabric (React Native's new rendering system) enabled: no Node version: v20.13.1 Device model: iPhone 16, simulator running on Bitrise M1 Large stack iOS version: iOS 18.0 macOS version: - Xcode version: 16 Test-runner (select one): jest

Detox logs

Detox logs ``` 07:42:42.451 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:43:02.457 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:43:22.466 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:43:42.475 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:44:02.483 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:44:22.487 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:44:42.495 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:45:02.507 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:45:22.518 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:45:42.535 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:46:02.539 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:46:22.545 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:46:42.555 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:47:02.577 detox[27767] i The app is busy with the following tasks: • Run loop "Main Run Loop" is awake. • 1 enqueued native timers: - Timer #1: + Fire date: 2024-10-10 07:47:03 +0000. + Time until fire: 1.063. + Repeat interval: 0. + Is recurring: NO. • There are 1 work items pending on the dispatch queue: "Main Queue ()". • The event "Runloop Perform Block" is taking place with object: "Main Run Loop". 07:47:07.899 detox[27767] i The app has not responded to the network requests below: (id = 6) invoke: {"type":"action","action":"scroll","params":[500,"down",0.01,0.6],"predicate":{"type":"id","value":"details_screen","isRegex":false},"while":{"type":"expectation","predicate":{"type":"id","value":"app_press_advanced_settings","isRegex":false},"expectation":"toBeVisible"}} ```

Device logs

Device logs: https://gist.github.com/jzaefferer/2fd9fd5ce02bd9a997f3ea98636c54a7

More data, please!

No response

jayshah123 commented 1 month ago

With Xcode 16 + RN 0.73.9 + Bitrise + detox@20.25.6 combination is also affecting me and couple of others.

atanas-bitrise commented 1 month ago

Hello,

We noticed that when multiple Simulators were booted up for parallel tests, there may be CPU bottlenecks. This ends up in a spike of processes waiting to be executed (in the hundreds). I think that this may correlate with what @jzaefferer is experiencing. Please create support tickets on Bitrise to verify if this is the case.

jzaefferer commented 1 month ago

@atanas-bitrise we only use a single worker, no parallel tests. Should I still create a Bitrise support ticket?

atanas-bitrise commented 1 month ago

@jzaefferer yes, please create a ticket, if it's happening on Bitrise. We can track what happens on the Virtual Machine.