Closed wilsontr closed 3 years ago
Well seems to me that indeed the app is awfully busy, with various, non-repeating actions taking place. What's the time-frame for this? Could you try to increase the overall timeout to something really long (>5 minutes)?
Here's a log with --debug-synchronization 30000
and timeouts set to 10 minutes. I will try using the Detox template app to isolate registering a lot of RNN screens at bootup.
yarn run v1.22.5
warning ../../package.json: No license field
$ detox test --configuration ios --debug-synchronization 30000
detox[9497] INFO: [test.js] DETOX_CONFIGURATION="ios" DETOX_DEBUG_SYNCHRONIZATION=30000 DETOX_REPORT_SPECS=true DETOX_START_TIMESTAMP=1626796297583 DETOX_USE_CUSTOM_LOGGER=true jest --config e2e/config.json --testNamePattern '^((?!:android:).)*$' --maxWorkers 1 e2e
detox[9498] INFO: [AppleSimUtils.js] com.[redacted].[redacted] launched. To watch simulator logs, run:
/usr/bin/xcrun simctl spawn [redacted] log stream --level debug --style compact --predicate 'process == "[redacted]"'
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 1739
Run Loop
⏱ “Main Run Loop”
⏱ “JS Run Loop”
One-time Events
⏱ “Runloop Perform Block” with object: “JS Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 3539
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 5347
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 7148
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 8956
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 10757
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 12565
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 14365
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 16174
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 17974
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 19782
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 21583
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 23391
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 25192
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 27000
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 28801
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 30609
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 32410
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 34218
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 36018
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 36956
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 37827
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 38757
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 39627
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 40565
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 41436
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 42366
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 43236
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 44174
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 45045
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 45974
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 46845
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 47783
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 48653
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 49583
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 50454
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 51392
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 52262
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 53192
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 54063
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 55000
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 55871
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 56801
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 57672
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 58609
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 59480
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 60410
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 61280
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 62199
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 63069
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 63999
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 64869
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 65800
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
Run Loop
⏱ “Main Run Loop”
⏱ “JS Run Loop”
One-time Events
⏱ “Runloop Perform Block” with object: “JS Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 67600
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 68470
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 69401
Run Loop
⏱ “Main Run Loop”
detox[9498] INFO: [APP_STATUS] The system is busy with the following tasks:
Dispatch Queue
⏱ Queue: “Main Queue (<OS_dispatch_queue_main: com.apple.main-thread>)” with 1 work item
JS Timer
⏱ 70271
Run Loop
⏱ “Main Run Loop”
detox[9498] WARN: [PENDING_REQUESTS] The app has not responded to the network requests below:
(id = 20) deliverPayload: {"url":"https://www.[redacted].com/activate/logout"}
(id = -1000) isReady: {}
Unresponded network requests might result in timeout errors in Detox tests.
FAIL e2e/specs/acquisition/Login.e2e.ts (1201.084 s)
App
✕ allows a test user to log in (599991 ms)
● App › allows a test user to log in
thrown: "Exceeded timeout of 600000 ms for a hook.
Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."
19 | }
20 |
> 21 | beforeAll(async () => {
| ^
22 | await init(config, { initGlobals: false });
23 | disableAndroidEmulatorAnimations();
24 | await device.launchApp({
at Object.<anonymous> (init.ts:21:1)
● App › allows a test user to log in
thrown: "Exceeded timeout of 600000 ms for a hook.
Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."
18 | });
19 |
> 20 | afterEach(async () => {
| ^
21 | await resetAppSession();
22 | });
23 |
at specs/acquisition/Login.e2e.ts:20:3
at Object.<anonymous> (specs/acquisition/Login.e2e.ts:12:1)
Turns out this was caused by a timer running in d3-timer as part of Victory Native. https://github.com/FormidableLabs/victory-native/issues/588
Closing.
@wilsontr That's an excellent find. Although, the issue you mentioned states the problem is in fact associated with Android rather than iOS (while the issue here was reported for iOS). Would you mind helping putting the pieces together? 😄
Description
I'm having a hard time getting Detox to sync with our app on both iOS and Android builds. I've been all over the app searching for a culprit, and I've used comments to strip the app down to a bare minimum of what's actually enabled, and I still get the timeout below.
The only thing I've found that can get the app synchronizing is to disable a number of screens that we are registering with React Native Navigation. This is a large app, with 80+ screens being registered at bootup. When I've commented out enough
Navigation.registerComponent()
calls, then the synchronization works. And when I've tried converting all of our screen component imports to inline requires, then the synchronization works.I've tried digging into the individual screen components to look for rogue timers being put in the global scope, but I haven't found anything yet. I have stripped down the app's launch screen and splash screen to the point that there are only buttons visible. We are using ES6 imports to bring in all of the screens that we register with RNN, to maintain type safety.
I get the feeling that this is some kind of race condition in either RNN or Detox that is being exposed by the number of screens that we're registering, but to attach a reproducible example, I'd have to share our whole source repo.
Environment (please complete the following information):
Logs
If you are experiencing a timeout in your test
Device and verbose Detox logs
--loglevel trace
argument and am providing the verbose log below: