android-test icon indicating copy to clipboard operation
android-test copied to clipboard

Published 20 hours ago • verified publisher icon android

java.lang.RuntimeException: androidx.test.services.shellexecutor.ClientNotConnected

Open tir38 opened this issue 6 years ago • 26 comments

Description

Instrumentation test randomly failing. When running espresso tests on our CI machine (which runs tests on Firebase Test Lab) we occasionally get the following crash and then the tests stop:

FATAL EXCEPTION: AndroidTestOrchestrator
Process: androidx.test.orchestrator, PID: 8463
java.lang.RuntimeException: androidx.test.services.shellexecutor.ClientNotConnected
	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommandSync(ShellExecutorImpl.java:60)
	at androidx.test.orchestrator.AndroidTestOrchestrator.execShellCommandSync(AndroidTestOrchestrator.java:532)
	at androidx.test.orchestrator.AndroidTestOrchestrator.access$700(AndroidTestOrchestrator.java:127)
	at androidx.test.orchestrator.AndroidTestOrchestrator$2.run(AndroidTestOrchestrator.java:360)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
	at java.lang.Thread.run(Thread.java:818)
Caused by: androidx.test.services.shellexecutor.ClientNotConnected
	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServer(ShellCommandClient.java:97)
	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServerSync(ShellCommandClient.java:135)
	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommandSync(ShellExecutorImpl.java:56)
	... 6 more

It's never the same test causing the problem. Not sure it matters but it's only when testing on Nexus5X emulator for API versions 23 / 24. Tests on other emulators / API versions all pass fine.

Steps to Reproduce

none

Expected Results

Tests should continue and complete

Actual Results

Crash.

AndroidX Test and Android OS Versions

 junitVersion = '4.12'
androidXJunitVersion = '1.1.1-alpha01'
androidXTestRunnerVersion = '1.1.2-alpha01'
androidXTestRulesVersion = '1.1.2-alpha01'
androidXTestOrchestratorVersion = '1.1.2-alpha01'
espressoCoreVersion = '3.1.2-alpha01'
espressoContribVersion = '3.1.2-alpha01'
espressoIdlingVersion = '3.1.2-alpha01'

Link to a public git repo demonstrating the problem:

none

tir38 avatar Apr 30 '19 17:04 tir38

We are also getting this every now and then. Any luck @tir38 ?

athkalia avatar May 31 '19 06:05 athkalia

