Espresso driver fails to start activity (android compose app)

ConstantinM · March 30, 2022, 1:50pm

Hi!
I’m using Appium server v2.0(2.0.0-beta.27), espresso driver ([email protected]) and java-client(8.0.0)
and I’m trying just to start an jetpack compose android app.
It fails when starting the activity.
-from appium server log

2022-03-30 13:08:28:156 [Espresso] Starting activity 'com.lt.android.portal.MainActivity' for package 'com.lt.android.portal'
2022-03-30 13:08:28:157 [WD Proxy] Matched '/appium/device/start_activity' to command name 'startActivity'
2022-03-30 13:08:28:157 [WD Proxy] Proxying [POST /appium/device/start_activity] to [POST http://127.0.0.1:8300/session/7b598010-bd61-4c00-bfd6-bd9792cfb2df/appium/device/start_activity] with body: {"appPackage":"com.lt.android.portal","appActivity":"com.lt.android.portal.MainActivity"}
2022-03-30 13:09:13:198 [WD Proxy] Got response with status 500: {"id":"83accb37-e683-404c-8f61-a656856ba4d4","sessionId":"7b598010-bd61-4c00-bfd6-bd9792cfb2df","value":{"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 ...
2022-03-30 13:09:13:198 [W3C] Matched W3C error code 'unknown error' to UnknownError
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)]

from 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:

gist.github.com

https://gist.github.com/cmaganu/61dc9163fc6cf558b08aa3f0bbb85f4c#file-appium-server-log

appium-server.log

2022-03-30 13:08:18:841 [Appium] Welcome to Appium v2.0.0-beta.27 (REV 9600617c52d0d2e48493424c529ac6c945d2775b)
2022-03-30 13:08:18:843 [Appium] Non-default server args:
2022-03-30 13:08:18:844 [Appium] { logTimestamp: true }
2022-03-30 13:08:18:844 [Appium] Attempting to load driver uiautomator2...
2022-03-30 13:08:18:845 [Appium] Requiring driver at /home/cmaganu/.appium/node_modules/appium-uiautomator2-driver
2022-03-30 13:08:19:248 [Appium] Attempting to load driver espresso...
2022-03-30 13:08:19:249 [Appium] Requiring driver at /home/cmaganu/.appium/node_modules/appium-espresso-driver
2022-03-30 13:08:19:598 [Appium] Appium REST http interface listener started on 0.0.0.0:4723
2022-03-30 13:08:19:598 [Appium] Available drivers:
2022-03-30 13:08:19:598 [Appium]   - [email protected] (automationName 'UiAutomator2')

This file has been truncated. show original

logcat.log

--------- beginning of main
03-30 16:08:20.240  1791  2269 E GnssHAL_GnssInterface: gnssSvStatusCb: a: input svInfo.flags is 8
03-30 16:08:20.241  1791  2269 E GnssHAL_GnssInterface: gnssSvStatusCb: b: input svInfo.flags is 8
03-30 16:08:21.241  1791  2269 E GnssHAL_GnssInterface: gnssSvStatusCb: a: input svInfo.flags is 8
03-30 16:08:21.241  1791  2269 E GnssHAL_GnssInterface: gnssSvStatusCb: b: input svInfo.flags is 8
03-30 16:08:22.241  1791  2269 E GnssHAL_GnssInterface: gnssSvStatusCb: a: input svInfo.flags is 8
03-30 16:08:22.241  1791  2269 E GnssHAL_GnssInterface: gnssSvStatusCb: b: input svInfo.flags is 8
--------- beginning of system
03-30 16:08:22.271  2024  2024 V SettingsProvider: Notifying for 0: content://settings/global/hidden_api_policy_pre_p_apps
03-30 16:08:22.283  2024  2024 V SettingsProvider: Notifying for 0: content://settings/global/hidden_api_policy_p_apps

This file has been truncated. show original

Any suggestion is welcome - I really don’t know where/how to start addressing this issue.
Thanks

Ashok_Singh · March 31, 2022, 2:55am

Hello @ConstantinM, seems I also have a similar query.
Could you please have a look and advice so that I could also reach your level?

Constantin_M · July 28, 2022, 8:29pm

The solution to my problem was that I did not have to start an/the “main” to start the app - espresso driver starts the app without having to start the activity for it.
Trying to start the activity I was just trying to start the app while is was already started/running and this caused appium/the test to fail.