diff --git a/tests/xharness/AppBundleInformationParser.cs b/tests/xharness/AppBundleInformationParser.cs index b19e2f8440..e327a4cf52 100644 --- a/tests/xharness/AppBundleInformationParser.cs +++ b/tests/xharness/AppBundleInformationParser.cs @@ -8,6 +8,7 @@ namespace Xharness { public string AppName { get; } public string BundleIdentifier { get; } public string AppPath { get; } + public string Variation { get; set; } public string LaunchAppPath { get; } public Extension? Extension { get; } diff --git a/tests/xharness/AppRunner.cs b/tests/xharness/AppRunner.cs index 9e81d06ae6..aecdc27e9d 100644 --- a/tests/xharness/AppRunner.cs +++ b/tests/xharness/AppRunner.cs @@ -1,6 +1,5 @@ using System; using System.Collections.Generic; -using System.Diagnostics; using System.IO; using System.Linq; using System.Text; @@ -16,16 +15,15 @@ using Xharness.Utilities; namespace Xharness { - class AppRunner + class AppRunner : IAppRunner { - readonly IProcessManager processManager; readonly ISimulatorsLoaderFactory simulatorsLoaderFactory; readonly ISimpleListenerFactory listenerFactory; readonly IDeviceLoaderFactory devicesLoaderFactory; readonly ICrashSnapshotReporterFactory snapshotReporterFactory; readonly ICaptureLogFactory captureLogFactory; readonly IDeviceLogCapturerFactory deviceLogCapturerFactory; - readonly IResultParser resultParser; + readonly ITestReporterFactory testReporterFactory; readonly RunMode runMode; readonly bool isSimulator; @@ -33,7 +31,7 @@ namespace Xharness { readonly IHarness harness; readonly string variation; readonly double timeoutMultiplier; - readonly BuildToolTask buildTask; + readonly string logDirectory; string deviceName; string companionDeviceName; @@ -46,6 +44,12 @@ namespace Xharness { set => ensureCleanSimulatorState = value; } + public IProcessManager ProcessManager { get; private set; } + + public BuildToolTask BuildTask { get; private set; } + + public RunMode RunMode { get; private set; } + bool IsExtension => AppInformation.Extension.HasValue; public AppBundleInformation AppInformation { get; } @@ -54,10 +58,13 @@ namespace Xharness { public string FailureMessage { get; private set; } - public ILog MainLog { get; set; } + public ILog MainLog { get; set; } public ILogs Logs { get; } + public XmlResultJargon XmlJargon => harness.XmlJargon; + public double LaunchTimeout => harness.LaunchTimeout; + public AppRunner (IProcessManager processManager, IAppBundleInformationParser appBundleInformationParser, ISimulatorsLoaderFactory simulatorsFactory, @@ -66,7 +73,7 @@ namespace Xharness { ICrashSnapshotReporterFactory snapshotReporterFactory, ICaptureLogFactory captureLogFactory, IDeviceLogCapturerFactory deviceLogCapturerFactory, - IResultParser resultParser, + ITestReporterFactory reporterFactory, TestTarget target, IHarness harness, ILog mainLog, @@ -84,14 +91,14 @@ namespace Xharness { if (appBundleInformationParser is null) throw new ArgumentNullException (nameof (appBundleInformationParser)); - this.processManager = processManager ?? throw new ArgumentNullException (nameof (processManager)); + this.ProcessManager = processManager ?? throw new ArgumentNullException (nameof (processManager)); this.simulatorsLoaderFactory = simulatorsFactory ?? throw new ArgumentNullException (nameof (simulatorsFactory)); this.listenerFactory = simpleListenerFactory ?? throw new ArgumentNullException (nameof (simpleListenerFactory)); this.devicesLoaderFactory = devicesFactory ?? throw new ArgumentNullException (nameof (devicesFactory)); this.snapshotReporterFactory = snapshotReporterFactory ?? throw new ArgumentNullException (nameof (snapshotReporterFactory)); this.captureLogFactory = captureLogFactory ?? throw new ArgumentNullException (nameof (captureLogFactory)); this.deviceLogCapturerFactory = deviceLogCapturerFactory ?? throw new ArgumentNullException (nameof (deviceLogCapturerFactory)); - this.resultParser = resultParser ?? throw new ArgumentNullException (nameof (resultParser)); + this.testReporterFactory = reporterFactory ?? throw new ArgumentNullException (nameof (testReporterFactory)); this.harness = harness ?? throw new ArgumentNullException (nameof (harness)); this.MainLog = mainLog ?? throw new ArgumentNullException (nameof (mainLog)); this.Logs = logs ?? throw new ArgumentNullException (nameof (logs)); @@ -101,12 +108,13 @@ namespace Xharness { this.ensureCleanSimulatorState = ensureCleanSimulatorState; this.simulators = simulators; this.variation = variation; - this.buildTask = buildTask; + this.BuildTask = buildTask; this.target = target; - runMode = target.ToRunMode (); + RunMode = target.ToRunMode (); isSimulator = target.IsSimulator (); AppInformation = appBundleInformationParser.ParseFromProject (projectFilePath, target, buildConfiguration); + AppInformation.Variation = variation; } async Task FindSimulatorAsync () @@ -137,7 +145,7 @@ namespace Xharness { }).Wait (); DeviceClass [] deviceClasses; - switch (runMode) { + switch (RunMode) { case RunMode.iOS: deviceClasses = new [] { DeviceClass.iPhone, DeviceClass.iPad, DeviceClass.iPod }; break; @@ -148,7 +156,7 @@ namespace Xharness { deviceClasses = new [] { DeviceClass.AppleTV }; // Untested break; default: - throw new ArgumentException (nameof(runMode)); + throw new ArgumentException (nameof(RunMode)); } var selected = devs.ConnectedDevices.Where ((v) => deviceClasses.Contains (v.DeviceClass) && v.IsUsableForDebugging != false); @@ -172,7 +180,7 @@ namespace Xharness { deviceName = selected_data.Name; - if (runMode == RunMode.WatchOS) + if (RunMode == RunMode.WatchOS) companionDeviceName = devs.FindCompanionDevice (MainLog, selected_data).Name; } @@ -197,7 +205,7 @@ namespace Xharness { args.Add (AppInformation.AppPath); AddDeviceName (args, companionDeviceName ?? deviceName); - if (runMode == RunMode.WatchOS) { + if (RunMode == RunMode.WatchOS) { args.Add ("--device"); args.Add ("ios,watchos"); } @@ -205,7 +213,7 @@ namespace Xharness { var totalSize = Directory.GetFiles (AppInformation.AppPath, "*", SearchOption.AllDirectories).Select ((v) => new FileInfo (v).Length).Sum (); MainLog.WriteLine ($"Installing '{AppInformation.AppPath}' to '{companionDeviceName ?? deviceName}'. Size: {totalSize} bytes = {totalSize / 1024.0 / 1024.0:N2} MB"); - return await processManager.ExecuteCommandAsync (harness.MlaunchPath, args, MainLog, TimeSpan.FromHours (1), cancellation_token: cancellation_token); + return await ProcessManager.ExecuteCommandAsync (harness.MlaunchPath, args, MainLog, TimeSpan.FromHours (1), cancellation_token: cancellation_token); } public async Task UninstallAsync () @@ -227,140 +235,12 @@ namespace Xharness { args.Add (AppInformation.BundleIdentifier); AddDeviceName (args, companionDeviceName ?? deviceName); - return await processManager.ExecuteCommandAsync (harness.MlaunchPath, args, MainLog, TimeSpan.FromMinutes (1)); + return await ProcessManager.ExecuteCommandAsync (harness.MlaunchPath, args, MainLog, TimeSpan.FromMinutes (1)); } - (string resultLine, bool failed, bool crashed) ParseResult (AppBundleInformation appInfo, string test_log_path, bool timed_out, out bool crashed) - { - crashed = false; - if (!File.Exists (test_log_path)) { - crashed = true; - return (null, false, true); // if we do not have a log file, the test crashes - } - // parsing the result is different if we are in jenkins or not. - // When in Jenkins, Touch.Unit produces an xml file instead of a console log (so that we can get better test reporting). - // However, for our own reporting, we still want the console-based log. This log is embedded inside the xml produced - // by Touch.Unit, so we need to extract it and write it to disk. We also need to re-save the xml output, since Touch.Unit - // wraps the NUnit xml output with additional information, which we need to unwrap so that Jenkins understands it. - // - // On the other hand, the nunit and xunit do not have that data and have to be parsed. - // - // This if statement has a small trick, we found out that internet sharing in some of the bots (VSTS) does not work, in - // that case, we cannot do a TCP connection to xharness to get the log, this is a problem since if we did not get the xml - // from the TCP connection, we are going to fail when trying to read it and not parse it. Therefore, we are not only - // going to check if we are in CI, but also if the listener_log is valid. - var path = Path.ChangeExtension (test_log_path, "xml"); - resultParser.CleanXml (test_log_path, path); + public TimeSpan GetNewTimeout () => TimeSpan.FromMinutes (harness.Timeout * timeoutMultiplier); - if (harness.InCI && resultParser.IsValidXml (path, out var xmlType)) { - (string resultLine, bool failed, bool crashed) parseResult = (null, false, false); - crashed = false; - try { - var newFilename = resultParser.GetXmlFilePath (path, xmlType); - - // at this point, we have the test results, but we want to be able to have attachments in vsts, so if the format is - // the right one (NUnitV3) add the nodes. ATM only TouchUnit uses V3. - var testRunName = $"{appInfo.AppName} {variation}"; - if (xmlType == XmlResultJargon.NUnitV3) { - var logFiles = new List (); - // add our logs AND the logs of the previous task, which is the build task - logFiles.AddRange (Directory.GetFiles (Logs.Directory)); - if (buildTask != null) // when using the run command, we do not have a build task, ergo, there are no logs to add. - logFiles.AddRange (Directory.GetFiles (buildTask.LogDirectory)); - // add the attachments and write in the new filename - // add a final prefix to the file name to make sure that the VSTS test uploaded just pick - // the final version, else we will upload tests more than once - newFilename = XmlResultParser.GetVSTSFilename (newFilename); - resultParser.UpdateMissingData (path, newFilename, testRunName, logFiles); - } else { - // rename the path to the correct value - File.Move (path, newFilename); - } - path = newFilename; - - // write the human readable results in a tmp file, which we later use to step on the logs - var tmpFile = Path.Combine (Path.GetTempPath (), Guid.NewGuid ().ToString ()); - (parseResult.resultLine, parseResult.failed) = resultParser.GenerateHumanReadableResults (path, tmpFile, xmlType); - File.Copy (tmpFile, test_log_path, true); - File.Delete (tmpFile); - - // we do not longer need the tmp file - Logs.AddFile (path, LogType.XmlLog.ToString ()); - return parseResult; - - } catch (Exception e) { - MainLog.WriteLine ("Could not parse xml result file: {0}", e); - // print file for better debugging - MainLog.WriteLine ("File data is:"); - MainLog.WriteLine (new string ('#', 10)); - using (var stream = new StreamReader (path)) { - string line; - while ((line = stream.ReadLine ()) != null) { - MainLog.WriteLine (line); - } - } - MainLog.WriteLine (new string ('#', 10)); - MainLog.WriteLine ("End of xml results."); - if (timed_out) { - WrenchLog.WriteLine ($"AddSummary: {runMode} timed out
"); - return parseResult; - } else { - WrenchLog.WriteLine ($"AddSummary: {runMode} crashed
"); - MainLog.WriteLine ("Test run crashed"); - crashed = true; - parseResult.crashed = true; - return parseResult; - } - } - - } // delete not needed copy - File.Delete (path); - // not the most efficient way but this just happens when we run - // the tests locally and we usually do not run all tests, we are - // more interested to be efficent on the bots - string resultLine = null; - using (var reader = new StreamReader (test_log_path)) { - string line = null; - bool failed = false; - while ((line = reader.ReadLine ()) != null) { - if (line.Contains ("Tests run:")) { - Console.WriteLine (line); - resultLine = line; - break; - } else if (line.Contains ("[FAIL]")) { - Console.WriteLine (line); - failed = true; - } - } - return (resultLine, failed, false); - } - } - - public bool TestsSucceeded (AppBundleInformation appInfo, string test_log_path, bool timed_out, out bool crashed) - { - var (resultLine, failed, crashed_out) = ParseResult (appInfo, test_log_path, timed_out, out crashed); - // read the parsed logs in a human readable way - if (resultLine != null) { - var tests_run = resultLine.Replace ("Tests run: ", ""); - if (failed) { - WrenchLog.WriteLine ("AddSummary: {0} failed: {1}
", runMode, tests_run); - MainLog.WriteLine ("Test run failed"); - return false; - } else { - WrenchLog.WriteLine ("AddSummary: {0} succeeded: {1}
", runMode, tests_run); - MainLog.WriteLine ("Test run succeeded"); - return true; - } - } else if (timed_out) { - WrenchLog.WriteLine ("AddSummary: {0} timed out
", runMode); - return false; - } else { - WrenchLog.WriteLine ("AddSummary: {0} crashed
", runMode); - MainLog.WriteLine ("Test run crashed"); - crashed = true; - return false; - } - } + public void LogException (int minLevel, string message, params object [] args) => harness.Log (minLevel, message, args); public async Task RunAsync () { @@ -416,8 +296,8 @@ namespace Xharness { args.Add ($"-setenv=NUNIT_HOSTNAME={ips}"); } - var listener_log = Logs.Create ($"test-{runMode.ToString().ToLower()}-{Helpers.Timestamp}.log", LogType.TestLog.ToString (), timestamp: !useXmlOutput); - var (transport, listener, listenerTmpFile) = listenerFactory.Create (runMode, MainLog, listener_log, isSimulator, true, useXmlOutput); + var listener_log = Logs.Create ($"test-{RunMode.ToString().ToLower()}-{Helpers.Timestamp}.log", LogType.TestLog.ToString (), timestamp: !useXmlOutput); + var (transport, listener, listenerTmpFile) = listenerFactory.Create (RunMode, MainLog, listener_log, isSimulator, true, useXmlOutput); args.Add ($"-argument=-app-arg:-transport:{transport}"); args.Add ($"-setenv=NUNIT_TRANSPORT={transport.ToString ().ToUpper ()}"); @@ -432,31 +312,20 @@ namespace Xharness { listener.StartAsync (); - var cancellation_source = new CancellationTokenSource (); - var timed_out = false; + // object that will take care of capturing and parsing the results + ILog run_log = MainLog; + var crashLogs = new Logs (Logs.Directory); + ICrashSnapshotReporter crashReporter = snapshotReporterFactory.Create (MainLog, crashLogs, isDevice: !isSimulator, deviceName); + var testReporter = testReporterFactory.Create (this, deviceName, listener, run_log, crashReporter, new XmlResultParser ()); listener.ConnectedTask .TimeoutAfter (TimeSpan.FromMinutes (harness.LaunchTimeout)) - .ContinueWith ((v) => { - if (v.IsFaulted) { - MainLog.WriteLine ("Test launch failed: {0}", v.Exception); - } else if (v.IsCanceled) { - MainLog.WriteLine ("Test launch was cancelled."); - } else if (v.Result) { - MainLog.WriteLine ("Test run started"); - } else { - cancellation_source.Cancel (); - MainLog.WriteLine ("Test launch timed out after {0} minute(s).", harness.LaunchTimeout); - timed_out = true; - } - }).DoNotAwait (); + .ContinueWith (testReporter.LaunchCallback) + .DoNotAwait (); foreach (var kvp in harness.EnvironmentVariables) args.Add ($"-setenv={kvp.Key}={kvp.Value}"); - bool? success = null; - bool launch_failure = false; - if (IsExtension) { switch (AppInformation.Extension) { case Extension.TodayExtension: @@ -476,16 +345,11 @@ namespace Xharness { if (!isSimulator) args.Add ("--disable-memory-limits"); - var timeout = TimeSpan.FromMinutes (harness.Timeout * timeoutMultiplier); - - var crashLogs = new Logs (Logs.Directory); - ICrashSnapshotReporter crashReporter = snapshotReporterFactory.Create (MainLog, crashLogs, isDevice: !isSimulator, deviceName); - if (isSimulator) { if (!await FindSimulatorAsync ()) return 1; - if (runMode != RunMode.WatchOS) { + if (RunMode != RunMode.WatchOS) { var stderr_tty = harness.GetStandardErrorTty (); if (!string.IsNullOrEmpty (stderr_tty)) { args.Add ($"--stdout={stderr_tty}"); @@ -517,7 +381,7 @@ namespace Xharness { WrenchLog.WriteLine ("AddFile: {0}", log.FullPath); } - MainLog.WriteLine ("*** Executing {0}/{1} in the simulator ***", AppInformation.AppName, runMode); + MainLog.WriteLine ("*** Executing {0}/{1} in the simulator ***", AppInformation.AppName, RunMode); if (EnsureCleanSimulatorState) { foreach (var sim in simulators) @@ -530,55 +394,8 @@ namespace Xharness { MainLog.WriteLine ("Starting test run"); - ILog run_log = MainLog; - var result = await processManager.ExecuteCommandAsync (harness.MlaunchPath, - args, - run_log, - timeout, - cancellation_token: cancellation_source.Token); - - if (result.TimedOut) { - timed_out = true; - success = false; - MainLog.WriteLine ("Test run timed out after {0} minute(s).", timeout); - } else if (result.Succeeded) { - MainLog.WriteLine ("Test run completed"); - success = true; - } else { - MainLog.WriteLine ("Test run failed"); - success = false; - } - - if (!success.Value) { - // find pid - var pid = -1; - using (var reader = run_log.GetReader ()) { - while (!reader.EndOfStream) { - var line = reader.ReadLine (); - if (line.StartsWith ("Application launched. PID = ", StringComparison.Ordinal)) { - var pidstr = line.Substring ("Application launched. PID = ".Length); - if (!int.TryParse (pidstr, out pid)) - MainLog.WriteLine ("Could not parse pid: {0}", pidstr); - } else if (line.Contains ("Xamarin.Hosting: Launched ") && line.Contains (" with pid ")) { - var pidstr = line.Substring (line.LastIndexOf (' ')); - if (!int.TryParse (pidstr, out pid)) - MainLog.WriteLine ("Could not parse pid: {0}", pidstr); - } else if (line.Contains ("error MT1008")) { - launch_failure = true; - } - } - } - if (pid > 0) { - var launchTimedout = cancellation_source.IsCancellationRequested; - var timeoutType = launchTimedout ? "Launch" : "Completion"; - var timeoutValue = launchTimedout ? harness.LaunchTimeout : timeout.TotalSeconds; - MainLog.WriteLine ($"{timeoutType} timed out after {timeoutValue} seconds"); - await processManager.KillTreeAsync (pid, MainLog, true); - } else { - MainLog.WriteLine ("Could not find pid in mtouch output."); - } - } - + await testReporter.CollectSimulatorResult ( + ProcessManager.ExecuteCommandAsync (harness.MlaunchPath, args, run_log, testReporter.Timeout, cancellation_token: testReporter.CancellationToken)); // cleanup after us if (EnsureCleanSimulatorState) @@ -588,9 +405,9 @@ namespace Xharness { log.StopCapture (); } else { - MainLog.WriteLine ("*** Executing {0}/{1} on device '{2}' ***", AppInformation.AppName, runMode, deviceName); + MainLog.WriteLine ("*** Executing {0}/{1} on device '{2}' ***", AppInformation.AppName, RunMode, deviceName); - if (runMode == RunMode.WatchOS) { + if (RunMode == RunMode.WatchOS) { args.Add ("--attach-native-debugger"); // this prevents the watch from backgrounding the app. } else { args.Add ("--wait-for-exit"); @@ -607,38 +424,10 @@ namespace Xharness { MainLog.WriteLine ("Starting test run"); - bool waitedForExit = true; // We need to check for MT1111 (which means that mlaunch won't wait for the app to exit). - var callbackLog = new CallbackLog ((line) => { - // MT1111: Application launched successfully, but it's not possible to wait for the app to exit as requested because it's not possible to detect app termination when launching using gdbserver - waitedForExit &= line?.Contains ("MT1111: ") != true; - if (line?.Contains ("error MT1007") == true) - launch_failure = true; - }); - - var runLog = Log.CreateAggregatedLog (callbackLog, MainLog); - var timeoutWatch = Stopwatch.StartNew (); - var result = await processManager.ExecuteCommandAsync (harness.MlaunchPath, args, runLog, timeout, cancellation_token: cancellation_source.Token); - - if (!waitedForExit && !result.TimedOut) { - // mlaunch couldn't wait for exit for some reason. Let's assume the app exits when the test listener completes. - MainLog.WriteLine ("Waiting for listener to complete, since mlaunch won't tell."); - if (!await listener.CompletionTask.TimeoutAfter (timeout - timeoutWatch.Elapsed)) { - result.TimedOut = true; - } - } - - if (result.TimedOut) { - timed_out = true; - success = false; - MainLog.WriteLine ("Test run timed out after {0} minute(s).", timeout.TotalMinutes); - } else if (result.Succeeded) { - MainLog.WriteLine ("Test run completed"); - success = true; - } else { - MainLog.WriteLine ("Test run failed"); - success = false; - } + var runLog = Log.CreateAggregatedLog (testReporter.CallbackLog, MainLog); + testReporter.TimeoutWatch.Start (); + await testReporter.CollectDeviceResult (ProcessManager.ExecuteCommandAsync (harness.MlaunchPath, args, runLog, testReporter.Timeout, cancellation_token: testReporter.CancellationToken)); } finally { deviceLogCapturer.StopCapture (); deviceSystemLog.Dispose (); @@ -654,174 +443,9 @@ namespace Xharness { listener.Cancel (); listener.Dispose (); - // check the final status - var crashed = false; - if (File.Exists (listener_log.FullPath)) { - WrenchLog.WriteLine ("AddFile: {0}", listener_log.FullPath); - success = TestsSucceeded (AppInformation, listener_log.FullPath, timed_out, out crashed); - } else if (timed_out) { - WrenchLog.WriteLine ("AddSummary: {0} never launched
", runMode); - MainLog.WriteLine ("Test run never launched"); - success = false; - } else if (launch_failure) { - WrenchLog.WriteLine ("AddSummary: {0} failed to launch
", runMode); - MainLog.WriteLine ("Test run failed to launch"); - success = false; - } else { - WrenchLog.WriteLine ("AddSummary: {0} crashed at startup (no log)
", runMode); - MainLog.WriteLine ("Test run crashed before it started (no log file produced)"); - crashed = true; - success = false; - } - - if (!success.HasValue) - success = false; - - var crashLogWaitTime = 0; - if (!success.Value) - crashLogWaitTime = 5; - if (crashed) - crashLogWaitTime = 30; - - await crashReporter.EndCaptureAsync (TimeSpan.FromSeconds (crashLogWaitTime)); - - if (timed_out) { - Result = TestExecutingResult.TimedOut; - } else if (crashed) { - Result = TestExecutingResult.Crashed; - } else if (success.Value) { - Result = TestExecutingResult.Succeeded; - } else { - Result = TestExecutingResult.Failed; - } - - // Check crash reports to see if any of them explains why the test run crashed. - if (!success.Value) { - int pid = 0; - string crash_reason = null; - foreach (var crashLog in crashLogs) { - try { - Logs.Add (crashLog); - - if (pid == 0) { - // Find the pid - using (var log_reader = MainLog.GetReader ()) { - string line; - while ((line = log_reader.ReadLine ()) != null) { - const string str = "was launched with pid '"; - var idx = line.IndexOf (str, StringComparison.Ordinal); - if (idx > 0) { - idx += str.Length; - var next_idx = line.IndexOf ('\'', idx); - if (next_idx > idx) - int.TryParse (line.Substring (idx, next_idx - idx), out pid); - } - if (pid != 0) - break; - } - } - } - - using (var crash_reader = crashLog.GetReader ()) { - var text = crash_reader.ReadToEnd (); - - var reader = System.Runtime.Serialization.Json.JsonReaderWriterFactory.CreateJsonReader (Encoding.UTF8.GetBytes (text), new XmlDictionaryReaderQuotas ()); - var doc = new XmlDocument (); - doc.Load (reader); - foreach (XmlNode node in doc.SelectNodes ($"/root/processes/item[pid = '" + pid + "']")) { - Console.WriteLine (node?.InnerXml); - Console.WriteLine (node?.SelectSingleNode ("reason")?.InnerText); - crash_reason = node?.SelectSingleNode ("reason")?.InnerText; - } - } - if (crash_reason != null) { - // if in CI, do write an xml error that will be picked as a failure by VSTS - if (harness.InCI) { - resultParser.GenerateFailure (Logs, - "crash", - AppInformation.AppName, - variation, - $"App Crash {AppInformation.AppName} {variation}", - $"App crashed {crash_reason}.", - MainLog.FullPath, - harness.XmlJargon); - } - - break; - } - } catch (Exception e) { - harness.Log (2, "Failed to process crash report '{1}': {0}", e.Message, crashLog.Description); - } - } - if (!string.IsNullOrEmpty (crash_reason)) { - if (crash_reason == "per-process-limit") { - FailureMessage = "Killed due to using too much memory (per-process-limit)."; - } else { - FailureMessage = $"Killed by the OS ({crash_reason})"; - } - if (harness.InCI) { - resultParser.GenerateFailure ( - Logs, - "crash", - AppInformation.AppName, - variation, - $"App Crash {AppInformation.AppName} {variation}", - $"App crashed: {FailureMessage}", - MainLog.FullPath, - harness.XmlJargon); - } - } else if (launch_failure) { - // same as with a crash - FailureMessage = $"Launch failure"; - if (harness.InCI) { - resultParser.GenerateFailure ( - Logs, - "launch", - AppInformation.AppName, - variation, - $"App Launch {AppInformation.AppName} {variation} on {deviceName}", - $"{FailureMessage} on {deviceName}", - MainLog.FullPath, - XmlResultJargon.NUnitV3); - } - } else if (!isSimulator && crashed && string.IsNullOrEmpty (crash_reason) && harness.InCI) { - // this happens more that what we would like on devices, the main reason most of the time is that we have had netwoking problems and the - // tcp connection could not be stablished. We are going to report it as an error since we have not parsed the logs, evne when the app might have - // not crashed. We need to check the main_log to see if we do have an tcp issue or not - var isTcp = false; - using (var reader = new StreamReader (MainLog.FullPath)) { - string line; - while ((line = reader.ReadLine ()) != null) { - if (line.Contains ("Couldn't establish a TCP connection with any of the hostnames")) { - isTcp = true; - break; - } - } - } - - if (isTcp) { - resultParser.GenerateFailure (Logs, - "tcp-connection", - AppInformation.AppName, - variation, - $"TcpConnection on {deviceName}", - $"Device {deviceName} could not reach the host over tcp.", - MainLog.FullPath, - harness.XmlJargon); - } - } else if (timed_out && harness.InCI) { - resultParser.GenerateFailure (Logs, - "timeout", - AppInformation.AppName, - variation, - $"App Timeout {AppInformation.AppName} {variation} on bot {deviceName}", - $"{AppInformation.AppName} {variation} Test run timed out after {timeout.TotalMinutes} minute(s) on bot {deviceName}.", - MainLog.FullPath, - harness.XmlJargon); - } - } - - return success.Value ? 0 : 1; + // check the final status, copy all the required data + (Result, FailureMessage) = await testReporter.ParseResult (); + return testReporter.Success.Value ? 0 : 1; } public void AddDeviceName (IList args) diff --git a/tests/xharness/Harness.cs b/tests/xharness/Harness.cs index 8b2da9770b..3026f5694f 100644 --- a/tests/xharness/Harness.cs +++ b/tests/xharness/Harness.cs @@ -612,7 +612,7 @@ namespace Xharness new CrashSnapshotReporterFactory (ProcessManager, XcodeRoot, MlaunchPath), new CaptureLogFactory (), new DeviceLogCapturerFactory (ProcessManager, XcodeRoot, MlaunchPath), - new XmlResultParser (), + new TestReporterFactory (), target, this, HarnessLog, @@ -643,7 +643,7 @@ namespace Xharness new CrashSnapshotReporterFactory (ProcessManager, XcodeRoot, MlaunchPath), new CaptureLogFactory (), new DeviceLogCapturerFactory (ProcessManager, XcodeRoot, MlaunchPath), - new XmlResultParser (), + new TestReporterFactory (), target, this, HarnessLog, @@ -672,7 +672,7 @@ namespace Xharness new CrashSnapshotReporterFactory (ProcessManager, XcodeRoot, MlaunchPath), new CaptureLogFactory (), new DeviceLogCapturerFactory (ProcessManager, XcodeRoot, MlaunchPath), - new XmlResultParser (), + new TestReporterFactory (), target, this, HarnessLog, diff --git a/tests/xharness/IAppRunner.cs b/tests/xharness/IAppRunner.cs new file mode 100644 index 0000000000..c77e9205f2 --- /dev/null +++ b/tests/xharness/IAppRunner.cs @@ -0,0 +1,21 @@ +using System; +using Xharness.Execution; +using Xharness.Jenkins.TestTasks; +using Xharness.Logging; + +namespace Xharness { + // common interface that contains the basic info needed by the test result to be able to parse the results and + // log all the required data. + public interface IAppRunner { + AppBundleInformation AppInformation { get; } + BuildToolTask BuildTask { get; } + TimeSpan GetNewTimeout (); + double LaunchTimeout { get; } + IProcessManager ProcessManager { get; } + ILogs Logs { get; } + ILog MainLog { get; } + RunMode RunMode { get; } + XmlResultJargon XmlJargon { get; } + void LogException (int minLevel, string message, params object [] args); + } +} diff --git a/tests/xharness/ITestReporter.cs b/tests/xharness/ITestReporter.cs new file mode 100644 index 0000000000..4b0229d43f --- /dev/null +++ b/tests/xharness/ITestReporter.cs @@ -0,0 +1,36 @@ +using System; +using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; +using Xharness.Execution; +using Xharness.Listeners; +using Xharness.Logging; + +namespace Xharness { + + public interface ITestReporterFactory { + ITestReporter Create (IAppRunner appRunner, + string device, + ISimpleListener simpleListener, + ILog log, + ICrashSnapshotReporter crashReports, + IResultParser resultParser); + } + + // interface that represents a class that know how to parse the results from an app run. + public interface ITestReporter { + + TimeSpan Timeout { get; } + ILog CallbackLog { get; } + + bool? Success { get; } + Stopwatch TimeoutWatch { get; } + CancellationToken CancellationToken { get; } + + void LaunchCallback (Task launchResult); + + Task CollectSimulatorResult (Task processExecution); + Task CollectDeviceResult (Task processExecution); + Task<(TestExecutingResult ExecutingResult, string FailureMessage)> ParseResult (); + } +} diff --git a/tests/xharness/Jenkins/Resource.cs b/tests/xharness/Jenkins/Resource.cs index eefa59ba56..96ce94394e 100644 --- a/tests/xharness/Jenkins/Resource.cs +++ b/tests/xharness/Jenkins/Resource.cs @@ -11,7 +11,7 @@ namespace Xharness.Jenkins // make each connected device a separate resource, which will make it possible // to run tests in parallel across devices (and at the same time use the desktop // to build the next test project). - class Resource + public class Resource { public string Name; public string Description; @@ -91,7 +91,7 @@ namespace Xharness.Jenkins } } - interface IAcquiredResource : IDisposable + public interface IAcquiredResource : IDisposable { Resource Resource { get; } } diff --git a/tests/xharness/Jenkins/TestTasks/BuildToolTask.cs b/tests/xharness/Jenkins/TestTasks/BuildToolTask.cs index 4235157279..38e6bb41b9 100644 --- a/tests/xharness/Jenkins/TestTasks/BuildToolTask.cs +++ b/tests/xharness/Jenkins/TestTasks/BuildToolTask.cs @@ -4,7 +4,7 @@ using Xharness.Execution; namespace Xharness.Jenkins.TestTasks { - abstract class BuildToolTask : TestTask + public abstract class BuildToolTask : TestTask { public bool SpecifyPlatform = true; public bool SpecifyConfiguration = true; diff --git a/tests/xharness/Jenkins/TestTasks/RunDeviceTask.cs b/tests/xharness/Jenkins/TestTasks/RunDeviceTask.cs index 8ef9f5c74a..6a1c9c5ebf 100644 --- a/tests/xharness/Jenkins/TestTasks/RunDeviceTask.cs +++ b/tests/xharness/Jenkins/TestTasks/RunDeviceTask.cs @@ -89,7 +89,7 @@ namespace Xharness.Jenkins.TestTasks new CrashSnapshotReporterFactory (ProcessManager, Harness.XcodeRoot, Harness.MlaunchPath), new CaptureLogFactory (), new DeviceLogCapturerFactory (processManager, Harness.XcodeRoot, Harness.MlaunchPath), - new XmlResultParser (), + new TestReporterFactory (), AppRunnerTarget, Harness, projectFilePath: ProjectFile, @@ -156,7 +156,7 @@ namespace Xharness.Jenkins.TestTasks new CrashSnapshotReporterFactory (ProcessManager, Harness.XcodeRoot, Harness.MlaunchPath), new CaptureLogFactory (), new DeviceLogCapturerFactory (processManager, Harness.XcodeRoot, Harness.MlaunchPath), - new XmlResultParser (), + new TestReporterFactory (), AppRunnerTarget, Harness, projectFilePath: ProjectFile, diff --git a/tests/xharness/Jenkins/TestTasks/RunSimulatorTask.cs b/tests/xharness/Jenkins/TestTasks/RunSimulatorTask.cs index bf11ca8a83..c05441e05f 100644 --- a/tests/xharness/Jenkins/TestTasks/RunSimulatorTask.cs +++ b/tests/xharness/Jenkins/TestTasks/RunSimulatorTask.cs @@ -85,7 +85,7 @@ namespace Xharness.Jenkins.TestTasks new CrashSnapshotReporterFactory (ProcessManager, Harness.XcodeRoot, Harness.MlaunchPath), new CaptureLogFactory (), new DeviceLogCapturerFactory (processManager, Harness.XcodeRoot, Harness.MlaunchPath), - new XmlResultParser (), + new TestReporterFactory (), AppRunnerTarget, Harness, mainLog: Logs.Create ($"run-{Device.UDID}-{Timestamp}.log", "Run log"), diff --git a/tests/xharness/Jenkins/TestTasks/TestTask.cs b/tests/xharness/Jenkins/TestTasks/TestTask.cs index d0a4020d13..9330c75751 100644 --- a/tests/xharness/Jenkins/TestTasks/TestTask.cs +++ b/tests/xharness/Jenkins/TestTasks/TestTask.cs @@ -10,7 +10,7 @@ using Xharness.Utilities; namespace Xharness.Jenkins.TestTasks { - abstract class TestTask + public abstract class TestTask { static int counter; public readonly int ID = counter++; diff --git a/tests/xharness/Listeners/SimpleListener.cs b/tests/xharness/Listeners/SimpleListener.cs index 8081a46d4d..67bbdfbb28 100644 --- a/tests/xharness/Listeners/SimpleListener.cs +++ b/tests/xharness/Listeners/SimpleListener.cs @@ -10,6 +10,7 @@ namespace Xharness.Listeners Task CompletionTask { get; } Task ConnectedTask { get; } int Port { get; } + ILog TestLog { get; } void Cancel (); void Dispose (); @@ -21,7 +22,7 @@ namespace Xharness.Listeners { readonly TaskCompletionSource stopped = new TaskCompletionSource (); readonly TaskCompletionSource connected = new TaskCompletionSource (); - readonly ILog testLog; + public ILog TestLog { get; private set; } // TODO: This can be removed as it's commented out below string xml_data; @@ -40,17 +41,17 @@ namespace Xharness.Listeners protected SimpleListener (ILog log, ILog testLog, bool xmlOutput) { Log = log ?? throw new ArgumentNullException (nameof (log)); - this.testLog = testLog ?? throw new ArgumentNullException (nameof (testLog)); + this.TestLog = testLog ?? throw new ArgumentNullException (nameof (testLog)); XmlOutput = xmlOutput; } protected void Connected (string remote) { - Log.WriteLine ("Connection from {0} saving logs to {1}", remote, testLog.FullPath); + Log.WriteLine ("Connection from {0} saving logs to {1}", remote, TestLog.FullPath); connected.TrySetResult (true); if (OutputWriter == null) { - OutputWriter = testLog; + OutputWriter = TestLog; // a few extra bits of data only available from this side var local_data = $@"[Local Date/Time: {DateTime.Now}] diff --git a/tests/xharness/TestReporter.cs b/tests/xharness/TestReporter.cs new file mode 100644 index 0000000000..766678111a --- /dev/null +++ b/tests/xharness/TestReporter.cs @@ -0,0 +1,490 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Text; +using System.Threading; +using System.Threading.Tasks; +using System.Xml; +using System.Runtime.Serialization.Json; +using Xharness.Execution; +using Xharness.Listeners; +using Xharness.Logging; +using Xharness.Utilities; + +namespace Xharness { + + public class TestReporterFactory : ITestReporterFactory { + + public ITestReporter Create (IAppRunner appRunner, string device, ISimpleListener simpleListener, ILog log, ICrashSnapshotReporter crashReports, IResultParser parser) + => new TestReporter (appRunner, device, simpleListener, log, crashReports, parser); + } + + // main class that gets the result of an executed test application, parses the results and provides information + // about the success or failure of the execution. + public class TestReporter : ITestReporter { + + const string timeoutMessage = "Test run timed out after {0} minute(s)."; + const string completionMessage = "Test run completed"; + const string failureMessage = "Test run failed"; + + public TimeSpan Timeout { get; private set; } + public ILog CallbackLog { get; private set; } + + public bool? Success { get; private set; } + public Stopwatch TimeoutWatch { get; private set; } + public CancellationToken CancellationToken => cancellationTokenSource.Token; + + public bool ResultsUseXml => runner.XmlJargon != XmlResultJargon.Missing; + + readonly IAppRunner runner; + readonly ISimpleListener listener; + readonly ILogs crashLogs; + readonly ILog runLog; + readonly ICrashSnapshotReporter crashReporter; + readonly IResultParser resultParser; + readonly string deviceName; + bool waitedForExit = true; + bool launchFailure; + bool isSimulatorTest; + bool timedout; + + readonly CancellationTokenSource cancellationTokenSource = new CancellationTokenSource (); + + public TestReporter (IAppRunner appRunner, string device, ISimpleListener simpleListener, ILog log, ICrashSnapshotReporter crashReports, IResultParser parser) + { + runner = appRunner ?? throw new ArgumentNullException (nameof (appRunner)); + deviceName = device; // can be null on simulators + listener = simpleListener ?? throw new ArgumentNullException (nameof (simpleListener)); + runLog = log ?? throw new ArgumentNullException (nameof (log)); + crashLogs = new Logs (runner.Logs.Directory); + crashReporter = crashReports ?? throw new ArgumentNullException (nameof (crashReports)); + resultParser = parser ?? throw new ArgumentNullException (nameof (parser)); + Timeout = runner.GetNewTimeout (); + TimeoutWatch = new Stopwatch (); + CallbackLog = new CallbackLog ((line) => { + // MT1111: Application launched successfully, but it's not possible to wait for the app to exit as requested because it's not possible to detect app termination when launching using gdbserver + waitedForExit &= line?.Contains ("MT1111: ") != true; + if (line?.Contains ("error MT1007") == true) + launchFailure = true; + }); + } + + // parse the run log and decide if we managed to start the process or not + async Task<(int pid, bool launchFailure)> GetPidFromRunLog () { + (int pid, bool launchFailure) pidData = (-1, true); + using var reader = runLog.GetReader (); // diposed at the end of the method, which is what we want + if (reader.Peek () == -1) { + // empty file! we definetly had a launch error in this case + pidData.launchFailure = true; + } else { + while (!reader.EndOfStream) { + var line = await reader.ReadLineAsync (); + if (line.StartsWith ("Application launched. PID = ", StringComparison.Ordinal)) { + var pidstr = line.Substring ("Application launched. PID = ".Length); + if (!int.TryParse (pidstr, out pidData.pid)) + runner.MainLog.WriteLine ("Could not parse pid: {0}", pidstr); + } else if (line.Contains ("Xamarin.Hosting: Launched ") && line.Contains (" with pid ")) { + var pidstr = line.Substring (line.LastIndexOf (' ')); + if (!int.TryParse (pidstr, out pidData.pid)) + runner.MainLog.WriteLine ("Could not parse pid: {0}", pidstr); + } else if (line.Contains ("error MT1008")) { + pidData.launchFailure = true; + } + } + } + return pidData; + } + + // parse the main log to get the pid + async Task GetPidFromMainLog () + { + int pid = -1; + using var log_reader = runner.MainLog.GetReader (); // dispose when we leave the method, which is what we want + string line; + while ((line = await log_reader.ReadLineAsync ()) != null) { + const string str = "was launched with pid '"; + var idx = line.IndexOf (str, StringComparison.Ordinal); + if (idx > 0) { + idx += str.Length; + var next_idx = line.IndexOf ('\'', idx); + if (next_idx > idx) + int.TryParse (line.Substring (idx, next_idx - idx), out pid); + } + if (pid != -1) + return pid; + } + return pid; + } + + // return the reason for a crash found in a log + void GetCrashReason (int pid, ILog crashLog, out string crashReason) + { + crashReason = null; + using var crashReader = crashLog.GetReader (); // dispose when we leave the method + var text = crashReader.ReadToEnd (); + + var reader = JsonReaderWriterFactory.CreateJsonReader (Encoding.UTF8.GetBytes (text), new XmlDictionaryReaderQuotas ()); + var doc = new XmlDocument (); + doc.Load (reader); + foreach (XmlNode node in doc.SelectNodes ($"/root/processes/item[pid = '" + pid + "']")) { + Console.WriteLine (node?.InnerXml); + Console.WriteLine (node?.SelectSingleNode ("reason")?.InnerText); + crashReason = node?.SelectSingleNode ("reason")?.InnerText; + } + } + + // return if the tcp connection with the device failed + async Task TcpConnectionFailed () + { + using var reader = new StreamReader (runner.MainLog.FullPath); + string line; + while ((line = await reader.ReadLineAsync ()) != null) { + if (line.Contains ("Couldn't establish a TCP connection with any of the hostnames")) { + return true; + } + } + return false; + } + + // kill any process + Task KillAppProcess (int pid, CancellationTokenSource cancellationSource) { + var launchTimedout = cancellationSource.IsCancellationRequested; + var timeoutType = launchTimedout ? "Launch" : "Completion"; + var timeoutValue = launchTimedout ? runner.LaunchTimeout : Timeout.TotalSeconds; + + runner.MainLog.WriteLine ($"{timeoutType} timed out after {timeoutValue} seconds"); + return runner.ProcessManager.KillTreeAsync (pid, runner.MainLog, true); + } + + async Task CollectResult (Task processExecution) + { + // wait for the execution of the process, once that is done, perform all the parsing operations and + // leave a clean API to be used by AppRunner, hidding all the diff details + var result = await processExecution; + if (!waitedForExit && !result.TimedOut) { + // mlaunch couldn't wait for exit for some reason. Let's assume the app exits when the test listener completes. + runner.MainLog.WriteLine ("Waiting for listener to complete, since mlaunch won't tell."); + if (!await listener.CompletionTask.TimeoutAfter (Timeout - TimeoutWatch.Elapsed)) { + result.TimedOut = true; + } + } + + if (result.TimedOut) { + timedout = true; + Success = false; + runner.MainLog.WriteLine (timeoutMessage, Timeout.TotalMinutes); + } else if (result.Succeeded) { + runner.MainLog.WriteLine (completionMessage); + Success = true; + } else { + runner.MainLog.WriteLine (failureMessage); + Success = false; + } + } + + public void LaunchCallback (Task launchResult) + { + if (launchResult.IsFaulted) { + runner.MainLog.WriteLine ("Test launch failed: {0}", launchResult.Exception); + } else if (launchResult.IsCanceled) { + runner.MainLog.WriteLine ("Test launch was cancelled."); + } else if (launchResult.Result) { + runner.MainLog.WriteLine ("Test run started"); + } else { + cancellationTokenSource.Cancel (); + runner.MainLog.WriteLine ("Test launch timed out after {0} minute(s).", runner.LaunchTimeout); + timedout = true; + } + } + + public async Task CollectSimulatorResult (Task processExecution) + { + isSimulatorTest = true; + await CollectResult (processExecution); + + if (!Success.Value) { + var (pid, launchFailure) = await GetPidFromRunLog (); + this.launchFailure = launchFailure; + if (pid > 0) { + await KillAppProcess (pid, cancellationTokenSource); + } else { + runner.MainLog.WriteLine ("Could not find pid in mtouch output."); + } + } + } + + public async Task CollectDeviceResult (Task processExecution) + { + isSimulatorTest = false; + await CollectResult (processExecution); + } + + async Task<(string ResultLine, bool Failed)> GetResultLine (string logPath) + { + string resultLine = null; + bool failed = false; + using var reader = new StreamReader (logPath); + string line = null; + while ((line = await reader.ReadLineAsync ()) != null) { + if (line.Contains ("Tests run:")) { + Console.WriteLine (line); + resultLine = line; + break; + } else if (line.Contains ("[FAIL]")) { + Console.WriteLine (line); + failed = true; + } + } + return (ResultLine: resultLine, Failed: failed); + } + + async Task<(string resultLine, bool failed, bool crashed)> ParseResultFile (AppBundleInformation appInfo, string test_log_path, bool timed_out) + { + (string resultLine, bool failed, bool crashed) parseResult = (null, false, false); + if (!File.Exists (test_log_path)) { + parseResult.crashed = true; // if we do not have a log file, the test crashes + return parseResult; + } + // parsing the result is different if we are in jenkins or not. + // When in Jenkins, Touch.Unit produces an xml file instead of a console log (so that we can get better test reporting). + // However, for our own reporting, we still want the console-based log. This log is embedded inside the xml produced + // by Touch.Unit, so we need to extract it and write it to disk. We also need to re-save the xml output, since Touch.Unit + // wraps the NUnit xml output with additional information, which we need to unwrap so that Jenkins understands it. + // + // On the other hand, the nunit and xunit do not have that data and have to be parsed. + // + // This if statement has a small trick, we found out that internet sharing in some of the bots (VSTS) does not work, in + // that case, we cannot do a TCP connection to xharness to get the log, this is a problem since if we did not get the xml + // from the TCP connection, we are going to fail when trying to read it and not parse it. Therefore, we are not only + // going to check if we are in CI, but also if the listener_log is valid. + var path = Path.ChangeExtension (test_log_path, "xml"); + resultParser.CleanXml (test_log_path, path); + + if (ResultsUseXml && resultParser.IsValidXml (path, out var xmlType)) { + try { + var newFilename = resultParser.GetXmlFilePath (path, xmlType); + + // at this point, we have the test results, but we want to be able to have attachments in vsts, so if the format is + // the right one (NUnitV3) add the nodes. ATM only TouchUnit uses V3. + var testRunName = $"{appInfo.AppName} {appInfo.Variation}"; + if (xmlType == XmlResultJargon.NUnitV3) { + var logFiles = new List (); + // add our logs AND the logs of the previous task, which is the build task + logFiles.AddRange (Directory.GetFiles (runner.Logs.Directory)); + if (runner.BuildTask != null) // when using the run command, we do not have a build task, ergo, there are no logs to add. + logFiles.AddRange (Directory.GetFiles (runner.BuildTask.LogDirectory)); + // add the attachments and write in the new filename + // add a final prefix to the file name to make sure that the VSTS test uploaded just pick + // the final version, else we will upload tests more than once + newFilename = XmlResultParser.GetVSTSFilename (newFilename); + resultParser.UpdateMissingData (path, newFilename, testRunName, logFiles); + } else { + // rename the path to the correct value + File.Move (path, newFilename); + } + path = newFilename; + + // write the human readable results in a tmp file, which we later use to step on the logs + var tmpFile = Path.Combine (Path.GetTempPath (), Guid.NewGuid ().ToString ()); + (parseResult.resultLine, parseResult.failed) = resultParser.GenerateHumanReadableResults (path, tmpFile, xmlType); + File.Copy (tmpFile, test_log_path, true); + File.Delete (tmpFile); + + // we do not longer need the tmp file + runner.Logs.AddFile (path, LogType.XmlLog.ToString ()); + return parseResult; + + } catch (Exception e) { + runner.MainLog.WriteLine ("Could not parse xml result file: {0}", e); + // print file for better debugging + runner.MainLog.WriteLine ("File data is:"); + runner.MainLog.WriteLine (new string ('#', 10)); + using (var stream = new StreamReader (path)) { + string line; + while ((line = await stream.ReadLineAsync ()) != null) { + runner.MainLog.WriteLine (line); + } + } + runner.MainLog.WriteLine (new string ('#', 10)); + runner.MainLog.WriteLine ("End of xml results."); + if (timed_out) { + WrenchLog.WriteLine ($"AddSummary: {runner.RunMode} timed out
"); + return parseResult; + } else { + WrenchLog.WriteLine ($"AddSummary: {runner.RunMode} crashed
"); + runner.MainLog.WriteLine ("Test run crashed"); + parseResult.crashed = true; + return parseResult; + } + } + + } + // delete not needed copy + File.Delete (path); + + // not the most efficient way but this just happens when we run + // the tests locally and we usually do not run all tests, we are + // more interested to be efficent on the bots + (parseResult.resultLine, parseResult.failed) = await GetResultLine (test_log_path); + return parseResult; + } + + async Task<(bool Succeeded, bool Crashed)> TestsSucceeded (AppBundleInformation appInfo, string test_log_path, bool timed_out) + { + var (resultLine, failed, crashed) = await ParseResultFile (appInfo, test_log_path, timed_out); + // read the parsed logs in a human readable way + if (resultLine != null) { + var tests_run = resultLine.Replace ("Tests run: ", ""); + if (failed) { + WrenchLog.WriteLine ("AddSummary: {0} failed: {1}
", runner.RunMode, tests_run); + runner.MainLog.WriteLine ("Test run failed"); + return (false, crashed); + } else { + WrenchLog.WriteLine ("AddSummary: {0} succeeded: {1}
", runner.RunMode, tests_run); + runner.MainLog.WriteLine ("Test run succeeded"); + return (true, crashed); + } + } else if (timed_out) { + WrenchLog.WriteLine ("AddSummary: {0} timed out
", runner.RunMode); + return (false, false); + } else { + WrenchLog.WriteLine ("AddSummary: {0} crashed
", runner.RunMode); + runner.MainLog.WriteLine ("Test run crashed"); + return (false, true); + } + } + + // generate all the xml failures that will help the integration with the CI and return the failure reason + async Task GenerateXmlFailures (string failureMessage, bool crashed, string crashReason) + { + if (!ResultsUseXml) // nothing to do + return; + if (!string.IsNullOrEmpty (crashReason)) { + resultParser.GenerateFailure ( + runner.Logs, + "crash", + runner.AppInformation.AppName, + runner.AppInformation.Variation, + $"App Crash {runner.AppInformation.AppName} {runner.AppInformation.Variation}", + $"App crashed: {failureMessage}", + runner.MainLog.FullPath, + runner.XmlJargon); + } else if (launchFailure) { + resultParser.GenerateFailure ( + runner.Logs, + "launch", + runner.AppInformation.AppName, + runner.AppInformation.Variation, + $"App Launch {runner.AppInformation.AppName} {runner.AppInformation.Variation} on {deviceName}", + $"{failureMessage} on {deviceName}", + runner.MainLog.FullPath, + runner.XmlJargon); + } else if (!isSimulatorTest && crashed && string.IsNullOrEmpty (crashReason)) { + // this happens more that what we would like on devices, the main reason most of the time is that we have had netwoking problems and the + // tcp connection could not be stablished. We are going to report it as an error since we have not parsed the logs, evne when the app might have + // not crashed. We need to check the main_log to see if we do have an tcp issue or not + if (await TcpConnectionFailed ()) { + resultParser.GenerateFailure ( + runner.Logs, + "tcp-connection", + runner.AppInformation.AppName, + runner.AppInformation.Variation, + $"TcpConnection on {deviceName}", + $"Device {deviceName} could not reach the host over tcp.", + runner.MainLog.FullPath, + runner.XmlJargon); + } + } else if (timedout) { + resultParser.GenerateFailure ( + runner.Logs, + "timeout", + runner.AppInformation.AppName, + runner.AppInformation.Variation, + $"App Timeout {runner.AppInformation.AppName} {runner.AppInformation.Variation} on bot {deviceName}", + $"{runner.AppInformation.AppName} {runner.AppInformation.Variation} Test run timed out after {Timeout.TotalMinutes} minute(s) on bot {deviceName}.", + runner.MainLog.FullPath, + runner.XmlJargon); + } + } + + public async Task<(TestExecutingResult ExecutingResult, string FailureMessage)> ParseResult () + { + var result = (ExecutingResult: TestExecutingResult.Finished, FailureMessage: (string) null); + var crashed = false; + if (File.Exists (listener.TestLog.FullPath)) { + WrenchLog.WriteLine ("AddFile: {0}", listener.TestLog.FullPath); + (Success, crashed) = await TestsSucceeded (runner.AppInformation, listener.TestLog.FullPath, timedout); + } else if (timedout) { + WrenchLog.WriteLine ("AddSummary: {0} never launched
", runner.RunMode); + runner.MainLog.WriteLine ("Test run never launched"); + Success = false; + } else if (launchFailure) { + WrenchLog.WriteLine ("AddSummary: {0} failed to launch
", runner.RunMode); + runner.MainLog.WriteLine ("Test run failed to launch"); + Success = false; + } else { + WrenchLog.WriteLine ("AddSummary: {0} crashed at startup (no log)
", runner.RunMode); + runner.MainLog.WriteLine ("Test run crashed before it started (no log file produced)"); + crashed = true; + Success = false; + } + + if (!Success.HasValue) + Success = false; + + var crashLogWaitTime = 0; + if (!Success.Value) + crashLogWaitTime = 5; + if (crashed) + crashLogWaitTime = 30; + + await crashReporter.EndCaptureAsync (TimeSpan.FromSeconds (crashLogWaitTime)); + + if (timedout) { + result.ExecutingResult = TestExecutingResult.TimedOut; + } else if (crashed) { + result.ExecutingResult = TestExecutingResult.Crashed; + } else if (Success.Value) { + result.ExecutingResult = TestExecutingResult.Succeeded; + } else { + result.ExecutingResult = TestExecutingResult.Failed; + } + + // Check crash reports to see if any of them explains why the test run crashed. + if (!Success.Value) { + int pid = -1; + string crashReason = null; + foreach (var crashLog in crashLogs) { + try { + runner.Logs.Add (crashLog); + + if (pid == -1) { + // Find the pid + pid = await GetPidFromMainLog (); + } + + GetCrashReason (pid, crashLog, out crashReason); + if (crashReason != null) + break; + } catch (Exception e) { + runner.LogException (2, "Failed to process crash report '{1}': {0}", e.Message, crashLog.Description); + } + } + if (!string.IsNullOrEmpty (crashReason)) { + if (crashReason == "per-process-limit") { + result.FailureMessage = "Killed due to using too much memory (per-process-limit)."; + } else { + result.FailureMessage = $"Killed by the OS ({crashReason})"; + } + } else if (launchFailure) { + // same as with a crash + result.FailureMessage = $"Launch failure"; + } + await GenerateXmlFailures (result.FailureMessage, crashed, crashReason); + } + return result; + } + + } +} diff --git a/tests/xharness/Xharness.Tests/Samples/NUnitV3SampleFailure.xml b/tests/xharness/Xharness.Tests/Samples/NUnitV3SampleFailure.xml new file mode 100644 index 0000000000..bf83ae78c0 --- /dev/null +++ b/tests/xharness/Xharness.Tests/Samples/NUnitV3SampleFailure.xml @@ -0,0 +1,61 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/tests/xharness/Xharness.Tests/Samples/NUnitV3SampleSuccess.xml b/tests/xharness/Xharness.Tests/Samples/NUnitV3SampleSuccess.xml new file mode 100644 index 0000000000..79714282cb --- /dev/null +++ b/tests/xharness/Xharness.Tests/Samples/NUnitV3SampleSuccess.xml @@ -0,0 +1,33 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/tests/xharness/Xharness.Tests/Samples/run-log.txt b/tests/xharness/Xharness.Tests/Samples/run-log.txt new file mode 100644 index 0000000000..cfdfe2a29b --- /dev/null +++ b/tests/xharness/Xharness.Tests/Samples/run-log.txt @@ -0,0 +1,47 @@ +14:48:45.0272010 Test log server listening on: 0.0.0.0:49987 +14:48:45.0308310 System log for the 'iPhone X (iOS 13.3) - created by xharness' simulator is: /Users/mandel/Library/Logs/CoreSimulator/96EBF3D8-393E-4166-B1AF-4A3BDEAC5021/system.log +14:48:45.0314300 *** Executing com.xamarin.bcltests.mscorlib Part 1/Classic in the simulator *** +14:48:45.0328640 Starting test run +14:48:45.0332180 /Users/mandel/Xamarin/xamarin-macios/master/xamarin-macios/_ios-build/Library/Frameworks/Xamarin.iOS.framework/Versions/Current/bin/mlaunch --sdkroot /Applications/Xcode113.app -v -argument=-connection-mode -argument=none -argument=-app-arg:-autostart -setenv=NUNIT_AUTOSTART=true -argument=-app-arg:-autoexit -setenv=NUNIT_AUTOEXIT=true -argument=-app-arg:-enablenetwork -setenv=NUNIT_ENABLE_NETWORK=true -argument=-app-arg:-hostname:127.0.0.1 -setenv=NUNIT_HOSTNAME=127.0.0.1 -argument=-app-arg:-transport:Tcp -setenv=NUNIT_TRANSPORT=TCP -argument=-app-arg:-hostport:49987 -setenv=NUNIT_HOSTPORT=49987 --launchsim "/Users/mandel/Xamarin/xamarin-macios/master/xamarin-macios/tests/xharness/tmp-test-dir/mscorlib Part 1/bin/mscorlib Part 1/iPhoneSimulator/Debug-unified/com.xamarin.bcltests.mscorlib Part 1.app" --stdout=/dev/ttys000 --stderr=/dev/ttys000 --device=:v2:udid=96EBF3D8-393E-4166-B1AF-4A3BDEAC5021 +14:48:45.2834160 Using Xcode 11.3 found in /Applications/Xcode113.app +14:48:45.2865790 Xamarin.Hosting: Xamarin.Hosting +14:48:45.2867370 Xamarin.Hosting: Version: cec1cba137 (master) +14:48:45.2867590 Xamarin.Hosting: Xcode: /Applications/Xcode113.app +14:48:45.2886960 Xamarin.Hosting: Xcode Version: 11.3 +14:48:45.2892130 Xamarin.Hosting: Verbosity: 11 +14:48:45.2987220 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTFoundation.framework/Versions/A/DVTFoundation +14:48:45.3024060 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTiPhoneSimulatorRemoteClient.framework/DVTiPhoneSimulatorRemoteClient +14:48:45.3024840 Xamarin.Hosting: Loaded /Library/Developer/PrivateFrameworks/CoreSimulator.framework/CoreSimulator +14:48:45.3026130 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DTDeviceKitBase.framework/DTDeviceKitBase +14:48:45.3154170 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTKit.framework/DVTKit +14:48:45.3159370 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DTDeviceKit.framework/DTDeviceKit +14:48:45.3160450 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DTXConnectionServices.framework/DTXConnectionServices +14:48:45.3167760 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTSourceControl.framework/DVTSourceControl +14:48:45.3168970 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTServices.framework/DVTServices +14:48:45.3170070 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTPortal.framework/DVTPortal +14:48:45.3236970 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTDocumentation.framework/DVTDocumentation +14:48:45.3244800 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTAnalyticsClient.framework/DVTAnalyticsClient +14:48:45.3254630 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/DVTAnalytics.framework/DVTAnalytics +14:48:45.3273940 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/SourceKit.framework/SourceKit +14:48:45.3451120 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/Frameworks/IDEFoundation.framework/IDEFoundation +14:48:45.3459620 Xamarin.Hosting: Loaded /Applications/Xcode113.app/Contents/SharedFrameworks/IDEProducts.framework/IDEProducts +14:48:45.4904370 Xamarin.Hosting: Simulator watchdogs are already disabled for 'iOS 13.3 (17C45) - iPhone X'. +14:48:45.5001330 Xamarin.Hosting: Launching simulator application 'com.apple.iphonesimulator' +14:48:45.8284390 Xamarin.Hosting: Ready notification 'com.apple.iphonesimulator.ready' received from the simulator. +14:48:45.8317100 Xamarin.Hosting: Booting iPhone X (iOS 13.3) - created by xharness... +14:48:46.4418970 Xamarin.Hosting: Booted iPhone X (iOS 13.3) - created by xharness successfully. +14:48:46.4461820 Copying in /Users/mandel/Xamarin/xamarin-macios/master/xamarin-macios/tests/xharness/tmp-test-dir/mscorlib Part 1/bin/mscorlib Part 1/iPhoneSimulator/Debug-unified/com.xamarin.bcltests.mscorlib Part 1.app/.monotouch-64 +14:48:48.1443990 Xamarin.Hosting: No need to boot (already booted): iPhone X (iOS 13.3) - created by xharness +14:48:48.1459630 Xamarin.Hosting: Installing /Users/mandel/Xamarin/xamarin-macios/master/xamarin-macios/tests/xharness/tmp-test-dir/mscorlib Part 1/bin/mscorlib Part 1/iPhoneSimulator/Debug-unified/com.xamarin.bcltests.mscorlib Part 1.app with Bundle Identifier com.xamarin.bcltests.mscorlib Part 1 on 'iOS 13.3 (17C45) - iPhone X'... +14:49:25.8788620 Xamarin.Hosting: Installed 'com.xamarin.bcltests.mscorlib Part 1' from /Users/mandel/Xamarin/xamarin-macios/master/xamarin-macios/tests/xharness/tmp-test-dir/mscorlib Part 1/bin/mscorlib Part 1/iPhoneSimulator/Debug-unified/com.xamarin.bcltests.mscorlib Part 1.app +14:49:26.6020030 Xamarin.Hosting: Could not find any potentially troublesome weak load commands. +14:49:26.7037460 Xamarin.Hosting: The bundle id com.xamarin.bcltests.mscorlib Part 1 was successfully installed. +14:49:26.7087350 Xamarin.Hosting: Launching com.xamarin.bcltests.mscorlib Part 1 on 'iOS 13.3 (17C45) - iPhone X' +14:49:26.7808590 Xamarin.Hosting: Launched com.xamarin.bcltests.mscorlib Part 1 with pid 94797 +14:49:26.7861460 Xamarin.Hosting: Device 'iOS 13.3 (17C45) - iPhone X' booted. +14:49:31.0250650 Connection from 127.0.0.1:53085 saving logs to /Users/mandel/Xamarin/xamarin-macios/master/xamarin-macios/jenkins-results/tests/20200320_144720/mscorlib Part 1/122/test-classic-20200320_144845.log +14:49:31.0257860 Test run started +14:50:01.4773140 Tests have finished executing +14:50:01.7897340 Xamarin.Hosting: Simulated process has exited. +14:50:02.0809610 Test run completed +14:50:02.1691940 Test run succeeded \ No newline at end of file diff --git a/tests/xharness/Xharness.Tests/Tests/AppRunnerTests.cs b/tests/xharness/Xharness.Tests/Tests/AppRunnerTests.cs index d515b2de37..eaf5dc03ee 100644 --- a/tests/xharness/Xharness.Tests/Tests/AppRunnerTests.cs +++ b/tests/xharness/Xharness.Tests/Tests/AppRunnerTests.cs @@ -125,7 +125,7 @@ namespace Xharness.Tests { snapshotReporterFactory, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Simulator_iOS64, Mock.Of (), mainLog.Object, @@ -150,7 +150,7 @@ namespace Xharness.Tests { snapshotReporterFactory, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Simulator_iOS64, Mock.Of (), mainLog.Object, @@ -174,7 +174,7 @@ namespace Xharness.Tests { snapshotReporterFactory, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Simulator_iOS64, Mock.Of (), mainLog.Object, @@ -198,7 +198,7 @@ namespace Xharness.Tests { snapshotReporterFactory, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Device_iOS, Mock.Of (), mainLog.Object, @@ -231,7 +231,7 @@ namespace Xharness.Tests { snapshotReporterFactory, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Device_iOS, harness, mainLog.Object, @@ -285,7 +285,7 @@ namespace Xharness.Tests { snapshotReporterFactory, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Device_iOS, harness, mainLog.Object, @@ -359,6 +359,20 @@ namespace Xharness.Tests { true, It.IsAny ())) .Returns (captureLog.Object); + var testReporterFactory = new Mock (); + var testReporter = new Mock (); + testReporterFactory.Setup (f => f.Create ( + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny ())).Returns (testReporter.Object); + testReporter.Setup (r => r.TimeoutWatch).Returns (new System.Diagnostics.Stopwatch ()); + testReporter.Setup (r => r.ParseResult ()).Returns (() => { + return Task.FromResult<(TestExecutingResult, string)> ((TestExecutingResult.Succeeded, null)); + }); + testReporter.Setup (r => r.Success).Returns (true); // Act var appRunner = new AppRunner (processManager.Object, @@ -369,7 +383,7 @@ namespace Xharness.Tests { crashReporterFactory.Object, captureLogFactory.Object, Mock.Of (), - Mock.Of (), + testReporterFactory.Object, TestTarget.Simulator_tvOS, GetMockedHarness (), mainLog.Object, @@ -464,10 +478,21 @@ namespace Xharness.Tests { .ReturnsAsync (new ProcessExecutionResult () { ExitCode = 0 }); var xmlResultFile = Path.ChangeExtension (testResultFilePath, "xml"); - var resultParser = new Mock (); - resultParser - .Setup (x => x.CleanXml (testResultFilePath, xmlResultFile)) - .Callback (() => File.Copy (testResultFilePath, xmlResultFile)); + var testReporterFactory = new Mock (); + var testReporter = new Mock (); + testReporterFactory.Setup (f => f.Create ( + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny ())).Returns (testReporter.Object); + testReporter.Setup (r => r.Timeout).Returns (TimeSpan.FromMinutes (harness.Timeout * 2)); + testReporter.Setup (r => r.TimeoutWatch).Returns (new System.Diagnostics.Stopwatch ()); + testReporter.Setup (r => r.ParseResult ()).Returns (() => { + return Task.FromResult<(TestExecutingResult, string)> ((TestExecutingResult.Succeeded, null)); + }); + testReporter.Setup (r => r.Success).Returns (true); // Act var appRunner = new AppRunner (processManager.Object, @@ -478,7 +503,7 @@ namespace Xharness.Tests { crashReporterFactory.Object, captureLogFactory.Object, Mock.Of (), // Use for devices only - resultParser.Object, + testReporterFactory.Object, TestTarget.Simulator_iOS64, harness, mainLog.Object, @@ -493,10 +518,6 @@ namespace Xharness.Tests { // Verify Assert.AreEqual (0, result); - mainLog.Verify (x => x.WriteLine ("Test run started")); - mainLog.Verify (x => x.WriteLine ("Test run completed")); - mainLog.Verify (x => x.WriteLine ("Test run succeeded")); - simpleListener.Verify (x => x.Initialize (), Times.AtLeastOnce); simpleListener.Verify (x => x.StartAsync (), Times.AtLeastOnce); simpleListener.Verify (x => x.Cancel (), Times.AtLeastOnce); @@ -510,8 +531,6 @@ namespace Xharness.Tests { // When ensureCleanSimulatorState == true simulator.Verify (x => x.PrepareSimulatorAsync (mainLog.Object, appName)); simulator.Verify (x => x.KillEverythingAsync (mainLog.Object)); - - resultParser.VerifyAll (); } [Test] @@ -542,7 +561,7 @@ namespace Xharness.Tests { crashReporterFactory.Object, Mock.Of (), Mock.Of (), - Mock.Of (), + Mock.Of (), TestTarget.Device_tvOS, GetMockedHarness (), mainLog.Object, @@ -620,10 +639,21 @@ namespace Xharness.Tests { .ReturnsAsync (new ProcessExecutionResult () { ExitCode = 0 }); var xmlResultFile = Path.ChangeExtension (testResultFilePath, "xml"); - var resultParser = new Mock (); - resultParser - .Setup (x => x.CleanXml (testResultFilePath, xmlResultFile)) - .Callback (() => File.Copy (testResultFilePath, xmlResultFile)); + var testReporterFactory = new Mock (); + var testReporter = new Mock (); + testReporterFactory.Setup (f => f.Create ( + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny ())).Returns (testReporter.Object); + testReporter.Setup (r => r.Timeout).Returns (TimeSpan.FromMinutes (harness.Timeout * 2)); + testReporter.Setup (r => r.TimeoutWatch).Returns (new System.Diagnostics.Stopwatch ()); + testReporter.Setup (r => r.ParseResult ()).Returns (() => { + return Task.FromResult<(TestExecutingResult, string)> ((TestExecutingResult.Succeeded, null)); + }); + testReporter.Setup (r => r.Success).Returns (true); // Act var appRunner = new AppRunner (processManager.Object, @@ -634,7 +664,7 @@ namespace Xharness.Tests { crashReporterFactory.Object, Mock.Of (), // Used for simulators only deviceLogCapturerFactory.Object, - resultParser.Object, + testReporterFactory.Object, TestTarget.Device_iOS, harness, mainLog.Object, @@ -650,10 +680,6 @@ namespace Xharness.Tests { processManager.VerifyAll (); - mainLog.Verify (x => x.WriteLine ("Test run started")); - mainLog.Verify (x => x.WriteLine ("Test run completed")); - mainLog.Verify (x => x.WriteLine ("Test run succeeded")); - simpleListener.Verify (x => x.Initialize (), Times.AtLeastOnce); simpleListener.Verify (x => x.StartAsync (), Times.AtLeastOnce); simpleListener.Verify (x => x.Cancel (), Times.AtLeastOnce); @@ -729,10 +755,21 @@ namespace Xharness.Tests { .ReturnsAsync (new ProcessExecutionResult () { ExitCode = 0 }); var xmlResultFile = Path.ChangeExtension (testResultFilePath, "xml"); - var resultParser = new Mock (); - resultParser - .Setup (x => x.CleanXml (testResultFilePath, xmlResultFile)) - .Callback (() => File.Copy (testResultFilePath, xmlResultFile)); + var testReporterFactory = new Mock (); + var testReporter = new Mock (); + testReporterFactory.Setup (f => f.Create ( + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny (), + It.IsAny ())).Returns (testReporter.Object); + testReporter.Setup (r => r.Timeout).Returns (TimeSpan.FromMinutes (harness.Timeout * 2)); + testReporter.Setup (r => r.TimeoutWatch).Returns (new System.Diagnostics.Stopwatch ()); + testReporter.Setup (r => r.ParseResult ()).Returns (() => { + return Task.FromResult<(TestExecutingResult, string)> ((TestExecutingResult.Failed, null)); + }); + testReporter.Setup (r => r.Success).Returns (false); // Act var appRunner = new AppRunner (processManager.Object, @@ -743,7 +780,7 @@ namespace Xharness.Tests { crashReporterFactory.Object, Mock.Of (), // Used for simulators only deviceLogCapturerFactory.Object, - resultParser.Object, + testReporterFactory.Object, TestTarget.Device_iOS, harness, mainLog.Object, @@ -759,10 +796,6 @@ namespace Xharness.Tests { processManager.VerifyAll (); - mainLog.Verify (x => x.WriteLine ("Test run started")); - mainLog.Verify (x => x.WriteLine ("Test run completed")); - mainLog.Verify (x => x.WriteLine ("Test run failed")); - simpleListener.Verify (x => x.Initialize (), Times.AtLeastOnce); simpleListener.Verify (x => x.StartAsync (), Times.AtLeastOnce); simpleListener.Verify (x => x.Cancel (), Times.AtLeastOnce); diff --git a/tests/xharness/Xharness.Tests/Tests/TestReporterTests.cs b/tests/xharness/Xharness.Tests/Tests/TestReporterTests.cs new file mode 100644 index 0000000000..bed662324e --- /dev/null +++ b/tests/xharness/Xharness.Tests/Tests/TestReporterTests.cs @@ -0,0 +1,334 @@ +using System; +using System.IO; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Moq; +using NUnit.Framework; +using Xharness.Execution; +using Xharness.Listeners; +using Xharness.Logging; + +namespace Xharness.Tests.Tests { + + [TestFixture] + public class TestReporterTests { + + Mock runner; + Mock crashReporter; + Mock processManager; + IResultParser parser; + Mock runLog; + Mock mainLog; + Mock logs; + Mock listener; + AppBundleInformation appInformation; + string deviceName = "Device Name"; + string logsDirectory; + + [SetUp] + public void SetUp () + { + runner = new Mock (); + crashReporter = new Mock (); + processManager = new Mock (); + parser = new XmlResultParser (); + runLog = new Mock (); + mainLog = new Mock (); + logs = new Mock (); + listener = new Mock (); + appInformation = new AppBundleInformation ("test app", "my.id.com", "/path/to/app", "/launch/app/path", null) { Variation = "Debug" }; + logsDirectory = Path.GetTempFileName (); + File.Delete (logsDirectory); + Directory.CreateDirectory (logsDirectory); + } + + [TearDown] + public void TearDown () + { + runner = null; + processManager = null; + runLog = null; + mainLog = null; + listener = null; + if (Directory.Exists (logsDirectory)) + Directory.Delete (logsDirectory, true); + } + + Stream GetRunLogSample () + { + var name = GetType ().Assembly.GetManifestResourceNames ().Where (a => a.EndsWith ("run-log.txt", StringComparison.Ordinal)).FirstOrDefault (); + return GetType ().Assembly.GetManifestResourceStream (name); + } + + TestReporter BuildTestResult () + { + runner.Setup (r => r.Logs).Returns (logs.Object); + runner.Setup (r => r.MainLog).Returns (mainLog.Object); + runner.Setup (r => r.AppInformation).Returns (appInformation); + runner.Setup (r => r.XmlJargon).Returns (XmlResultJargon.NUnitV3); + runner.Setup (r => r.ProcessManager).Returns (processManager.Object); + logs.Setup (l => l.Directory).Returns (logsDirectory); + return new TestReporter (runner.Object, deviceName, listener.Object, runLog.Object, crashReporter.Object, parser); + } + + [Test] + public async Task CollectSimulatorResultsSucess () + { + // set the listener to return a task that we are not going to complete + var cancellationTokenSource = new CancellationTokenSource (); + var tcs = new TaskCompletionSource (); + listener.Setup (l => l.CompletionTask).Returns (tcs.Task); // will never be set to be completed + + // ensure that we do provide the required runlog information so that we know if it was a launch failure or not, we are + // not dealing with the launch faliure + runLog.Setup (l => l.GetReader ()).Returns (new StreamReader (GetRunLogSample ())); + + var testResult = BuildTestResult (); + var processResult = Task.FromResult (new ProcessExecutionResult () { TimedOut = false, ExitCode = 0 }); + await testResult.CollectSimulatorResult (processResult); + // we should have timeout, since the task completion source was never set + Assert.IsTrue (testResult.Success, "success"); + + processManager.Verify (p => p.KillTreeAsync (It.IsAny (), It.IsAny (), true), Times.Never); + } + + // we need to make sure that we take into account the case in which we do have data, but no PID and an empty file + // which is a catastrophic launch error + [TestCase ("Some Data")] + [TestCase (null)] + public async Task CollectSimulatorResultsLaunchFailureTest (string runLogData) + { + // similar to the above test, but in this case we ware going to fake a launch issue, that is, the runlog + // does not contain a PID that we can parse and later try to kill. + + // set the listener to return a task that we are not going to complete + var cancellationTokenSource = new CancellationTokenSource (); + var tcs = new TaskCompletionSource (); + listener.Setup (l => l.CompletionTask).Returns (tcs.Task); // will never be set to be completed + + // empty test file to be returned as the runlog stream + var tmpFile = Path.GetTempFileName (); + if (!string.IsNullOrEmpty (runLogData)) { + using (var writer = new StreamWriter (tmpFile)) { + writer.Write (runLogData); + } + } + + // ensure that we do provide the required runlog information so that we know if it was a launch failure or not, we are + // not dealing with the launch faliure + runLog.Setup (l => l.GetReader ()).Returns (new StreamReader (File.Create (tmpFile))); + + var testResult = BuildTestResult (); + var processResult = Task.FromResult (new ProcessExecutionResult () { TimedOut = true, ExitCode = 0 }); + await testResult.CollectSimulatorResult (processResult); + // we should have timeout, since the task completion source was never set + Assert.IsFalse (testResult.Success, "success"); + + // verify that we do not try to kill a process that never got started + processManager.Verify (p => p.KillTreeAsync (It.IsAny (), It.IsAny (), true), Times.Never); + File.Delete (tmpFile); + } + + + [TestCase (0)] + [TestCase (1)] + public async Task CollectSimulatorResultsSuccessLaunchTest (int processExitCode) + { + // fake the best case scenario, we got the process to exit correctly + var cancellationTokenSource = new CancellationTokenSource (); + var tcs = new TaskCompletionSource (); + var processResult = Task.FromResult (new ProcessExecutionResult () { TimedOut = false, ExitCode = processExitCode }); + + // ensure we do not consider it to be a launch failure + runLog.Setup (l => l.GetReader ()).Returns (new StreamReader (GetRunLogSample ())); + + var testResult = BuildTestResult (); + await testResult.CollectSimulatorResult (processResult); + + // we should have timeout, since the task completion source was never set + if (processExitCode != 0) + Assert.IsFalse (testResult.Success, "success"); + else + Assert.IsTrue (testResult.Success, "success"); + + if (processExitCode != 0) + processManager.Verify (p => p.KillTreeAsync (It.IsAny (), It.IsAny (), true), Times.Once); + else + // verify that we do not try to kill a process that never got started + processManager.Verify (p => p.KillTreeAsync (It.IsAny (), It.IsAny (), true), Times.Never); + } + + [Test] + public async Task CollectDeviceResultTimeoutTest () + { + // set the listener to return a task that we are not going to complete + var tcs = new TaskCompletionSource (); + listener.Setup (l => l.CompletionTask).Returns (tcs.Task); // will never be set to be completed + + // ensure that we do provide the required runlog information so that we know if it was a launch failure or not, we are + // not dealing with the launch faliure + runLog.Setup (l => l.GetReader ()).Returns (new StreamReader (GetRunLogSample ())); + + var testResult = BuildTestResult (); + var processResult = Task.FromResult (new ProcessExecutionResult () { TimedOut = true, ExitCode = 0 }); + await testResult.CollectDeviceResult (processResult); + // we should have timeout, since the task completion source was never set + Assert.IsFalse (testResult.Success, "success"); + } + + [TestCase (0)] + [TestCase (1)] + public async Task CollectDeviceResultSuccessTest (int processExitCode) + { + // fake the best case scenario, we got the process to exit correctly + var processResult = Task.FromResult (new ProcessExecutionResult () { TimedOut = false, ExitCode = processExitCode }); + + // ensure we do not consider it to be a launch failure + runLog.Setup (l => l.GetReader ()).Returns (new StreamReader (GetRunLogSample ())); + + var testResult = BuildTestResult (); + await testResult.CollectDeviceResult (processResult); + + // we should have timeout, since the task completion source was never set + if (processExitCode != 0) + Assert.IsFalse (testResult.Success, "success"); + else + Assert.IsTrue (testResult.Success, "success"); + } + + [Test] + public void LaunchCallbackFaultedTest () + { + var testResult = BuildTestResult (); + var t = Task.FromException (new Exception ("test")); + testResult.LaunchCallback (t); + // verify that we did report the launch proble + mainLog.Verify (l => l.WriteLine ( + It.Is (s => s.StartsWith ($"Test launch failed:")), It.IsAny ()), Times.Once); + } + + [Test] + public void LaunchCallbackCanceledTest () + { + var testResult = BuildTestResult (); + var tcs = new TaskCompletionSource (); + tcs.TrySetCanceled (); + testResult.LaunchCallback (tcs.Task); + // verify we notify that the execution was canceled + mainLog.Verify (l => l.WriteLine (It.Is (s => s.Equals ("Test launch was cancelled."))), Times.Once); + } + + [Test] + public void LaunchCallbackSuccessTest () + { + var testResult = BuildTestResult (); + var t = Task.FromResult (true); + testResult.LaunchCallback (t); + mainLog.Verify (l => l.WriteLine (It.Is (s => s.Equals ("Test run started"))), Times.Once); + } + + // copy the sample data to a given tmp file + string CreateSampleFile (string resourceName) + { + var name = GetType ().Assembly.GetManifestResourceNames ().Where (a => a.EndsWith (resourceName, StringComparison.Ordinal)).FirstOrDefault (); + var tempPath = Path.GetTempFileName (); + using var outputStream = new StreamWriter (tempPath); + using var sampleStream = new StreamReader (GetType ().Assembly.GetManifestResourceStream (name)); + string line; + while ((line = sampleStream.ReadLine ()) != null) + outputStream.WriteLine (line); + return tempPath; + } + + [Test] + public async Task ParseResultFailingTestsTest () + { + var sample = CreateSampleFile ("NUnitV3SampleFailure.xml"); + var listenerLog = new Mock (); + listener.Setup (l => l.TestLog).Returns (listenerLog.Object); + listenerLog.Setup (l => l.FullPath).Returns (sample); + runner.Setup (r => r.AppInformation).Returns (appInformation); + + var testResult = BuildTestResult (); + var (result, failure) = await testResult.ParseResult (); + Assert.AreEqual (TestExecutingResult.Failed, result, "execution result"); + Assert.IsNull (failure, "failure message"); + + // ensure that we do call the crash reporter end capture but with 0, since it was a success + crashReporter.Verify (c => c.EndCaptureAsync (It.Is (t => t.TotalSeconds == 5)), Times.Once); + } + + [Test] + public async Task ParseResultSuccessTestsTest () + { + // get a file with a success result so that we can return it as part of the listener log + var sample = CreateSampleFile ("NUnitV3SampleSuccess.xml"); + var listenerLog = new Mock (); + listener.Setup (l => l.TestLog).Returns (listenerLog.Object); + listenerLog.Setup (l => l.FullPath).Returns (sample); + runner.Setup (r => r.AppInformation).Returns (appInformation); + + var testResult = BuildTestResult (); + var (result, failure) = await testResult.ParseResult (); + Assert.AreEqual (TestExecutingResult.Succeeded, result, "execution result"); + Assert.IsNull (failure, "failure message"); + + // ensure that we do call the crash reporter end capture but with 0, since it was a success + crashReporter.Verify (c => c.EndCaptureAsync (It.Is (t => t.TotalSeconds == 0)), Times.Once); + } + + [Test] + public async Task ParseResultTimeoutTestsTest () + { + // more complicated test, we need to fake a process timeout, then ensure that the result is the expected one + var tcs = new TaskCompletionSource (); + listener.Setup (l => l.CompletionTask).Returns (tcs.Task); // will never be set to be completed + + var listenerLog = new Mock (); + listener.Setup (l => l.TestLog).Returns (listenerLog.Object); + listenerLog.Setup (l => l.FullPath).Returns ("/my/missing/path"); + + // ensure that we do provide the required runlog information so that we know if it was a launch failure or not, we are + // not dealing with the launch faliure + runLog.Setup (l => l.GetReader ()).Returns (new StreamReader (GetRunLogSample ())); + + var failurePath = Path.Combine (logsDirectory, "my-failure.xml"); + var failureLog = new Mock (); + failureLog.Setup (l => l.FullPath).Returns (failurePath); + logs.Setup (l => l.Create (It.IsAny (), It.IsAny (), null)).Returns (failureLog.Object); + + // create some data for the stderr + var stderr = Path.GetTempFileName (); + using (var stream = File.Create (stderr)) + using (var writer = new StreamWriter (stream)) { + await writer.WriteAsync ("Some data to be added to stderr of the failure"); + } + mainLog.Setup (l => l.FullPath).Returns (stderr); + + var testResult = BuildTestResult (); + var processResult = Task.FromResult (new ProcessExecutionResult () { TimedOut = true, ExitCode = 0 }); + await testResult.CollectDeviceResult (processResult); + // we should have timeout, since the task completion source was never set + var (result, failure) = await testResult.ParseResult (); + Assert.IsFalse (testResult.Success, "success"); + + // verify that we state that there was a timeout + mainLog.Verify (l => l.WriteLine (It.Is (s => s.Equals ("Test run never launched"))), Times.Once); + // assert that the timeout failure was created. + Assert.IsTrue (File.Exists (failurePath), "failure path"); + var isTimeoutFailure = false; + using (var reader = new StreamReader (failurePath)) { + string line = null; + while ((line = await reader.ReadLineAsync ()) != null) { + if (line.Contains ("App Timeout")) { + isTimeoutFailure = true; + break; + } + } + } + Assert.IsTrue (isTimeoutFailure, "correct xml"); + File.Delete (failurePath); + } + } +} diff --git a/tests/xharness/Xharness.Tests/Xharness.Tests.csproj b/tests/xharness/Xharness.Tests/Xharness.Tests.csproj index d78c28aa78..82a0bdbc29 100644 --- a/tests/xharness/Xharness.Tests/Xharness.Tests.csproj +++ b/tests/xharness/Xharness.Tests/Xharness.Tests.csproj @@ -81,6 +81,7 @@ + @@ -98,6 +99,9 @@ + + + diff --git a/tests/xharness/xharness.csproj b/tests/xharness/xharness.csproj index 3c8dedbecb..07b5d26a3b 100644 --- a/tests/xharness/xharness.csproj +++ b/tests/xharness/xharness.csproj @@ -174,6 +174,9 @@ + + +