@athkalia nope. Sadly we just removed the API 23/24 devices from our list of test emulators =(

tir38 avatar May 31 '19 22:05 tir38

@athkalia this started happening on all of our test emulators (including API28). I think what was happening was that we were hitting the default 15 min timeout for Firebase Test Lab. Depending on how you trigger your tests you may need to increase the timeout

https://cloud.google.com/sdk/gcloud/reference/firebase/test/android/run#--timeout

When we bumped to 30 mins, everything was fine.

tir38 avatar Jun 12 '19 02:06 tir38

I think for us it's already 30mins

athkalia avatar Jun 12 '19 14:06 athkalia

I believe the maximum value is 60 minutes. So maybe you can try bumping it to 35 minutes and see if that helps. The give away for me was when I actually went and looked at the firebase console. I saw this banner that said your test has timed out or expired. I didn't see any actual indication in the logs though.

tir38 avatar Jun 13 '19 15:06 tir38

We are also facing this issue, changing timeout doesn't really help us. We have observed that where ever we have a time out we see the following in the logs. E/FirebaseInstanceId(xxxx): Token retrieval failed: SERVICE_NOT_AVAILABLE

izBasit avatar Sep 04 '19 13:09 izBasit

hey @athkalia , did you ever figure out how to fix the issue?

mykola-tarchanyn avatar Nov 21 '19 03:11 mykola-tarchanyn

Same problem here, even with a 1 hour timeout, I'm getting ClientNotConnected. Previously, tests would run fine with a 7m timeout.

ber4444 avatar Nov 21 '19 21:11 ber4444

Nope, sorry :/

athkalia avatar Nov 28 '19 17:11 athkalia

Do we have an update about this?

It started a few days ago and it's happening with different devices with different API levels on Firebase Test Lab.

08-03 06:22:39.053: D/CarrierSvcBindHelper(1504): No carrier app for: 0
08-03 06:22:39.054: E/ShellCommandClient(11739): Couldn't find a published binder
08-03 06:22:39.056: E/ShellExecutorImpl(11739): ShellCommandClient not connected. Is ShellCommandExecutor service started?
08-03 06:22:39.056: E/ShellExecutorImpl(11739): androidx.test.services.shellexecutor.ClientNotConnected
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServer(ShellCommandClient.java:97)
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommand(ShellExecutorImpl.java:77)
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at androidx.test.orchestrator.TestRunnable.runShellCommand(TestRunnable.java:207)
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at androidx.test.orchestrator.TestRunnable.run(TestRunnable.java:133)
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
08-03 06:22:39.056: E/ShellExecutorImpl(11739): 	at java.lang.Thread.run(Thread.java:764)
08-03 06:22:39.057: I/PackageManager(917): Observer no longer exists.
08-03 06:22:39.059: I/GeofencerStateMachine(6734): removeGeofences: removeRequest=RemoveGeofencingRequest[REMOVE_ALL packageName=com.bendingspoons.thirtydayfitness.test]
08-03 06:22:39.061: I/CarrierServices(3011): [2] RcsAutoStartReceiver.b: carrierServicesJibeServiceEnabled changed from true to true
08-03 06:22:39.061: I/CarrierServices(3011): --------- beginning of crash
08-03 06:22:39.061: E/AndroidRuntime(11739): FATAL EXCEPTION: AndroidTestOrchestrator
08-03 06:22:39.061: E/AndroidRuntime(11739): Process: androidx.test.orchestrator, PID: 11739
08-03 06:22:39.061: E/AndroidRuntime(11739): java.lang.RuntimeException: androidx.test.services.shellexecutor.ClientNotConnected
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommand(ShellExecutorImpl.java:81)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at androidx.test.orchestrator.TestRunnable.runShellCommand(TestRunnable.java:207)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at androidx.test.orchestrator.TestRunnable.run(TestRunnable.java:133)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at java.lang.Thread.run(Thread.java:764)
08-03 06:22:39.061: E/AndroidRuntime(11739): Caused by: androidx.test.services.shellexecutor.ClientNotConnected
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServer(ShellCommandClient.java:97)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommand(ShellExecutorImpl.java:77)
08-03 06:22:39.061: E/AndroidRuntime(11739): 	... 5 more
08-03 06:22:39.062: I/CarrierServices(3011): [2] RcsAutoStartReceiver.b: enableRcs changed from true to true
08-03 06:22:39.072: I/Process(11739): Sending signal. PID: 11739 SIG: 9

Any kind of help, please?

hamen avatar Aug 03 '20 13:08 hamen

@hamen It seems Firebase introduced a bug to TestLab when they updated their dependencies. The bug was introduced in firebase-iid and firebase-messaging dependencies. If you are using either of these dependencies, you must update them to 20.2.3 or later. Messaging is already at 20.2.4

HeinousGames avatar Aug 10 '20 19:08 HeinousGames

Similar issue. Updating dependencies did not help.

gcloud firebase test android run --type instrumentation --app app/build/outputs/apk/... --test app/build/outputs/apk/... --device model=Nexus6,version=21,locale=en_US,orientation=portrait --use-orchestrator --num-flaky-test-attempts=1

08-31 08:42:35.211: I/Remoter(1342): Saved screenshot to '/data/screenshots/__pmv__-0832.jpg'
08-31 08:42:36.162: E/ShellCommandClient(5636): Couldn't find a published binder
08-31 08:42:36.162: E/ShellExecutorImpl(5636): ShellCommandClient not connected. Is ShellCommandExecutor service started?
08-31 08:42:36.162: E/ShellExecutorImpl(5636): androidx.test.services.shellexecutor.ClientNotConnected
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServer(ShellCommandClient.java:97)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommand(ShellExecutorImpl.java:77)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at androidx.test.orchestrator.TestRunnable.runShellCommand(TestRunnable.java:207)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at androidx.test.orchestrator.TestRunnable.run(TestRunnable.java:133)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): 	at java.lang.Thread.run(Thread.java:818)
08-31 08:42:36.162: E/ShellExecutorImpl(5636): --------- beginning of crash
08-31 08:42:36.162: E/AndroidRuntime(5636): FATAL EXCEPTION: AndroidTestOrchestrator
08-31 08:42:36.162: E/AndroidRuntime(5636): Process: androidx.test.orchestrator, PID: 5636
08-31 08:42:36.162: E/AndroidRuntime(5636): java.lang.RuntimeException: androidx.test.services.shellexecutor.ClientNotConnected
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommand(ShellExecutorImpl.java:81)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at androidx.test.orchestrator.TestRunnable.runShellCommand(TestRunnable.java:207)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at androidx.test.orchestrator.TestRunnable.run(TestRunnable.java:133)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at java.lang.Thread.run(Thread.java:818)
08-31 08:42:36.162: E/AndroidRuntime(5636): Caused by: androidx.test.services.shellexecutor.ClientNotConnected
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServer(ShellCommandClient.java:97)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommand(ShellExecutorImpl.java:77)
08-31 08:42:36.162: E/AndroidRuntime(5636): 	... 5 more
08-31 08:42:36.163: W/ActivityManager(1694): Error in app androidx.test.orchestrator running instrumentation ComponentInfo{androidx.test.orchestrator/androidx.test.orchestrator.AndroidTestOrchestrator}:
08-31 08:42:36.163: W/ActivityManager(1694):   androidx.test.services.shellexecutor.ClientNotConnected
08-31 08:42:36.163: W/ActivityManager(1694):   androidx.test.services.shellexecutor.ClientNotConnected: androidx.test.services.shellexecutor.ClientNotConnected
08-31 08:42:36.163: I/ActivityManager(1694): Force stopping androidx.test.orchestrator appid=10082 user=0: finished inst
08-31 08:42:36.163: I/ActivityManager(1694): Killing 5636:androidx.test.orchestrator/u0a82 (adj 0): stop androidx.test.orchestrator
08-31 08:42:36.208: W/ActivityManager(1694): Scheduling restart of crashed service androidx.test.orchestrator/.OrchestratorService in 1000ms
08-31 08:42:36.208: I/ActivityManager(1694):   Force stopping service ServiceRecord{f54f1ef u0 androidx.test.orchestrator/.OrchestratorService}
08-31 08:42:36.513: I/Remoter(1342): Saved screenshot to '/data/screenshots/__pmv__-0833.jpg'
08-31 08:42:36.595: I/OrchestrationListener(16216): OrchestrationListener disconnected from service
08-31 08:42:37.700: I/Remoter(1342): Saved screenshot to '/data/screenshots/__pmv__-0834.jpg'

borwoj avatar Aug 31 '20 16:08 borwoj

@borwoj Android Studio will usually warn you if there is a dependency that can be updated, but I've seen it fail for Firebase dependencies sometimes. You should look up the latest dependency version numbers and compare against the ones in your project, just to be safe.

HeinousGames avatar Sep 01 '20 00:09 HeinousGames

I was hitting the same issue when porting instrumentation tests from module to another. For me the issue was related to not having clearPackageData configuration in the new module:

Groovy gradle syntax:

   testInstrumentationRunnerArguments clearPackageData: 'true'

Kotlin gradle syntax:

  testInstrumentationRunnerArguments = mapOf(
      "clearPackageData" to "true"
    )

Refs https://developer.android.com/training/testing/junit-runner#ato-gradle

tobrun avatar Nov 03 '20 18:11 tobrun

We also have this issue but we always had clearPackageData enabled like mentioned by @tobrun I'm not sure if that's the cause.

Is there anything we can do to help proceed investigation of this issue?

tasomaniac avatar Apr 30 '21 06:04 tasomaniac

We experience the same issue :/ Did anyone find a way to fix it?

charbgr avatar Dec 27 '21 14:12 charbgr

If you look in your system logcat, I expect that you will find that androidx.test.services was killed. Check for low memory issues; that's usually the culprit.

What's happening there is that the code run as an Instrumentation is publishing a service handle to the SpeakEasy service running in androidx.test.services, and the test orchestrator is expecting to get that handle from SpeakEasy so it can run shell commands in the instrumented process (with all of its privileges). If androidx.test.services is killed and restarted between the start of instrumentation and the start of the test, it loses the handle published by the Instrumentation.

mithriltabby avatar Jan 04 '22 18:01 mithriltabby

Our project on Firebase Test Lab are running into this intermittently too (ARM emulator). Frustrating as it ultimately is a timeout with no other information.

We're using latest stable (02/2023):

  • orchestrator: 1.4.2
  • runner: 1.5.2
  • core: 1.5.0
  • ext.junit: 1.1.5
