Hardcode instrumentation wind up time interval

[mykola-mokhnach]

It looks like the instrumentation process is not very talkative on some phone models.

Addresses https://discuss.appium.io/t/appium-1-11-0beta3-take-to-long-to-initialize-the-app/25166

[mykola-mokhnach]

Please don't merge until the fix is confirmed

[mykola-mokhnach]

@KazuCocoa Can you please confirm if this fix works with the scenario from appium/appium#12019 ?

[KazuCocoa]

Worked like below. Tried 5 times, and they worked. One or twice take a bit long time, but it could launch in leftoversCleanupTimeout

[UiAutomator2] Starting UIAutomator2 server 3.1.1
[UiAutomator2] Using UIAutomator2 server from '/Users/kazuaki/GitHub/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-v3.1.1.apk' and test from '/Users/kazuaki/GitHub/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-debug-androidTest.apk'
[UiAutomator2] Waiting up to 10000ms until instrumentation leftovers are cleaned up
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[UiAutomator2] Instrumentation leftovers have not been cleaned up properly after 10000ms.Continuing anyway
[UiAutomator2] Waiting up to 60000ms for UiAutomator2 to be online...
[debug] [ADB] Creating ADB subprocess with args: ["-P",5037,"-s","emulator-5554","shell","am","instrument","-w","--no-window-animation","io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner"]
[debug] [Instrumentation] INSTRUMENTATION_RESULT: shortMsg=Process crashed.
[debug] [Instrumentation] INSTRUMENTATION_CODE: 0
[debug] [Instrumentation] The process has exited with code 0
[debug] [Instrumentation] io.appium.uiautomator2.server.test.AppiumUiAutomator2Server:
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[WD Proxy] Got an unexpected response: {"errno":"ECONNRESET","code":"ECONNRESET","syscall":"read"}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body
[debug] [WD Proxy] Got response with status 200: "{\"sessionId\":\"SESSIONID\",\"status\":0,\"value\":\"Status Invoked\"}"
[debug] [UiAutomator2] The initialization of the instrumentation process took 12544ms
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://localhost:8200/wd/hub/session] with body: {"desiredCapabilities":{"platform":"LINUX","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"platformName":"android","automationName":"uiautomator2","app":"/Users/kazuaki/GitHub/ruby_lib/test_apps/api.apk","udid":"emulator-5554","noSign":true,"deviceName":"Android Emulator","appPackage":"io.appium.android.apis","appActivity":"io.appium.android.apis.ApiDemos","someCapability":"some_capability","unicodeKeyboard":true,"resetKeyboard":true,"disableWindowAnimation":true,"newCommandTimeout":300,"systemPort":8200,"language":"en","locale":"US","adbExecTimeout":10000,"chromeOptions":{"args":["--disable-popup-blocking"]},"uiautomator2ServerLaunchTimeout":60000},"platformName":"android","automationName":"uiautomator2","app":"/Users/kazuaki/GitHub/ruby_lib/test_apps/api.apk","udid":"emulator-5554","noSign":true,"deviceName":"emulator-5554","appPackage":"io.appium.android.apis","appAc...
[debug] [WD Proxy] Got response with status 200: {"sessionId":"7555cd66-3674-452a-ba4b-fa403539022e","status":0,"value":"Created Session"}

a couple of times were only a few calling [debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8200/wd/hub/status] with no body

[mykola-mokhnach]

@KazuCocoa Can you please check if the delay has been decreased with the most recent commit?

[KazuCocoa]

The latest one works as well. On my environment, there were no significant differences between ee3649b and before the commit one.

[mykola-mokhnach]

Thanks @KazuCocoa