Add better query logging

With step descriptions so logs have helpful info
Redth · Oct 16, 2022 · f7782b9 · f7782b9
1 parent a1691e4
commit f7782b9
Show file tree

Hide file tree

Showing 10 changed files with 148 additions and 94 deletions.
diff --git a/src/Core/Query/DescendantsQueryStep.cs b/src/Core/Query/DescendantsQueryStep.cs
@@ -4,7 +4,8 @@ namespace Microsoft.Maui.Automation.Querying;
 
 public class DescendantsQueryStep : PredicateQueryStep
 {
-	public DescendantsQueryStep(Predicate<IElement>? predicate) : base(predicate)
+	public DescendantsQueryStep(Predicate<IElement>? predicate, string? predicateDescription = null)
+		: base(predicate, predicateDescription)
 	{
 	}
 
@@ -13,6 +14,9 @@ public DescendantsQueryStep() : base()
 	}
 
 	public override Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IElement> tree, IEnumerable<IElement> currentSet)
-		=> Task.FromResult(currentSet.Traverse(Predicate));
+		=> Task.FromResult(currentSet.Traverse(Predicate));
+
+	public override string ToString()
+		=> $"Descendants({base.ToString()})";
 }
 
diff --git a/src/Core/Query/DriverQuery.cs b/src/Core/Query/DriverQuery.cs
@@ -51,10 +51,29 @@ public async Task<IEnumerable<IElement>> Elements(int autoWaitMs = DefaultAutoWa
 		public TaskAwaiter<IEnumerable<IElement>> GetAwaiter()
 			=> AutoWait().GetAwaiter();
 
+		void LogQuery(IEnumerable<IElement> elements, int waited)
+		{
+			var s = new StringBuilder();
+			s.Append(Query.ToString());
+			s.AppendLine($"\t ✅ (Waited {waited}ms)");
+			Logger.LogInformation(s.ToString());
+		}
+
+		Exception LogQuery(Exception ex, int waited, IEnumerable<IElement> elements)
+		{
+			var s = new StringBuilder();
+			s.Append(Query.ToString());
+			s.AppendLine($"\t ❌ (Waited {waited}ms)");
+			Logger.LogInformation(s.ToString());
+			Logger.LogError(ex, ex.Message);
+
+			return ex;
+		}
+
 		async Task<IEnumerable<IElement>> AutoWait(int autoWaitMs = DefaultAutoWaitMilliseconds, int retryDelayMs = DefaultAutoWaitRetryMilliseconds, bool waitForNone = false)
 		{
-			Logger.LogInformation($"[Query({Query.Id})] AutoWaiting...");
 			var waited = 0;
+			IEnumerable<IElement> results = Enumerable.Empty<IElement>();
 
 			while (waited < autoWaitMs || autoWaitMs <= 0)
 			{
@@ -63,7 +82,7 @@ async Task<IEnumerable<IElement>> AutoWait(int autoWaitMs = DefaultAutoWaitMilli
 
 				var elements = await Driver.GetElements(platform).ConfigureAwait(false);
 
-				var results = await Query.Execute(Driver, elements);
+				results = await Query.Execute(Driver, elements);
 
 				var anyResults = results.Any();
 
@@ -73,13 +92,9 @@ async Task<IEnumerable<IElement>> AutoWait(int autoWaitMs = DefaultAutoWaitMilli
 					if (autoWaitMs <= 0 || !anyResults)
 					{
 						if (anyResults)
-						{
-							var ex = new ElementsStillFoundException(Query);
-							Logger.LogError(ex, $"[Query({Query.Id})] {ex.Message}");
-							throw ex;
-						}
+							throw LogQuery(new ElementsStillFoundException(Query), waited, results);
 
-						Logger.LogInformation($"[Query({Query.Id})] Completed with {results.Count()} element(s).");
+						LogQuery(results, waited);
 						return results;
 					}
 				}
@@ -88,28 +103,19 @@ async Task<IEnumerable<IElement>> AutoWait(int autoWaitMs = DefaultAutoWaitMilli
 					// Wait until we find 1 or more
 					if (autoWaitMs <= 0 || anyResults)
 					{
-						Logger.LogInformation($"[Query({Query.Id})] Completed with {results.Count()} element(s).");
+						LogQuery(results, waited);
 						return results;
 					}
 				}
 
-				Logger.LogInformation($"[Query({Query.Id})] Waited {waited}ms, Waiting another {retryDelayMs}ms...");
-				Thread.Sleep(retryDelayMs);
+				await Task.Delay(retryDelayMs);
 				waited += retryDelayMs;
 			}
 
 			if (waitForNone)
-			{
-				var ex = new ElementsStillFoundException(Query);
-				Logger.LogError(ex, $"[Query({Query.Id})] {ex.Message}");
-				throw ex;
-			}
+				throw LogQuery(new ElementsStillFoundException(Query), waited, results);
 			else
-			{
-				var ex = new ElementsNotFoundException(Query);
-				Logger.LogError(ex, $"[Query({Query.Id})] {ex.Message}");
-				throw ex;
-			}
+				throw LogQuery(new ElementsNotFoundException(Query), waited, results);
 		}
 
 	}

diff --git a/src/Core/Query/FirstQueryStep.cs b/src/Core/Query/FirstQueryStep.cs
@@ -7,7 +7,8 @@ class FirstQueryStep : PredicateQueryStep
 	public FirstQueryStep() : base()
 	{ }
 
-	public FirstQueryStep(Predicate<IElement>? predicate = null) : base(predicate)
+	public FirstQueryStep(Predicate<IElement>? predicate = null, string? predicateDescription = null)
+		: base(predicate, predicateDescription)
 	{ }
 
 	public override Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IElement> tree, IEnumerable<IElement> currentSet)
