Appium is looking for element for a long time

Issues/Bugs
1

I faced into the problem when try to catch element in android. I’ve tried to find element by id (‘player_play_fullscreen’), which is visible, and noticed that it takes too much time:
2015-10-16 09:42:22:385 - info: --> POST /wd/hub/session/d497ed65-7cb2-4d8b-9217-9126847fdf94/elements {“using”:“id”,“value”:“player_play_fullscreen”}

2015-10-16 09:42:22:386 - info: [debug] Waiting up to 0ms for condition
2015-10-16 09:42:22:387 - info: [debug] Pushing command to appium work queue: [“find”,{“strategy”:“id”,“selector”:“player_play_fullscreen”,“context”:"",“multiple”:true}]
2015-10-16 09:42:22:392 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {“cmd”:“action”,“action”:“find”,“params”:{“strategy”:“id”,“selector”:“player_play_fullscreen”,“context”:"",“multiple”:true}}
2015-10-16 09:42:22:392 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2015-10-16 09:42:22:392 - info: [debug] [BOOTSTRAP] [debug] Got command action: find
2015-10-16 09:42:22:397 - info: [debug] [BOOTSTRAP] [debug] Finding player_play_fullscreen using ID with the contextId: multiple: true
2015-10-16 09:42:22:400 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[RESOURCE_ID=com.conax.golive.access.defaultOperator:id/player_play_fullscreen]
2015-10-16 09:42:22:406 - info: [debug] [BOOTSTRAP] [debug] getElements selector:UiSelector[RESOURCE_ID=com.conax.golive.access.defaultOperator:id/player_play_fullscreen]
2015-10-16 09:42:22:409 - info: [debug] [BOOTSTRAP] [debug] Element[] is null: (0)
2015-10-16 09:42:22:413 - info: [debug] [BOOTSTRAP] [debug] getElements tmp selector:UiSelector[INSTANCE=0, RESOURCE_ID=com.conax.golive.access.defaultOperator:id/player_play_fullscreen]
2015-10-16 09:42:32:463 - info: [debug] [BOOTSTRAP] [debug] Element[] is null: (1)
2015-10-16 09:42:32:464 - info: [debug] [BOOTSTRAP] [debug] getElements tmp selector:UiSelector[INSTANCE=1, RESOURCE_ID=com.conax.golive.access.defaultOperator:id/player_play_fullscreen]
2015-10-16 09:42:39:268 - info: --> GET /wd/hub/status {}
2015-10-16 09:42:39:269 - info: [debug] Responding to client with success: {“status”:0,“value”:{“build”:{“version”:“1.4.8”,“revision”:“c8179bd8352d3c62d98fa58b324491230df9342a”}},“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:42:39:269 - info: <-- GET /wd/hub/status 200 0.957 ms - 155 {“status”:0,“value”:{“build”:{“version”:“1.4.8”,“revision”:“c8179bd8352d3c62d98fa58b324491230df9342a”}},“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:42:42:651 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[RESOURCE_ID=android:id/player_play_fullscreen]
2015-10-16 09:42:42:653 - info: [debug] [BOOTSTRAP] [debug] getElements selector:UiSelector[RESOURCE_ID=android:id/player_play_fullscreen]
2015-10-16 09:42:42:653 - info: [debug] [BOOTSTRAP] [debug] Element[] is null: (0)
2015-10-16 09:42:42:653 - info: [debug] [BOOTSTRAP] [debug] getElements tmp selector:UiSelector[INSTANCE=0, RESOURCE_ID=android:id/player_play_fullscreen]
2015-10-16 09:42:42:849 - info: --> GET /wd/hub/status {}
2015-10-16 09:42:42:850 - info: [debug] Responding to client with success: {“status”:0,“value”:{“build”:{“version”:“1.4.8”,“revision”:“c8179bd8352d3c62d98fa58b324491230df9342a”}},“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:42:42:850 - info: <-- GET /wd/hub/status 200 0.977 ms - 155 {“status”:0,“value”:{“build”:{“version”:“1.4.8”,“revision”:“c8179bd8352d3c62d98fa58b324491230df9342a”}},“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:42:52:762 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[DESCRIPTION=player_play_fullscreen]
2015-10-16 09:42:52:765 - info: [debug] [BOOTSTRAP] [debug] getElements selector:UiSelector[DESCRIPTION=player_play_fullscreen]
2015-10-16 09:42:52:765 - info: [debug] [BOOTSTRAP] [debug] Element[] is null: (0)
2015-10-16 09:42:52:765 - info: [debug] [BOOTSTRAP] [debug] getElements tmp selector:UiSelector[DESCRIPTION=player_play_fullscreen, INSTANCE=0]
2015-10-16 09:42:53:161 - info:
–> GET /wd/hub/status {}
2015-10-16 09:42:53:161 - info: [debug] Responding to client with success: {“status”:0,“value”:{“build”:{“version”:“1.4.8”,“revision”:“c8179bd8352d3c62d98fa58b324491230df9342a”}},“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:42:53:162 - info: <-- GET /wd/hub/status 200 0.743 ms - 155 {“status”:0,“value”:{“build”:{“version”:“1.4.8”,“revision”:“c8179bd8352d3c62d98fa58b324491230df9342a”}},“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:43:02:985 - info: [debug] [BOOTSTRAP] [debug] Returning result: {“status”:0,“value”:[{“ELEMENT”:“1”}]}
2015-10-16 09:43:02:986 - info: [debug] Responding to client with success: {“status”:0,“value”:[{“ELEMENT”:“1”}],“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}
2015-10-16 09:43:02:986 - info: <-- POST /wd/hub/session/d497ed65-7cb2-4d8b-9217-9126847fdf94/elements 200 40599.437 ms - 89 {“status”:0,“value”:[{“ELEMENT”:“1”}],“sessionId”:“d497ed65-7cb2-4d8b-9217-9126847fdf94”}

It starts at 09:42:22:385 and finished at 09:43:02:986, so takes 42 seconds…

Also there is an exception in a log from device:

W/UiAutomatorBridge( 3962): Could not detect idle state.
W/UiAutomatorBridge( 3962): java.util.concurrent.TimeoutException: No idle state with idle timeout: 500 within global timeout: 10000
W/UiAutomatorBridge( 3962): at android.app.UiAutomation.waitForIdle(UiAutomation.java:590)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiAutomatorBridge.waitForIdle(UiAutomatorBridge.java:96)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiAutomatorBridge.waitForIdle(UiAutomatorBridge.java:91)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.QueryController.findAccessibilityNodeInfo(QueryController.java:143)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.QueryController.findAccessibilityNodeInfo(QueryController.java:138)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiObject.findAccessibilityNodeInfo(UiObject.java:168)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiObject.waitForExists(UiObject.java:848)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiObject.exists(UiObject.java:899)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.common.UiWatchers$3.checkForCondition(UiWatchers.java:87)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiDevice.runWatchers(UiDevice.java:557)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiObject.findAccessibilityNodeInfo(UiObject.java:173)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiObject.waitForExists(UiObject.java:848)
W/UiAutomatorBridge( 3962): at com.android.uiautomator.core.UiObject.exists(UiObject.java:899)
W/UiAutomatorBridge( 3962): at io.appium.android.bootstrap.utils.TheWatchers.isDialogPresent(TheWatchers.java:35)
W/UiAutomatorBridge( 3962): at io.appium.android.bootstrap.utils.TheWatchers.check(TheWatchers.java:20)
W/UiAutomatorBridge( 3962): at io.appium.android.bootstrap.SocketServer$1.run(SocketServer.java:124)
W/UiAutomatorBridge( 3962): at java.util.Timer$TimerImpl.run(Timer.java:284)

2

Me too getting the similar issue as below, provide me a solution for the same.

::01-04 15:02:12.801 W/UiAutomatorBridge( 927): Could not detect idle state.
Sys data is ::01-04 15:02:12.801 W/UiAutomatorBridge( 927): java.util.concurrent.TimeoutException: No idle state with idle timeout: 500 within global timeout: 10000
Sys data is ::01-04 15:02:12.801 W/UiAutomatorBridge( 927): at android.app.UiAutomation.waitForIdle(UiAutomation.java:590)
Sys data is ::01-04 15:02:12.801 W/UiAutomatorBridge( 927): at com.android.uiautomator.core.UiAutomatorBridge.waitForIdle(UiAutomatorBridge.java:96)
Sys data is ::01-04 15:02:12.801 W/UiAutomatorBridge( 927): at com.android.uiautomator.core.UiAutomatorBridge.waitForIdle(UiAutomatorBridge.java:91)…

3

In my case, the problem is not in the tests, but in the application. The UIAutomator (which appium uses) waiting for the app finishes all activities and then continues its steps. Our app did requests to a database and refreshed UI too often, UIAutomator could not do anything and fell with timeout exception. We reduced the frequency of app requests and now do not have such problems. I hope it helps you to find issue.