02-02 13:18:32.208: E/AndroidRuntime(7612): FATAL EXCEPTION: AndroidTestOrchestrator
02-02 13:18:32.208: E/AndroidRuntime(7612): Process: androidx.test.orchestrator, PID: 7612
02-02 13:18:32.208: E/AndroidRuntime(7612): java.lang.RuntimeException: androidx.test.services.shellexecutor.ClientNotConnected
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommandSync(ShellExecutorImpl.java:8)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommandSync(ShellExecutorImpl.java:1)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.orchestrator.AndroidTestOrchestrator.execShellCommandSync(AndroidTestOrchestrator.java:3)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.orchestrator.AndroidTestOrchestrator.-$$Nest$smexecShellCommandSync(Unknown Source:0)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.orchestrator.AndroidTestOrchestrator$2.run(AndroidTestOrchestrator.java:1)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at java.lang.Thread.run(Thread.java:923)
02-02 13:18:32.208: E/AndroidRuntime(7612): Caused by: androidx.test.services.shellexecutor.ClientNotConnected
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServer(ShellCommandClient.java:19)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.services.shellexecutor.ShellCommandClient.execOnServerSync(ShellCommandClient.java:2)
02-02 13:18:32.208: E/AndroidRuntime(7612): 	at androidx.test.services.shellexecutor.ShellExecutorImpl.executeShellCommandSync(ShellExecutorImpl.java:2)

and then the orchestrator dies

02-02 13:18:32.218: I/ActivityManager(556): Process androidx.test.orchestrator (pid 7612) has died: fg  BTOP
02-02 13:18:32.218: I/Zygote(301): Process 7612 exited due to signal 9 (Killed)
02-02 13:18:32.218: I/libprocessgroup(556): Successfully killed process cgroup uid 10170 pid 7612 in 0ms
02-02 13:18:32.218: W/ActivityManager(556): Scheduling restart of crashed service androidx.test.orchestrator/.OrchestratorService in 1000ms for connection
02-02 13:18:32.219: W/ActivityManager(556): Crash of app androidx.test.orchestrator running instrumentation ComponentInfo{androidx.test.orchestrator/androidx.test.orchestrator.AndroidTestOrchestrator}
02-02 13:18:32.222: I/ActivityManager(556): Force stopping androidx.test.orchestrator appid=10170 user=0: finished inst
02-02 13:18:32.222: I/ActivityManager(556):   Force stopping service ServiceRecord{26b4b99 u0 androidx.test.orchestrator/.OrchestratorService}

I don't particularly see anything about androidx.test.services dying although I'm not entirely sure what that might be logged as.

AaronMT avatar Feb 03 '23 20:02 AaronMT

Are they any new Information on this bug? We have the same behaviour on our testexecution for 2-3 month now

DabsterB avatar Dec 08 '23 12:12 DabsterB

One thing to watch out for is installing applications after am instrument has started; dex2oat is a memory hog and will often wind up killing androidx.test.services to make room.

mithriltabby avatar Dec 08 '23 18:12 mithriltabby

Any update on this ? For some reason in my case, it's happening only when tests running on API 33 physical device - b0q / Samsung / Galaxy S22 Ultra

Other runs on API 27/28/29/30 are stable.

AShunevych avatar Dec 22 '23 14:12 AShunevych

Are your tests installing an APK after the test starts? dex2oat can take up huge amounts of memory, which can lead to killing androidx.test.services. Performing all installs before the am instrument call should avoid that.

mithriltabby avatar Jan 02 '24 23:01 mithriltabby

@mithriltabby could you clarify the logic behind this snippet? Is it supposed to swallow the exceptions when executing shell commands to avoid tests marked as failed? https://github.com/android/android-test/blob/7a0feb64c2e0d74422fe0e4e617c629f1d73f30c/runner/android_test_orchestrator/java/androidx/test/orchestrator/AndroidTestOrchestrator.java#L523-L535

If I'm not missing anything, it's not gonna work, because here these exceptions are wrapped into a RuntimeException: https://github.com/android/android-test/blob/7a0feb64c2e0d74422fe0e4e617c629f1d73f30c/services/shellexecutor/java/androidx/test/services/shellexecutor/ShellExecutorImpl.java#L65-L72

romtsn avatar Jan 11 '24 23:01 romtsn

That's one of those things that needs refactoring, but there are clients depending on the existing behavior, so doing so is going to be a lot of work and we haven't had time to do it yet.

mithriltabby avatar Jan 12 '24 01:01 mithriltabby