Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
tir38 opened this issue Apr 30, 2019 · 24 comments

Comments

@tir38
Copy link

tir38 commented Apr 30, 2019

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

@athkalia
Copy link

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

@tir38
Copy link
Author

tir38 commented May 31, 2019

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

@tir38
Copy link
Author

tir38 commented Jun 12, 2019

@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.

@athkalia
Copy link

I think for us it's already 30mins

@tir38
Copy link
Author

tir38 commented Jun 13, 2019

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.

@izBasit
Copy link

izBasit commented Sep 4, 2019

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

@mykola-tarchanyn
Copy link

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

@ber4444
Copy link

ber4444 commented Nov 21, 2019

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

@athkalia
Copy link

Nope, sorry :/

@hamen
Copy link

hamen commented Aug 3, 2020

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?

@HeinousGames
Copy link

@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

@borwoj
Copy link

borwoj commented Aug 31, 2020

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'

@HeinousGames
Copy link

@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.

@tobrun
Copy link

tobrun commented Nov 3, 2020

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

@tasomaniac
Copy link

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?

@charbgr
Copy link

charbgr commented Dec 27, 2021

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

@mithriltabby
Copy link
Collaborator

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.

@AaronMT
Copy link

AaronMT commented Feb 3, 2023

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.

Zemotacqy pushed a commit to Zemotacqy/android-test that referenced this issue May 5, 2023
Update gradle, build tools, androidx and guava versions to latest stable versions.
@DabsterB
Copy link

DabsterB commented Dec 8, 2023

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

@mithriltabby
Copy link
Collaborator

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.

@AShunevych
Copy link

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.

@mithriltabby
Copy link
Collaborator

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.

@romtsn
Copy link

romtsn commented Jan 11, 2024

@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?

} catch (ClientNotConnected clientNotConnected) {
exception = clientNotConnected;
} catch (IOException e) {
exception = e;
} catch (RemoteException e) {
exception = e;
} finally {
if (exception != null) {
Log.w(
TAG,
String.format("Failed executing shell command [%s] with params [%s]", cmd, params),
exception);
}

If I'm not missing anything, it's not gonna work, because here these exceptions are wrapped into a RuntimeException:

} catch (ClientNotConnected e) {
Log.e(TAG, "ShellCommandClient not connected. Is ShellCommandExecutor service started?", e);
throw new RuntimeException(e);
} catch (IOException | RemoteException e) {
Log.e(
TAG, "ShellCommandClient connection failed. Is ShellCommandExecutor service started?", e);
throw new RuntimeException(e);
}

@mithriltabby
Copy link
Collaborator

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests