Test run failure after emulator randomly terminates

[ksadowski]

Describe the bug

Due to project changes I need to start running UI tests on API 35. Unfortunately after changing API 34 to 35 test runs started to fail when emulator gets randomly disconnected. There is no reconnection or rerun in such case and scheduled test suite is interrupted.

To Reproduce

I'm running pipeline on Bitrise CI, first stage builds app and test app, then those files are passed to multiple parallel workflows running tests with Marathon (each workflow is separate instance). Issue happens randomly in workflows that are running tests.

At some point (it can be after 1-2 minutes or 15+ minutes) such error happens:

D 08:56:00.471 [DeviceMonitor-3 @coroutine#7] <AdamDeviceProvider> Device emulator-5554 changed state to DISCONNECTED
D 08:56:00.471 [main @coroutine#35] <DevicePoolActor[omni]> remove device 127.0.0.1:5037:emulator-5554
D 08:56:00.471 [main @coroutine#35] <DevicePoolActor[omni]> devices.size = 0
E 08:56:00.471 [AndroidDevice - execution - 127.0.0.1:5037:emulator-5554-2 @coroutine#639] <AndroidDevice> Unable to start screenrecord
com.malinskiy.adam.exception.RequestRejectedException: No exit code delimiter found in 
	at com.malinskiy.adam.request.shell.v1.ShellResultResponseTransformer.transform(ShellResultResponseTransformer.kt:35)
	at com.malinskiy.adam.request.shell.v1.SyncShellCommandRequest.transform(SyncShellCommandRequest.kt:37)
	at com.malinskiy.adam.request.SynchronousRequest.readElement$suspendImpl(SynchronousRequest.kt:43)
	at com.malinskiy.adam.request.SynchronousRequest$readElement$1.invokeSuspend(SynchronousRequest.kt)
	at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42)
	at kotlinx.coroutines.TimeoutKt.withTimeoutOrNull(Timeout.kt:101)
	at com.malinskiy.marathon.android.adam.AdamAndroidDevice.safeStartScreenRecorder(AdamAndroidDevice.kt:420)
	at com.malinskiy.marathon.android.executor.listeners.video.ScreenRecorder.startRecordingTestVideo(ScreenRecorder.kt:28)
	at com.malinskiy.marathon.android.executor.listeners.video.ScreenRecorder.run(ScreenRecorder.kt:16)
	at com.malinskiy.marathon.android.executor.listeners.video.ScreenRecorderTestBatchListener$testStarted$2.invokeSuspend(ScreenRecorderTestBatchListener.kt:68)
Caused by: com.malinskiy.adam.exception.RequestRejectedException: No exit code delimiter found in 
	at com.malinskiy.adam.request.shell.v1.ShellResultResponseTransformer.transform(ShellResultResponseTransformer.kt:35)
	at com.malinskiy.adam.request.shell.v1.SyncShellCommandRequest.transform(SyncShellCommandRequest.kt:37)
	at com.malinskiy.adam.request.SynchronousRequest.readElement$suspendImpl(SynchronousRequest.kt:43)
	at com.malinskiy.adam.request.SynchronousRequest$readElement$1.invokeSuspend(SynchronousRequest.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
D 08:56:00.472 [main @coroutine#35] <DevicePoolActor[omni]> pool DevicePoolId(name=omni): noActiveDevices
E 08:56:00.472 [AndroidDevice - execution - 127.0.0.1:5037:emulator-5554-2 @coroutine#639] <ScreenRecorder> Something went wrong while screen recording
com.malinskiy.adam.exception.RequestRejectedException: No exit code delimiter found in 
	at com.malinskiy.adam.request.shell.v1.ShellResultResponseTransformer.transform(ShellResultResponseTransformer.kt:35)
	at com.malinskiy.adam.request.shell.v1.SyncShellCommandRequest.transform(SyncShellCommandRequest.kt:37)
	at com.malinskiy.adam.request.SynchronousRequest.readElement$suspendImpl(SynchronousRequest.kt:43)
	at com.malinskiy.adam.request.SynchronousRequest$readElement$1.invokeSuspend(SynchronousRequest.kt)
	at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42)
	at kotlinx.coroutines.TimeoutKt.withTimeoutOrNull(Timeout.kt:101)
	at com.malinskiy.marathon.android.adam.AdamAndroidDevice.safeStartScreenRecorder(AdamAndroidDevice.kt:420)
	at com.malinskiy.marathon.android.executor.listeners.video.ScreenRecorder.startRecordingTestVideo(ScreenRecorder.kt:28)
	at com.malinskiy.marathon.android.executor.listeners.video.ScreenRecorder.run(ScreenRecorder.kt:16)
	at com.malinskiy.marathon.android.executor.listeners.video.ScreenRecorderTestBatchListener$testStarted$2.invokeSuspend(ScreenRecorderTestBatchListener.kt:68)
Caused by: com.malinskiy.adam.exception.RequestRejectedException: No exit code delimiter found in 
	at com.malinskiy.adam.request.shell.v1.ShellResultResponseTransformer.transform(ShellResultResponseTransformer.kt:35)
	at com.malinskiy.adam.request.shell.v1.SyncShellCommandRequest.transform(SyncShellCommandRequest.kt:37)
	at com.malinskiy.adam.request.SynchronousRequest.readElement$suspendImpl(SynchronousRequest.kt:43)
	at com.malinskiy.adam.request.SynchronousRequest$readElement$1.invokeSuspend(SynchronousRequest.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
D 08:56:00.472 [main @coroutine#35] <DevicePoolActor[omni]> terminate pool DevicePoolId(name=omni)
W 08:56:00.474 [main @coroutine#629] <D.0.0.1:5037:emulator-5554]> Device execution has been cancelled
kotlinx.coroutines.JobCancellationException: Job was cancelled
	at kotlinx.coroutines.JobSupport.cancel(JobSupport.kt:1556)
	at kotlinx.coroutines.Job$DefaultImpls.cancel$[REDACTED](Job.kt:195)
	at com.malinskiy.marathon.execution.DevicePoolActor.terminate(DevicePoolActor.kt:131)
	at com.malinskiy.marathon.execution.DevicePoolActor.removeDevice(DevicePoolActor.kt:143)
	at com.malinskiy.marathon.execution.DevicePoolActor.receive(DevicePoolActor.kt:42)
	at com.malinskiy.marathon.execution.DevicePoolActor.receive(DevicePoolActor.kt:26)
	at com.malinskiy.marathon.actor.Actor$delegate$1.invokeSuspend(Actor.kt:34)
	at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42)
	at com.malinskiy.marathon.android.adam.AdamAndroidDevice.execute(AdamAndroidDevice.kt:479)
	at com.malinskiy.marathon.execution.device.DeviceActor$executeBatch$2.invokeSuspend(DeviceActor.kt:190)
Caused by: kotlinx.coroutines.JobCancellationException: Job was cancelled
	at kotlinx.coroutines.JobSupport.cancel(JobSupport.kt:1556)
	at kotlinx.coroutines.Job$DefaultImpls.cancel$[REDACTED](Job.kt:195)
	at com.malinskiy.marathon.execution.DevicePoolActor.terminate(DevicePoolActor.kt:131)
	at com.malinskiy.marathon.execution.DevicePoolActor.removeDevice(DevicePoolActor.kt:143)
	at com.malinskiy.marathon.execution.DevicePoolActor.receive(DevicePoolActor.kt:42)
	at com.malinskiy.marathon.execution.DevicePoolActor.receive(DevicePoolActor.kt:26)
	at com.malinskiy.marathon.actor.Actor$delegate$1.invokeSuspend(Actor.kt:34)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:277)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:95)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:69)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$[REDACTED](Builders.kt:48)
	at kotlinx.coroutines.BuildersKt.runBlocking$[REDACTED](Unknown Source)
	at com.malinskiy.marathon.Marathon.run(Marathon.kt:69)
	at com.malinskiy.marathon.cli.ApplicationViewKt.execute(ApplicationView.kt:86)
	at com.malinskiy.marathon.cli.ApplicationViewKt.access$execute(ApplicationView.kt:1)
	at com.malinskiy.marathon.cli.ApplicationViewKt$main$1.invoke(ApplicationView.kt:34)
	at com.malinskiy.marathon.cli.ApplicationViewKt$main$1.invoke(ApplicationView.kt:34)
	at com.malinskiy.marathon.cli.args.MarathonCli.run(CliCommands.kt:44)
	at com.github.ajalt.clikt.core.CoreCliktCommandKt.parse(CoreCliktCommand.kt:107)
	at com.github.ajalt.clikt.core.CoreCliktCommandKt.main(CoreCliktCommand.kt:78)
	at com.github.ajalt.clikt.core.CoreCliktCommandKt.main(CoreCliktCommand.kt:90)
	at com.malinskiy.marathon.cli.ApplicationViewKt.main(ApplicationView.kt:36)
E 08:56:00.475 [DefaultDispatcher-worker-2 @coroutine#636] <AndroidDevice> CoroutineContext closing due to unrecoverable error
java.nio.BufferUnderflowException: null
	at java.base/java.nio.Buffer.nextGetIndex(Buffer.java:699)
	at java.base/java.nio.HeapByteBuffer.get(HeapByteBuffer.java:165)
	at com.malinskiy.adam.transport.vertx.VertxSocket.readByte(VertxSocket.kt:152)
	at com.malinskiy.adam.transport.vertx.VertxSocket$readByte$1.invokeSuspend(VertxSocket.kt)
	at _COROUTINE._BOUNDARY._(CoroutineDebugging.kt:42)
	at com.malinskiy.adam.request.shell.AsyncCompatShellCommandRequest$execute$2.invokeSuspend(AsyncCompatShellCommandRequest.kt:56)
Caused by: java.nio.BufferUnderflowException: null
	at java.base/java.nio.Buffer.nextGetIndex(Buffer.java:699)
	at java.base/java.nio.HeapByteBuffer.get(HeapByteBuffer.java:165)
	at com.malinskiy.adam.transport.vertx.VertxSocket.readByte(VertxSocket.kt:152)
	at com.malinskiy.adam.transport.vertx.VertxSocket$readByte$1.invokeSuspend(VertxSocket.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
D 08:56:00.476 [main @coroutine#629] <D.0.0.1:5037:emulator-5554]> Returning batch 283a77b2-079a-439e-9db0-4acad63cd0c1. Reason: Device 127.0.0.1:5037:emulator-5554 terminated
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t2 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t14 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t13 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t6 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t10 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t12 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t9 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t5 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t8 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t4 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t3 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t16 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t11 but no events received
E 08:56:00.477 [main @coroutine#2] <c.m.m.e.progress.PoolProgressAccumulator> Expected to run package.tests.suites.secondSuite#t7 but no events received
W 08:56:00.486 [DefaultDispatcher-worker-1 @execute 127.0.0.1:5037:emulator-5554#630] <c.m.m.a.e.listeners.TestResultsListener> uncompleted = package.tests.suites.secondSuite#t16, 127.0.0.1:5037:emulator-5554
Allure environment data saved.
Marathon run finished:
Device pool omni:
	18 passed, 0 failed, 0 ignored tests
	Flakiness overhead: 0H 16m 00s
	Raw: 18 passed, 0 failed, 0 ignored, 2 incomplete tests
	Incomplete tests:
		package.tests.suites.secondSuite#t16 incomplete 1 time(s)
		package.tests.suites.firstSuite#t25 incomplete 1 time(s)
Total time: 0H 33m 55s

D 08:56:01.529 [main @coroutine#645] <D.0.0.1:5037:emulator-5554]> terminate 127.0.0.1:5037:emulator-5554
I 08:56:01.530 [main] <c.m.m.e.BugsnagExceptionsReporter> Finish BugSnag
D 08:56:01.530 [main] <com.bugsnag.Bugsnag> Closing connection to Bugsnag
Marathon execution failed
D 08:56:01.611 [Thread-2] <com.bugsnag.Bugsnag> Closing connection to Bugsnag

Expected behavior

Marathon test run shouldn't be interrupted, maybe it's possible to reconnect to booted emulator?

Logs and reports

2 failed test run logs are attached (one with video recording enabled, another one with screenshots). Marathonfile is also included.

Devices (please complete the following information):

• Ubuntu 22.04 for Android & Docker Bitrise stack
• Device: Emulator Pixel 7 (6 too)
• OS: Android API 35

Additional context
I've tried running with both Java 17 and 21, upgrading steps on Bitrise, also updated Marathon test runner to latest - v0.10.4. It was fine with Pixel 6 API 34 on Marathon v0.10.1.

failure-log.txt
failure-log-2.txt
Marathonfile.txt

[Malinskiy]

Marathon terminates when no devices are available for execution. You have devices.size=0 in the log, so that's the reason why your run finishes prematurely, not API 35. I suggest adding more emulators to the run or increasing the stability of devices

[ksadowski]

Thanks for answer, so could you confirm based on both failure logs, that emulator got terminated during the test run, so Marathon just can't reconnect to it? I'm not doing any actions to actively kill it, so if Marathon can't reboot it and reconnect your suggestion is the only option.

[Malinskiy]

Disconnect doesn't mean the device is terminated, merely that connection via adb is lost. Marathon can't reboot the device because it's not responsible for spinning them up in the first place. If the device comes back eventually then it will reuse this device, but that only works if there is more than one device. If no devices are left - there is nothing to do and the run terminates

[ksadowski]

Alright, thanks!

[Zap4ick]

got similar problem, would be good to have some option to make adb try to reconnect to the device...

[trevjonez]

I think the issue is more so with marathon (or adam rather?) marking api 35 and api 36 devices as disconnected when they may not have actually disconnected. Seems like possible flake in how the health is determined? Or possibly some latency or other different behavior starting at 35?

In my case this only manifests as an issue when the disconnection happens in the middle of a coverage file pull leading to partial downloads and truncated .ec files being produced. The test run is marked success even though the file sync did not complete, thus it won't be reran. This will cause gradle cache poisoning in my case since the follow up jacoco report task then fails.

Visible starting on line 452 of this filtered log of my run.
45107.txt

The logs here are a mix of marathon as well as my emulator manager solution. My own adb checks never show it as having lost the ssh connection to the device. Marathon also later picks it back up and resumes using it. Visible in the timeline.

devices in this timeline are all 35/36 and the issue seems to happen about 3x more at api 35 than 36.

[trevjonez]

I suspect it may be some flake in the tcp connection when AsyncDeviceMonitorRequest is ran. Would it be reasonable to add some amount of auto retry on that when it might be transitioning to disconnected?

[trevjonez]

Shower thought, is it possible that a running file pull actually causes the health check to fail?

Well actually might not explain the back to back inits like on 35779 in the timeline screenshot.

[Malinskiy]

From the timeline, you might just be overloading an adb daemon or devices just can't handle the number of concurrent adb connections and drop them. To investigate, you can run adb server with trace logs and see what the server outputs when marathon loses the devices. Back-to-back inits can happen if the connection is lost during init as well (it's many adb commands, not just calling constructor on a class).

Judging by the logs of the original issue at the top, the adb server tells marathon that the device has disconnected i.e. changed state to DISCONNECTED. Marathon will retry this device when it switches back to adb's device state, so I'm not sure which retries everyone is asking here.

[trevjonez]

So I've been testing with multiple adb servers. this for sure helps with being able to handle more devices but has not resolved the 35/36 devices disconnecting randomly in flight even when things are 1:1.

Working thru adding better logging for my ssh processes so i'll be able to produce a set of logs that is easier to sift thru.

At that point I'll have things 1:1:1 for adb-server:ssh:emulator so I can hopefully isolate exactly where things are going sideways. Currently suspicious of ssh more than anything else, still super odd to me that the issue is distinct to 35/36.

For my issue I think something marathon should absolutely do is make sure that it doesn't include any file in the outputs when the device had a disconnect while in the middle of a file pull. Further I don't think test execution should even be recorded as successful unless all the files that need to be pulled are pulled. Marking such a test as incomplete when the file sync ops didn't complete seems like an appropriate behavior.

[trevjonez]

would also be kind of cool if the file pull times were rendered on the timeline report. I assume that is a fair bit of the gaps in my timeline?