Open elysiunk opened 2 years ago
It seems like the app under test was not able to launch:
[HTTP] Could not cache the response identified by '22054a3e-8d9d-4e20-b14c-a84002d61a82', because it has not been completed
[HTTP] Does the client terminate connections too early?
[WD Proxy] Got response with status 500: {"id":"6da5fd03-21b7-4287-9e1a-72db9d2cfb5b","sessionId":null,"value":{"error":"session not created","message":"java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x14000000 cmp=com.withings.wiscale2.beta/com.withings.wiscale2.MainActivity } within 45000 milliseconds. Perhaps the main thread has not gone idle within a reasonable amount of time? There could be an animation or something constantly repainting the screen. Or the activity is doing network calls on creation? See the threaddump logs. For your reference the last time the event queue was idle before your activity launch request was 1647420182077 and now the last time the queue went idle was: 1647420182229. If these numbers are the same your activity might be hogging the event queue.","stacktrace":"io.appium.espressoserver.lib.handlers.exceptions.SessionNotCreatedException: java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x14000000 cmp=com.withings.wiscale2.beta/com.withings.wiscale2.Mai...
[debug] [W3C] Matched W3C error code 'session not created' to SessionNotCreatedError
[debug] [Espresso] Deleting espresso session
[debug] [ADB] Running '/usr/local/share/android-sdk/platform-tools/adb -P 5037 -s RZ8MB22CATZ shell am force-stop com.withings.wiscale2.beta'
[debug] [Espresso] [Instrumentation] INSTRUMENTATION_RESULT: shortMsg=Process crashed.
[debug] [Espresso] INSTRUMENTATION_CODE: 0
[debug] [Logcat] Stopping logcat capture
What happens when you calls the below command directly?
[Espresso] Starting Espresso Server v1.45.3 with cmd: adb shell am instrument -w -e debug false -e disableAnalytics true io.appium.espressoserver.test/androidx.test.runner.AndroidJUnitRunner
Nothing happens when I send this command, I had the following message and I'm blocked. The app is not launch on the phone.
io.appium.espressoserver.EspressoServerRunnerTest:
The message itself was expected, but not launch indicates the espresso (instrumentation process) waited for the app starts. Then, Tte logcat may help.
I have the problem with my app only if I'm logged in. If I logout from my app, then I start a simple test on the "onboarding" screen of our app, it seems to work (the app is launch, I can try to find element, I also use the appium inspector tool and I can see the different element of the page)
The error is only for the test that open our app when we are logged in. The main screen is doing network calls and the error message says:
Or the activity is doing network calls on creation?
Maybe it's related
Do you know what we should do on appium side to manage this?
Here the logcat trace when we are on "onbarding" screen: logcat_onboarding.txt
Here the logcat trace when we are logged in: logcat_loggedin.txt
Probably https://github.com/android/testing-samples/issues/143#issuecomment-977813061 ? It seems like the issue itself is not Appium specific. Kind of Espresso framework stuff.
Hi! It seems I'm having the same issue (appium 2.0.0-beta.27, espresso-driver 2.2.0, java-client 8.0.0) when trying to start an compose app
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] Encountered internal error running command: An unknown server-side error occurred while processing the command. Original error: java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x10000000 cmp=com.lt.android.portal/.MainActivity } within 45000 milliseconds. Perhaps the main thread has not gone idle within a reasonable amount of time? There could be an animation or something constantly repainting the screen. Or the activity is doing network calls on creation? See the threaddump logs. For your reference the last time the event queue was idle before your activity launch request was 1648645706650 and now the last time the queue went idle was: 1648645740115. If these numbers are the same your activity might be hogging the event queue.
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x10000000 cmp=com.lt.android.portal/.MainActivity } within 45000 milliseconds. Perhaps the main thread has not gone idle within a reasonable amount of time? There could be an animation or something constantly repainting the screen. Or the activity is doing network calls on creation? See the threaddump logs. For your reference the last time the event queue was idle before your activity launch request was 1648645706650 and now the last time the queue went idle was: 1648645740115. If these numbers are the same your activity might be hogging the event queue.
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] at androidx.test.runner.MonitoringInstrumentation.startActivitySync(MonitoringInstrumentation.java:548)
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.helpers.ActivityHelpers.startActivity(ActivityHelpers.kt:113)
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:27)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:23)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.RequestHandler$DefaultImpls.handle(RequestHandler.kt:57)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.http.Router.route(Router.kt:229)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.http.Server.serve(Server.kt:51)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:945)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at java.lang.Thread.run(Thread.java:919)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)]
logcat:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[FinalizerWatchdogDaemon,5,system]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Object.java:442)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Object.java:568)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Daemons$FinalizerWatchdogDaemon.sleepUntilNeeded(Daemons.java:339)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Daemons$FinalizerWatchdogDaemon.runInternal(Daemons.java:319)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Daemons$Daemon.run(Daemons.java:137)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.run(Thread.java:919)
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[MonitoringInstrumentation,5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Object.java:442)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Object.java:568)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.app.Instrumentation.startActivitySync(Instrumentation.java:525)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.app.Instrumentation.startActivitySync(Instrumentation.java:464)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: androidx.test.runner.MonitoringInstrumentation.access$001(MonitoringInstrumentation.java:101)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: androidx.test.runner.MonitoringInstrumentation$4.call(MonitoringInstrumentation.java:538)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: androidx.test.runner.MonitoringInstrumentation$4.call(MonitoringInstrumentation.java:535)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.util.concurrent.FutureTask.run(FutureTask.java:266)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.run(Thread.java:919)
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[Binder:20365_4,5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[Okio Watchdog,5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Object.java:442)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Object.wait(Object.java:568)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: com.android.okhttp.okio.AsyncTimeout.awaitTimeout(AsyncTimeout.java:313)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: com.android.okhttp.okio.AsyncTimeout.access$000(AsyncTimeout.java:42)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: com.android.okhttp.okio.AsyncTimeout$Watchdog.run(AsyncTimeout.java:288)
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[Signal Catcher,5,system]
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[UiAutomation,5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.MessageQueue.nativePollOnce(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.MessageQueue.next(MessageQueue.java:336)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.Looper.loop(Looper.java:174)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.HandlerThread.run(HandlerThread.java:67)
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[GoogleApiHandler,5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.MessageQueue.nativePollOnce(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.MessageQueue.next(MessageQueue.java:336)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.Looper.loop(Looper.java:174)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: android.os.HandlerThread.run(HandlerThread.java:67)
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[Thread-3,5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.sleep(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.sleep(Thread.java:440)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.sleep(Thread.java:356)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.EspressoServerRunnerTest.syncComposeClock$lambda-1(EspressoServerRunnerTest.kt:58)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.EspressoServerRunnerTest.$r8$lambda$jauViYNVZZYLGAmqE_UAyxLcTt0(Unknown Source:0)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.EspressoServerRunnerTest$$ExternalSyntheticLambda0.run(Unknown Source:0)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.run(Thread.java:919)
03-30 16:09:11.915 20365 20420 E THREAD_STATE:
03-30 16:09:11.915 20365 20420 E THREAD_STATE: Thread[NanoHttpd Request Processor (#1),5,main]
03-30 16:09:11.915 20365 20420 E THREAD_STATE: dalvik.system.VMStack.getThreadStackTrace(Native Method)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.getStackTrace(Thread.java:1720)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: java.lang.Thread.getAllStackTraces(Thread.java:1796)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: androidx.test.runner.MonitoringInstrumentation.getThreadState(MonitoringInstrumentation.java:738)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: androidx.test.runner.MonitoringInstrumentation.dumpThreadStateToOutputs(MonitoringInstrumentation.java:733)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: androidx.test.runner.MonitoringInstrumentation.startActivitySync(MonitoringInstrumentation.java:545)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.helpers.ActivityHelpers.startActivity(ActivityHelpers.kt:113)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:27)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:23)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.handlers.RequestHandler$DefaultImpls.handle(RequestHandler.kt:57)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.http.Router.route(Router.kt:229)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: io.appium.espressoserver.lib.http.Server.serve(Server.kt:51)
03-30 16:09:11.915 20365 20420 E THREAD_STATE: fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java
03-30 16:09:11.922 20365 20420 I appium : Responding to server with error: {error=unknown error, message=java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x10000000 cmp=com.lt.android.portal/.MainActivity } within 45000 milliseconds. Perhaps the main thread has not gone idle within a reasonable amount of time? There could be an animation or something constantly repainting the screen. Or the activity is doing network calls on creation? See the threaddump logs. For your reference the last time the event queue was idle before your activity launch request was 1648645706650 and now the last time the queue went idle was: 1648645740115. If these numbers are the same your activity might be hogging the event queue., stacktrace=java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x10000000 cmp=com.lt.android.portal/.MainActivity } within 45000 milliseconds. Perhaps the main thread has not gone idle within a reasonable amount of time? There could be an animation or something constantly repainting the screen. Or the activity is doing network calls on creation? See the threaddump logs. For your reference the last time the event queue was idle before your activity launch request was 1648645706650 and now the last time the queue went idle was: 1648645740115. If these numbers are the same your activity might be hogging the event queue.
03-30 16:09:11.922 20365 20420 I appium : at androidx.test.runner.MonitoringInstrumentation.startActivitySync(MonitoringInstrumentation.java:548)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.helpers.ActivityHelpers.startActivity(ActivityHelpers.kt:113)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:27)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:23)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.handlers.RequestHandler$DefaultImpls.handle(RequestHandler.kt:57)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.http.Router.route(Router.kt:229)
03-30 16:09:11.922 20365 20420 I appium : at io.appium.espressoserver.lib.http.Server.serve(Server.kt:51)
03-30 16:09:11.922 20365 20420 I appium : at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:945)
03-30 16:09:11.922 20365 20420 I appium : at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)
03-30 16:09:11.922 20365 20420 I appium : at java.lang.Thread.run(Thread.java:919)
03-30 16:09:11.922 20365 20420 I appium : }
Full logs: https://gist.github.com/cmaganu/61dc9163fc6cf558b08aa3f0bbb85f4c#file-appium-server-log https://gist.github.com/cmaganu/61dc9163fc6cf558b08aa3f0bbb85f4c#file-logcat-log
From the testing-samples link above I tried without success the "disable animations" suggestion and I couldn't find out how to "Turn on background popup permission".
Any suggestion on how to approach this? Thanks
It means https://developer.android.com/reference/androidx/test/runner/MonitoringInstrumentation#startActivitySync(android.content.Intent) was not able to confirm com.lt.android.portal/.MainActivity
launched.
If the activity was not intended one appium:appWaitPackage
may help.
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] java.lang.RuntimeException: Could not launch intent Intent { act=ACTION_MAIN flg=0x10000000 cmp=com.lt.android.portal/.MainActivity } within 45000 milliseconds. Perhaps the main thread has not gone idle within a reasonable amount of time? There could be an animation or something constantly repainting the screen. Or the activity is doing network calls on creation? See the threaddump logs. For your reference the last time the event queue was idle before your activity launch request was 1648645706650 and now the last time the queue went idle was: 1648645740115. If these numbers are the same your activity might be hogging the event queue.
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] at androidx.test.runner.MonitoringInstrumentation.startActivitySync(MonitoringInstrumentation.java:548)
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.helpers.ActivityHelpers.startActivity(ActivityHelpers.kt:113)
2022-03-30 13:09:13:240 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:27)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handleInternal(StartActivity.kt:23)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.RequestHandler$DefaultImpls.handle(RequestHandler.kt:57)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.handlers.StartActivity.handle(StartActivity.kt:23)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.http.Router.route(Router.kt:229)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at io.appium.espressoserver.lib.http.Server.serve(Server.kt:51)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:945)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)] at java.lang.Thread.run(Thread.java:919)
2022-03-30 13:09:13:241 [EspressoDriver@8d16f04f (e17142d8)]
this is how I managed to get pass this problem https://github.com/appium/appium-espresso-driver/issues/805#issuecomment-1197768092
Hi,
We have an issue with the implementation of our test from UIAutomator2 to espresso. We see the app launch on the phone, but we have a timeout from the server. We disable all animation from the phone settings.
Our Android dev team implement a test in espresso native and they don't have the issue. Here their test code:
Here the trace of appium during the test with appium espresso: appium_traces.txt
Do you have any idea to fix our issue ?
Thanks