Fixes for Xharness issues 354(again), 385, and 389

src/Microsoft.DotNet.XHarness.Android/AdbRunner.cs

@@ -9,6 +9,7 @@
 using System.Runtime.InteropServices;
 using System.Threading;
 using Microsoft.DotNet.XHarness.Android.Execution;
+using Microsoft.DotNet.XHarness.Common.Utilities;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.DotNet.XHarness.Android
@@ -19,6 +20,7 @@ public class AdbRunner
 
         private const string AdbEnvironmentVariableName = "ADB_EXE_PATH";
         private const string AdbDeviceFullInstallFailureMessage = "INSTALL_FAILED_INSUFFICIENT_STORAGE";
+        private const string AdbInstallBrokenPipeError = "Failure calling service package: Broken pipe";
         private const string AdbShellPropertyForBootCompletion = "sys.boot_completed";
         private readonly string _absoluteAdbExePath;
         private readonly ILogger _log;
@@ -132,7 +134,7 @@ public void DumpBugReport(string outputFilePath)
             }
         }
 
-        public void WaitForDevice()
+        public void WaitForDevice(int timeToWaitForBootCompletionSeconds = 300)
         {
             // This command waits for ANY kind of device to be available (emulator or real)
             // Needed because emulators start up asynchronously and take a while.
@@ -146,16 +148,27 @@ public void WaitForDevice()
                 throw new Exception($"Error waiting for Android device/emulator.  Std out:{result.StandardOutput} Std. Err: {result.StandardError}.  Do you need to set the current device?");
             }
 
-            // Once wait-for-device returns, we'll give it up to 30s for 'adb shell getprop sys.boot_completed' to be '1' (as opposed to empty) to make package managers happy
+            // Some users will be installing the emulator and immediately calling xharness, they need to be able to expect the device is ready to load APKs.
+            // Once wait-for-device returns, we'll give it up to timeToWaitForBootCompletionSeconds seconds (default 5 min) for 'adb shell getprop sys.boot_completed'
+            // to be '1' (as opposed to empty) to make subsequent automation happy.
+            var began = DateTimeOffset.UtcNow;
+            var waitingUntil = began.AddSeconds(timeToWaitForBootCompletionSeconds);
             var bootCompleted = RunAdbCommand($"shell getprop {AdbShellPropertyForBootCompletion}");
 
-            int triesLeft = 3;
-            while (!bootCompleted.StandardOutput.Trim().StartsWith("1") && triesLeft > 1)
+            while (!bootCompleted.StandardOutput.Trim().StartsWith("1") && DateTimeOffset.UtcNow < waitingUntil)
             {
                 bootCompleted = RunAdbCommand($"shell getprop {AdbShellPropertyForBootCompletion}");
                 _log.LogDebug($"{AdbShellPropertyForBootCompletion} = '{bootCompleted.StandardOutput.Trim()}'");
                 Thread.Sleep((int)TimeSpan.FromSeconds(10).TotalMilliseconds);
-                triesLeft--;
+            }
+
+            if (bootCompleted.StandardOutput.Trim().StartsWith("1"))
+            {
+                _log.LogDebug($"Waited {DateTimeOffset.UtcNow.Subtract(began).TotalSeconds} seconds for device for {AdbShellPropertyForBootCompletion} to be 1.");
+            }
+            else
+            {
+                _log.LogWarning($"Did not detect boot completion variable on device; variable used ('{AdbShellPropertyForBootCompletion}') may be incorrect or device may be in a bad state");
             }
         }
 