@@ -18,6 +19,9 @@ public override Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<
 			return Task.FromResult<IEnumerable<IElement>>(new[] { first });
 		else
 			return Task.FromResult(Enumerable.Empty<IElement>());
-	}
+	}
+
+	public override string ToString()
+		=> $"First({base.ToString()})";
 }
 
diff --git a/src/Core/Query/IndexQueryStep.cs b/src/Core/Query/IndexQueryStep.cs
@@ -2,20 +2,14 @@
 
 namespace Microsoft.Maui.Automation.Querying;
 
-public class IndexQueryStep : PredicateQueryStep
+public class IndexQueryStep : QueryStep
 {
 	public IndexQueryStep(int index)
 		: base()
 	{
 		Index = index;
 	}
 
-	public IndexQueryStep(int index, Predicate<IElement> predicate)
-		: base(predicate)
-	{
-		Index = index;
-	}
-
 	public readonly int Index;
 
 	public override Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IElement> tree, IEnumerable<IElement> currentSet)
@@ -29,6 +23,9 @@ public override Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<
 		catch { }
 
 		return Task.FromResult<IEnumerable<IElement>>(newSet);
-	}
+	}
+
+	public override string ToString()
+		=> $"Index({Index})";
 }
 
diff --git a/src/Core/Query/InteractionQueryStep.cs b/src/Core/Query/InteractionQueryStep.cs
@@ -4,15 +4,17 @@ namespace Microsoft.Maui.Automation.Querying;
 
 public class InteractionQueryStep : IQueryStep
 {
-	public InteractionQueryStep(Func<IDriver, IElement, Task> interaction)
+	public InteractionQueryStep(Func<IDriver, IElement, Task> interaction, string? interactionDescription)
 	{
 		Interaction = interaction;
+		InteractionDescription = interactionDescription ?? "Custom";
 	}
 
 	public virtual TimeSpan DefaultPauseBeforeInteraction => TimeSpan.FromMilliseconds(300);
 	public virtual TimeSpan DefaultPauseAfterInteraction => TimeSpan.FromMilliseconds(300);
 
 	public readonly Func<IDriver, IElement, Task> Interaction;
+	public readonly string InteractionDescription;
 
 	public async Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IElement> tree, IEnumerable<IElement> currentSet)
 	{
@@ -27,7 +29,10 @@ public async Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IEl
 		}
 
 		return currentSet;
-	}
+	}
+
+	public override string ToString()
+		=> $"{InteractionDescription}";
 }
 
 
diff --git a/src/Core/Query/PredicateQueryStep.cs b/src/Core/Query/PredicateQueryStep.cs
@@ -4,14 +4,19 @@ namespace Microsoft.Maui.Automation.Querying;
 
 public class PredicateQueryStep : QueryStep
 {
-	public PredicateQueryStep(Predicate<IElement>? predicate = null)
+	public PredicateQueryStep(Predicate<IElement>? predicate = null, string? predicateDescription = null) : base()
 	{
-		Predicate = predicate ?? new Predicate<IElement>(e => true);
+		Predicate = predicate ?? new Predicate<IElement>(e => true);
+		PredicateDescription = predicate is null ? string.Empty : predicateDescription ?? "Expression";
 	}
 
-	public readonly Predicate<IElement> Predicate;
-
+	public readonly Predicate<IElement> Predicate;
+	public virtual string PredicateDescription { get; private set; }
+
 	public override Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IElement> tree, IEnumerable<IElement> currentSet)
