[WIP] idea to speed up Xamarin.Android.Build.Tests

src/Xamarin.Android.Build.Tasks/Tests/Xamarin.Android.Build.Tests/Utilities/BaseTest.cs

@@ -177,6 +177,26 @@ protected ProjectBuilder CreateDllBuilder (string directory, bool cleanupAfterSu
 			return BuildHelper.CreateDllBuilder (directory, cleanupAfterSuccessfulBuild, cleanupOnDispose);
 		}
 
+		protected void AssertBuild(ProjectBuilder builder)
+		{
+			foreach (var assertion in builder.Assertions) {
+				if (!assertion.Passed) {
+					Assert.Fail (assertion.ToString ());
+				}
+			}
+			builder.Assertions.Clear ();
+		}
+
+		protected void AssertBuildDidNotPass (ProjectBuilder builder)
+		{
+			foreach (var assertion in builder.Assertions) {
+				if (assertion.Passed) {
+					Assert.Fail (assertion.ToString ());
+				}
+			}
+			builder.Assertions.Clear ();
+		}
+
 		[OneTimeSetUp]
 		public void FixtureSetup ()
 		{
@@ -215,8 +235,17 @@ protected virtual void CleanupTest ()
 				return;
 			if (TestContext.CurrentContext.Result.Outcome.Status == NUnit.Framework.Interfaces.TestStatus.Passed || 
 			    TestContext.CurrentContext.Result.Outcome.Status == NUnit.Framework.Interfaces.TestStatus.Skipped) {
-				FileSystemUtils.SetDirectoryWriteable (output);
-				Directory.Delete (output, recursive: true);
+
+				do {
+					try {
+						FileSystemUtils.SetDirectoryWriteable (output);
+						Directory.Delete (output, recursive: true);
+						break;
+					} catch (IOException) {
+						//NOTE: seems to happen quite a bit on Windows
+						Thread.Sleep (25);
+					}
+				} while (true);
 			} else {
 				foreach (var file in Directory.GetFiles (Path.Combine (output), "build.log", SearchOption.AllDirectories)) {
 					TestContext.Out.WriteLine ("*************************************************************************");

src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Common/Assertion.cs

@@ -0,0 +1,41 @@
+using System;
+using System.Linq.Expressions;
+
+namespace Xamarin.ProjectTools
+{
+	/// <summary>
+	/// Represents an "assertion" that a condition is true as the build output streams through a callback
+	/// </summary>
+	public class Assertion
+	{
+		readonly Expression<Func<string, bool>> expression;
+		Func<string, bool> func;
+
+		public bool Passed { get; private set; }
+
+		public string Message { get; private set; }
+
+		public Assertion (Expression<Func<string, bool>> expression, string message = null)
+		{
+			this.expression = expression;
+			Message = message;
+		}
+
+		public void Assert(string line)
+		{
+			if (!Passed) {
+				if (func == null)
+					func = expression.Compile ();
+				Passed = func (line);
+			}
+		}
+
+		public override string ToString ()
+		{
+			if (!string.IsNullOrEmpty (Message))
+				return Message;
+
+			return $"Expression was false: {expression.Body}";
+		}
+	}
+}

src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Common/BuildOutput.cs

@@ -44,30 +44,10 @@ public string GetIntermediaryAsText (string file)
 			return File.ReadAllText (GetIntermediaryPath (file));
 		}
 
-		public bool IsTargetSkipped (string target)
+		//TODO: remove
+		public bool IsTargetSkipped (string a)
 		{
-			if (!Builder.LastBuildOutput.Contains (target))
-				throw new ArgumentException (string.Format ("Target '{0}' is not even in the build output.", target));
-			return Builder.LastBuildOutput.Contains (string.Format ("Target {0} skipped due to ", target))
-					|| Builder.LastBuildOutput.Contains (string.Format ("Skipping target \"{0}\" because it has no outputs.", target))
-					|| Builder.LastBuildOutput.Contains (string.Format ("Target \"{0}\" skipped, due to", target))
-					|| Builder.LastBuildOutput.Contains (string.Format ("Skipping target \"{0}\" because its outputs are up-to-date", target))
-					|| Builder.LastBuildOutput.Contains (string.Format ("target {0}, skipping", target))
-					|| Builder.LastBuildOutput.Contains ($"Skipping target \"{target}\" because all output files are up-to-date");
-		}
-
-		public bool IsApkInstalled {
-			get { return Builder.LastBuildOutput.Contains (" pm install "); }
-		}
-
-		public bool AreTargetsAllSkipped (params string [] targets)
-		{
-			return targets.All (t => IsTargetSkipped (t));
-		}
-
-		public bool AreTargetsAllBuilt (params string [] targets)
-		{
-			return targets.All (t => !IsTargetSkipped (t));
+			throw new NotImplementedException ();
 		}
 	}
 

src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Common/Builder.cs

@@ -14,11 +14,60 @@ public class Builder : IDisposable
 		public bool IsUnix { get; set; }
 		public bool RunningMSBuild { get; set; }
 		public LoggerVerbosity Verbosity { get; set; }
-		public string LastBuildOutput { get; set; }
 		public TimeSpan LastBuildTime { get; protected set; }
 		public string BuildLogFile { get; set; }
 		public bool ThrowOnBuildFailure { get; set; }
 
+		//TODO: remove
+		public string LastBuildOutput {
+			get { throw new NotImplementedException (); }
+		}
+
+		public List<Assertion> Assertions { get; set; } = new List<Assertion> ();
+
+		public void AssertTargetSkipped (string target)
+		{
+			Assertions.Add (new Assertion (o => o.Contains (target), $"Target '{target}' is not even in the build output."));
+
+			Assertions.Add (new Assertion (o => o.Contains ($"Target {target} skipped due to ") ||
+				o.Contains ($"Skipping target \"{target}\" because it has no outputs.") ||
+				o.Contains ($"Target \"{target}\" skipped, due to") ||
+				o.Contains ($"Skipping target \"{target}\" because its outputs are up-to-date") ||
+				o.Contains ($"target {target}, skipping") ||
+				o.Contains ($"Skipping target \"{target}\" because all output files are up-to-date"), $"Target {target} was not skipped."));
+		}
+
+		public void AssertApkInstalled ()
+		{
+			Assertions.Add (new Assertion (o => o.Contains (" pm install ")));
+		}
+
+		public void AssertAllTargetsSkipped (params string [] targets)
+		{
+			foreach (var t in targets) {
+				AssertTargetSkipped (t);
+			}
+		}
+
+		public void AssertTargetIsBuilt (string target)
+		{
+			Assertions.Add (new Assertion (o => o.Contains (target), $"Target '{target}' is not even in the build output."));
+
+			Assertions.Add (new Assertion (o => !o.Contains ($"Target {target} skipped due to ") &&
+				!o.Contains ($"Skipping target \"{target}\" because it has no outputs.") &&
+				!o.Contains ($"Target \"{target}\" skipped, due to") &&
+				!o.Contains ($"Skipping target \"{target}\" because its outputs are up-to-date") &&
+				!o.Contains ($"target {target}, skipping") &&
+				!o.Contains ($"Skipping target \"{target}\" because all output files are up-to-date"), $"Target {target} was not built."));
+		}
+
+		public void AssertAllTargetsBuilt (params string [] targets)
+		{
+			foreach (var t in targets) {
+				AssertTargetIsBuilt (t);
+			}
+		}
+
 		string GetVisualStudio2017Directory ()
 		{
 			var editions = new [] {
@@ -187,11 +236,6 @@ protected bool BuildInternal (string projectOrSolution, string target, string []
 				? Path.GetFullPath (Path.Combine (Root, Path.GetDirectoryName (projectOrSolution), BuildLogFile))
 				: null;
 
-			var logger = buildLogFullPath == null
-				? string.Empty
-				: string.Format ("/noconsolelogger \"/flp1:LogFile={0};Encoding=UTF-8;Verbosity={1}\"",
-					buildLogFullPath, Verbosity.ToString ().ToLower ());
-
 			var start = DateTime.UtcNow;
 			var homeDirectory = Environment.GetFolderPath (Environment.SpecialFolder.Personal);
  			var androidSdkToolPath = Path.Combine (homeDirectory, "android-toolchain");
@@ -208,8 +252,8 @@ protected bool BuildInternal (string projectOrSolution, string target, string []
 
 			var args  = new StringBuilder ();
 			var psi   = new ProcessStartInfo (XABuildExe);
-			args.AppendFormat ("{0} /t:{1} {2}",
-				QuoteFileName(Path.Combine (Root, projectOrSolution)), target, logger);
+			args.AppendFormat ("{0} /t:{1} /v:{2}",
+				QuoteFileName(Path.Combine (Root, projectOrSolution)), target, Verbosity);
 			if (RunningMSBuild)
 				args.Append (" /p:BuildingOutOfProcess=true");
 			else
@@ -244,57 +288,75 @@ protected bool BuildInternal (string projectOrSolution, string target, string []
 
 			bool nativeCrashDetected = false;
 			bool result = false;
+			bool lastBuildTimeSet = false;
 			int attempts = 1;
 			for (int attempt = 0; attempt < attempts; attempt++) {
-				var p = Process.Start (psi);
-				var ranToCompletion = p.WaitForExit ((int)new TimeSpan (0, 10, 0).TotalMilliseconds);
-				result = ranToCompletion && p.ExitCode == 0;
-
-				LastBuildTime = DateTime.UtcNow - start;
-
-				var sb = new StringBuilder ();
-				sb.AppendLine (psi.FileName + " " + args.ToString () + Environment.NewLine);
-				if (!ranToCompletion)
-					sb.AppendLine ("Build Timed Out!");
-				if (buildLogFullPath != null && File.Exists (buildLogFullPath)) {
-					using (var fs = File.OpenRead (buildLogFullPath)) {
-						using (var sr = new StreamReader (fs, Encoding.UTF8, true, 65536)) {
-							string line;
-							while ((line = sr.ReadLine ()) != null) {
-								sb.AppendLine (line);
-								if (line.StartsWith ("Time Elapsed", StringComparison.OrdinalIgnoreCase)) {
-									var match = timeElapsedRegEx.Match (line);
-									if (match.Success) {
-										LastBuildTime = TimeSpan.Parse (match.Groups ["TimeSpan"].Value);
-										Console.WriteLine ($"Found Time Elapsed {LastBuildTime}");
-									}
-								}
-								if (line.StartsWith ("Got a SIGSEGV while executing native code", StringComparison.OrdinalIgnoreCase)) {
-									nativeCrashDetected = true;
-									break;
+				using (var p = new Process { StartInfo = psi }) {
+					StreamWriter file = null;
+					if (buildLogFullPath != null) {
+						Directory.CreateDirectory (Path.GetDirectoryName (buildLogFullPath));
+						file = File.CreateText (buildLogFullPath);
+					}
+					try {
+						var standardError = new StringBuilder ();
+						file?.WriteLine ("#stdout begin");
+
+						p.OutputDataReceived += (sender, e) => {
+							if (e.Data == null)
+								return;
+							if (e.Data.StartsWith ("Time Elapsed", StringComparison.OrdinalIgnoreCase)) {
+								var match = timeElapsedRegEx.Match (e.Data);
+								if (match.Success) {
+									LastBuildTime = TimeSpan.Parse (match.Groups ["TimeSpan"].Value);
+									lastBuildTimeSet = true;
+									Console.WriteLine ($"Found Time Elapsed {LastBuildTime}");
 								}
 							}
+
+							if (e.Data.StartsWith ("Got a SIGSEGV while executing native code", StringComparison.OrdinalIgnoreCase)) {
+								nativeCrashDetected = true;
+							}
+
+							foreach (var assertion in Assertions) {
+								assertion.Assert (e.Data);
+							}
+
+							file?.WriteLine (e.Data);
+						};
+						p.ErrorDataReceived += (sender, e) => standardError.AppendLine (e.Data);
+
+						p.Start ();
+						p.BeginOutputReadLine ();
+						p.BeginErrorReadLine ();
+
+						var ranToCompletion = p.WaitForExit ((int)new TimeSpan (0, 10, 0).TotalMilliseconds);
+						if (nativeCrashDetected) {
+							Console.WriteLine ($"Native crash detected! Running the build for {projectOrSolution} again.");
+							continue;
 						}
-					}
-				}
-				sb.AppendFormat ("\n#stdout begin\n{0}\n#stdout end\n", p.StandardOutput.ReadToEnd ());
-				sb.AppendFormat ("\n#stderr begin\n{0}\n#stderr end\n", p.StandardError.ReadToEnd ());
+						result = ranToCompletion && p.ExitCode == 0;
+						if (!lastBuildTimeSet)
+							LastBuildTime = DateTime.UtcNow - start;
 
-				LastBuildOutput = sb.ToString ();
-				if (nativeCrashDetected) {
-					Console.WriteLine ($"Native crash detected! Running the build for {projectOrSolution} again.");
-					continue;
+						if (file != null) {
+							file.WriteLine ();
+							file.WriteLine ("#stdout end");
+							file.WriteLine ();
+							file.WriteLine ("#stderr begin");
+							file.WriteLine (standardError.ToString ());
+							file.WriteLine ("#stderr end");
+						}
+					} finally {
+						file?.Dispose ();
+					}
 				}
 			}
 
-
-			if (buildLogFullPath != null) {
-				Directory.CreateDirectory (Path.GetDirectoryName (buildLogFullPath));
-				File.WriteAllText (buildLogFullPath, LastBuildOutput);
-			}
 			if (!result && ThrowOnBuildFailure) {
 				string message = "Build failure: " + Path.GetFileName (projectOrSolution) + (BuildLogFile != null && File.Exists (buildLogFullPath) ? "Build log recorded at " + buildLogFullPath : null);
-				throw new FailedBuildException (message, null, LastBuildOutput);
+
+				//TODO: do we really need the full build log here? It seems to lock up my VS test runner
+				throw new FailedBuildException (message, null);
 			}
 
 			return result;

src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Xamarin.ProjectTools.csproj

@@ -41,6 +41,7 @@
   </ItemGroup>
   <ItemGroup>
     <Compile Include="Properties\AssemblyInfo.cs" />
+    <Compile Include="Common\Assertion.cs" />
     <Compile Include="Common\BuildActions.cs" />
     <Compile Include="Common\BuildItem.cs" />
     <Compile Include="Common\Package.cs" />