@@ -180,7 +193,6 @@ public void KillAdbServer()
 
         public int InstallApk(string apkPath)
         {
-            bool needToRetry = false;
             _log.LogInformation($"Attempting to install {apkPath}: ");
             if (string.IsNullOrEmpty(apkPath))
             {
@@ -193,26 +205,23 @@ public int InstallApk(string apkPath)
 
             var result = RunAdbCommand($"install \"{apkPath}\"");
 
-            // If this keeps happening, we should look into exercising Helix infra retry logic when on Helix
-            // since users should be able assume tests themselves can't break the ADB server.
-            if (result.ExitCode == (int)AdbExitCodes.ADB_BROKEN_PIPE)
+            // Two possible retry scenarios, theoretically both can happen on the same run:
+
+            // 1. Pipe between ADB server and emulator device is broken; restarting the ADB server helps
+            if (result.ExitCode == (int)AdbExitCodes.ADB_BROKEN_PIPE || result.StandardError.Contains(AdbInstallBrokenPipeError))
             {
                 _log.LogWarning($"Hit broken pipe error; Will make one attempt to restart ADB server, then retry the install");
                 KillAdbServer();
                 StartAdbServer();
-                needToRetry = true; 
+                result = RunAdbCommand($"install \"{apkPath}\"");
             }
 
+            // 2. Installation cache on device is messed up; restarting the device reliably seems to unblock this (unless the device is actually full, if so this will error the same)
             if (result.ExitCode != (int)AdbExitCodes.SUCCESS && result.StandardError.Contains(AdbDeviceFullInstallFailureMessage))
             {
                 _log.LogWarning($"It seems the package installation cache may be full on the device.  We'll try to reboot it before trying one more time.{Environment.NewLine}Output:{result}");
                 RebootAndroidDevice();
                 WaitForDevice();
-                needToRetry = true;
-            }
-
-            if (needToRetry)
-            {
                 result = RunAdbCommand($"install \"{apkPath}\"");
             }
 
@@ -224,6 +233,7 @@ public int InstallApk(string apkPath)
             {
                 _log.LogInformation($"Successfully installed {apkPath}.");
             }
+
             return result.ExitCode;
         }
 
@@ -318,7 +328,8 @@ public List<string> PullFiles(string devicePath, string localPath)
 
                 if (result.ExitCode != (int)AdbExitCodes.SUCCESS)
                 {
-                    _log.LogError(message: $"ERROR: {result}");
+                    throw new Exception($"Failed pulling files: {result}");
+
                 }
                 else
                 {
@@ -442,8 +453,9 @@ public void PushFiles(string localDirectory, string devicePath, bool removeIfPre
             }
             else
             {
-                // May consider abandoning the run here instead of just printing errors.
+                // Abandon the run here, don't just guess.
                 _log.LogError($"Error: listing attached devices / emulators: {result.StandardError}. Check that any emulators have been started, and attached device(s) are connected via USB, powered-on, and unlocked.");
+                throw new Exception("One or more attached Android devices are offline");
             }
             return devicesAndArchitectures;
         }

src/Microsoft.DotNet.XHarness.CLI/Commands/Android/AndroidTestCommand.cs

@@ -13,6 +13,7 @@
 using Microsoft.DotNet.XHarness.Common.CLI;
 using Microsoft.DotNet.XHarness.Common.CLI.CommandArguments;
 using Microsoft.DotNet.XHarness.Common.CLI.Commands;
+using Microsoft.DotNet.XHarness.Common.Utilities;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.DotNet.XHarness.CLI.Commands.Android
@@ -95,7 +96,14 @@ protected override Task<ExitCode> InvokeInternal(ILogger logger)
 
                     // enumerate the devices attached and their architectures
                     // Tell ADB to only use that one (will always use the present one for systems w/ only 1 machine)
-                    runner.SetActiveDevice(GetDeviceToUse(logger, runner, apkRequiredArchitecture));
+                    var deviceToUse = GetDeviceToUse(logger, runner, apkRequiredArchitecture);
+
+                    if (deviceToUse == null)
+                    {
+                        return Task.FromResult(ExitCode.ADB_DEVICE_ENUMERATION_FAILURE);
+                    }
+
+                    runner.SetActiveDevice(deviceToUse);
 
                     // Wait til at least device(s) are ready
                     runner.WaitForDevice();
@@ -120,6 +128,7 @@ protected override Task<ExitCode> InvokeInternal(ILogger logger)
                 // No class name = default Instrumentation
                 ProcessExecutionResults? result = runner.RunApkInstrumentation(apkPackageName, _arguments.InstrumentationName, _arguments.InstrumentationArguments, _arguments.Timeout);
                 bool processCrashed = false;
+                bool failurePullingFiles = false;
 
                 using (logger.BeginScope("Post-test copy and cleanup"))
                 {
@@ -136,7 +145,15 @@ protected override Task<ExitCode> InvokeInternal(ILogger logger)
                             if (resultValues.ContainsKey(possibleResultKey))
                             {
                                 logger.LogInformation($"Found XML result file: '{resultValues[possibleResultKey]}'(key: {possibleResultKey})");
-                                runner.PullFiles(resultValues[possibleResultKey], _arguments.OutputDirectory);
+                                try
+                                {
+                                    runner.PullFiles(resultValues[possibleResultKey], _arguments.OutputDirectory);
+                                }
+                                catch (Exception toLog)
+                                {
+                                    logger.LogError(toLog, "Hit error (typically permissions) trying to pull {filePathOnDevice}", resultValues[possibleResultKey]);
+                                    failurePullingFiles = true;
+                                }
                             }
                         }
                         if (resultValues.ContainsKey(TestRunSummaryVariableName))
@@ -174,10 +191,18 @@ protected override Task<ExitCode> InvokeInternal(ILogger logger)
                     // Optionally copy off an entire folder
                     if (!string.IsNullOrEmpty(_arguments.DeviceOutputFolder))
                     {
-                        var logs = runner.PullFiles(_arguments.DeviceOutputFolder, _arguments.OutputDirectory);
-                        foreach (string log in logs)
+                        try
+                        {
+                            var logs = runner.PullFiles(_arguments.DeviceOutputFolder, _arguments.OutputDirectory);
+                            foreach (string log in logs)
+                            {
+                                logger.LogDebug($"Found output file: {log}");
+                            }
+                        }
+                        catch (Exception toLog)
                         {
-                            logger.LogDebug($"Found output file: {log}");
+                            logger.LogError(toLog, "Hit error (typically permissions) trying to pull {filePathOnDevice}", _arguments.DeviceOutputFolder);
+                            failurePullingFiles = true;
                         }
                     }
 
@@ -195,6 +220,11 @@ protected override Task<ExitCode> InvokeInternal(ILogger logger)
                 {
                     logger.LogError($"Non-success instrumentation exit code: {instrumentationExitCode}, expected: {_arguments.ExpectedExitCode}");
                 }
+                else if (failurePullingFiles)
+                {
+                    logger.LogError($"Received expected instrumentation exit code ({instrumentationExitCode}), but we hit errors pulling files from the device (see log for details.)");
+                    return Task.FromResult(ExitCode.DEVICE_FILE_COPY_FAILURE);
+                }
                 else
                 {
                     return Task.FromResult(ExitCode.SUCCESS);
@@ -210,23 +240,35 @@ protected override Task<ExitCode> InvokeInternal(ILogger logger)
 
         private string? GetDeviceToUse(ILogger logger, AdbRunner runner, string apkRequiredArchitecture)
         {
-            var allDevicesAndTheirArchitectures = runner.GetAttachedDevicesAndArchitectures();
-            if (allDevicesAndTheirArchitectures.Count > 0)
+            Dictionary<string, string?> allDevicesAndTheirArchitectures = new Dictionary<string, string?>();
+            try
             {
-                if (allDevicesAndTheirArchitectures.Any(kvp => kvp.Value != null && kvp.Value.Equals(apkRequiredArchitecture, StringComparison.OrdinalIgnoreCase)))
-                {
-                    var firstAvailableCompatible = allDevicesAndTheirArchitectures.Where(kvp => kvp.Value != null && kvp.Value.Equals(apkRequiredArchitecture, StringComparison.OrdinalIgnoreCase)).FirstOrDefault();
-                    logger.LogInformation($"Using first-found compatible device of {allDevicesAndTheirArchitectures.Count} total- serial: '{firstAvailableCompatible.Key}' - Arch: {firstAvailableCompatible.Value}");
-                    return firstAvailableCompatible.Key;
-                }
-                else
-                {
-                    logger.LogWarning($"No devices found with architecture '{apkRequiredArchitecture}'.  Just returning first available device; installation will likely fail, but we'll try anyways.");
-                    return allDevicesAndTheirArchitectures.Keys.First();
-                }
+                allDevicesAndTheirArchitectures = runner.GetAttachedDevicesAndArchitectures();
+            }
+            catch (Exception toLog)
+            {
+                logger.LogError(toLog, "Exception thrown while trying to find compatible device with architecture {architecture}", apkRequiredArchitecture);
+            }
+
+            if (allDevicesAndTheirArchitectures.Count == 0)
+            {
+                logger.LogError("No attached device detected");
+                return null;
+            }
+
+            if (allDevicesAndTheirArchitectures.Any(kvp => kvp.Value.Equals(apkRequiredArchitecture, StringComparison.OrdinalIgnoreCase)))
+            {
+                // Key-value tuples here are of the form <device serial number, device architecture>
+                KeyValuePair<string, string?> firstAvailableCompatible = allDevicesAndTheirArchitectures.FirstOrDefault(kvp => apkRequiredArchitecture.Equals(kvp.Value, StringComparison.OrdinalIgnoreCase));
+                logger.LogInformation($"Using first-found compatible device of {allDevicesAndTheirArchitectures.Count} total- serial: '{firstAvailableCompatible.Key}' - Arch: {firstAvailableCompatible.Value}");
+                return firstAvailableCompatible.Key;
+            }
+            else
+            {
+                // In this case, the enumeration worked, we found one or more devices, but nothing matched the APK's architecture; fail out.
+                logger.LogError($"No devices found with architecture '{apkRequiredArchitecture}'.");
+                return null;
             }
-            logger.LogError("No attached device detected");
-            return null;
         }
 
         private (Dictionary<string, string> values, int exitCode) ParseInstrumentationOutputs(ILogger logger, string stdOut)

src/Microsoft.DotNet.XHarness.Common/CLI/ExitCode.cs

@@ -51,6 +51,8 @@ public enum ExitCode
         DEVICE_NOT_FOUND = 81,
         RETURN_CODE_NOT_SET = 82,
         APP_LAUNCH_FAILURE = 83,
+        DEVICE_FILE_COPY_FAILURE = 84,
+        ADB_DEVICE_ENUMERATION_FAILURE = 85,
 
         #endregion
     }