-		=> Task.FromResult(currentSet.Where(e => Predicate.Invoke(e)));
+		=> Task.FromResult(currentSet.Where(e => Predicate.Invoke(e)));
+
+	public override string ToString()
+		=> PredicateDescription;
 }
 
diff --git a/src/Core/Query/Query.cs b/src/Core/Query/Query.cs
@@ -1,7 +1,9 @@
-using Microsoft.Extensions.Logging;
+using System.Text;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Abstractions;
-using Microsoft.Maui.Automation.Driver;
-
+using Microsoft.Maui.Automation.Driver;
+using static System.Net.Mime.MediaTypeNames;
+
 namespace Microsoft.Maui.Automation.Querying;
 
 public class Query
@@ -16,41 +18,45 @@ public static class ConfigurationKeys
 
 	public Query()
 	{
-		Id = Guid.NewGuid().ToString();
+		QueryId = Guid.NewGuid().ToString();
 	}
 
 	public Query(Platform automationPlatform)
 	{
 		AutomationPlatform = automationPlatform;
-		Id = Guid.NewGuid().ToString();
+		QueryId = Guid.NewGuid().ToString();
 	}
 
-	public readonly string Id;
+	public readonly string QueryId;
 
 	List<IQueryStep> steps = new();
 
 	public static Query On(Platform automationPlatform)
 		=> new Query(automationPlatform);
 
-	public static Query By(Predicate<IElement> predicate)
-		=> new Query().Append(predicate);
-
-	public static Query ByAutomationId(string automationId)
-		=> By(e => e.AutomationId == automationId);
+	static Query by(Predicate<IElement> predicate, string? predicateDescription = null)
+		=> new Query().append(predicate, predicateDescription);
+
+	public static Query By(Predicate<IElement> predicate)
+		=> by(predicate, null);
+
+    public static Query AutomationId(string automationId)
+		=> by(e => e.AutomationId == automationId, $"AutomationId='{automationId}'");
 
 	public static Query ById(string id)
-		=> By(e => e.Id == id);
+		=> by(e => e.Id == id, $"Id='{id}'");
 
-	public static Query OfType(string type)
-		=> By(e => e.Type == type);
+	public static Query Type(string type)
+		=> by(e => e.Type == type, $"Type='{type}'");
 
 	public static Query ContainingText(string text, StringComparison comparisonType = StringComparison.InvariantCultureIgnoreCase)
-		=> By(e => e.Text.Contains(text, comparisonType));
+		=> by(e => e.Text.Contains(text, comparisonType), $"$Text.Contains('{text}')");
 
 	public static Query Marked(string marked, StringComparison comparisonType = StringComparison.InvariantCultureIgnoreCase)
-		=> By(e => e.Id.Equals(marked, comparisonType)
+		=> by(e => e.Id.Equals(marked, comparisonType)
 			|| e.AutomationId.Equals(marked, comparisonType)
-			|| e.Text.Equals(marked, comparisonType));
+			|| e.Text.Equals(marked, comparisonType),
+			$"Id='{marked}' OR AutomationId='{marked}' OR Text='{marked}'");
 
 	public Query Append(IQueryStep step)
 	{
@@ -59,11 +65,14 @@ public Query Append(IQueryStep step)
 	}
 
 	public Query Append(Predicate<IElement> predicate)
-	{
-		steps.Add(new PredicateQueryStep(predicate));
-		return this;
-	}
-
+		=> append(predicate, null);
+
+	internal Query append(Predicate<IElement> predicate, string? predicateDescription = null)
+	{
+		steps.Add(new PredicateQueryStep(predicate, predicateDescription));
+		return this;
+	}
+
 	public Platform? AutomationPlatform { get; private set; }
 
 	public async Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IElement> source)
@@ -94,6 +103,25 @@ public async Task<IEnumerable<IElement>> Execute(IDriver driver, IEnumerable<IEl
 		}
 
 		return currentSet;
+	}
+
+	public override string ToString()
+	{
+		var s = new StringBuilder();
+		s.Append($"Query(Id='{QueryId}'");
+
+		if (AutomationPlatform is not null)
+			s.Append(", AutomationPlatform={AutomationPlatform}");
+		s.AppendLine(")");
+
+		for (int i = 0; i < steps.Count; i++)
+		{
+			var step = steps[i];
+			s.Append($"\t .{step.ToString()}");
+			if (i < steps.Count - 1)
+				s.AppendLine();
+		}
+
+		return s.ToString();
 	}
-
 }