[ScreenRuler.UITests.Next] Add verbose execution-log artifact; close via toolbar Close button (no kill)

Per feedback: stop killing the UI to mask the hang. Close via the toolbar's Close button using the already-open toolbar session (a targeted search for one button, not a full list-windows enumeration of the frozen overlay - which was the hang). Add DiagnosticLogger: every step is timestamped, echoed to TestContext AND saved as a TestExecutionLog_*.log result artifact, so we can see exactly what happens - the clipboard value after each measurement, the window list winappcli reports for the overlay check, and where time goes. Open/close detection stays a hang-free Win32 process-presence CHECK (Process.GetProcessesByName - a check, not a kill) so the suite reliably runs and produces the log.
This commit is contained in:
gkhmyznikov
2026-06-26 11:43:39 -07:00
parent 95fac8ea29
commit 3eddfdd444
2 changed files with 143 additions and 32 deletions

View File

@@ -0,0 +1,66 @@
// Copyright (c) Microsoft Corporation
// The Microsoft Corporation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System.Diagnostics;
using System.Text;
using Microsoft.PowerToys.UITest.Next;
using Microsoft.VisualStudio.TestTools.UnitTesting;
namespace ScreenRuler.UITests.Next;
/// <summary>
/// Verbose per-test execution log. Every <see cref="Step"/> is timestamped with the elapsed seconds
/// since the test began, echoed to the <see cref="TestContext"/> (so it shows inline in the run
/// output) AND accumulated; <see cref="Save"/> writes the whole thing out as a
/// <c>TestExecutionLog_*.log</c> result artifact for post-mortem on CI. ScreenRuler UI tests run
/// sequentially, so a single ambient instance (see <c>TestHelper</c>) is safe.
/// </summary>
internal sealed class DiagnosticLogger
{
private readonly UITestBase testBase;
private readonly string testName;
private readonly StringBuilder buffer = new();
private readonly Stopwatch stopwatch = Stopwatch.StartNew();
public DiagnosticLogger(UITestBase testBase, string testName)
{
this.testBase = testBase;
this.testName = testName;
Step($"===== {testName}: execution log started =====");
}
/// <summary>Append one timestamped step, echoing it to the TestContext immediately.</summary>
public void Step(string message)
{
var line = $"[+{stopwatch.Elapsed.TotalSeconds,8:F2}s] {message}";
buffer.AppendLine(line);
try
{
testBase.TestContext.WriteLine(line);
}
catch
{
// TestContext can be unavailable late in teardown — the buffered copy is still saved.
}
}
/// <summary>Flush the whole log to a result-attached file artifact (best-effort).</summary>
public void Save()
{
Step($"===== {testName}: execution log ended =====");
try
{
var dir = testBase.TestContext.TestResultsDirectory ?? Path.GetTempPath();
Directory.CreateDirectory(dir);
var safeName = string.Concat((testName ?? "test").Split(Path.GetInvalidFileNameChars()));
var file = Path.Combine(dir, $"TestExecutionLog_{safeName}_{DateTime.Now:yyyyMMdd_HHmmss_fff}.log");
File.WriteAllText(file, buffer.ToString());
testBase.TestContext.AddResultFile(file);
}
catch
{
// Best-effort artifact; the inline TestContext copy is the fallback.
}
}
}

View File

@@ -47,11 +47,25 @@ public static class TestHelper
// hotkeys/overlays interfere).
public const string ModuleSettingsKey = "Measure Tool";
// Ambient per-test diagnostics + the live toolbar session. ScreenRuler UI tests run sequentially,
// so a single ambient instance is safe. The logger is created in InitializeTest and flushed (as a
// TestExecutionLog artifact) in CleanupTest; Log(...) is a no-op when no test is active.
private static DiagnosticLogger? log;
private static Session? activeRuler;
/// <summary>Append a verbose, timestamped step to the current test's execution log.</summary>
private static void Log(string message) => log?.Step(message);
/// <summary>Navigate to the Screen Ruler settings page, enable the toggle, and read the shortcut.</summary>
public static Key[] InitializeTest(UITestBase testBase, string testName)
{
log = new DiagnosticLogger(testBase, testName);
activeRuler = null;
Log("InitializeTest: navigating to the Screen Ruler settings page");
LaunchFromSetting(testBase);
Log("InitializeTest: enabling the Screen Ruler toggle");
var toggleSwitch = SetScreenRulerToggle(testBase, enable: true);
Assert.IsTrue(toggleSwitch.IsOn, $"Screen Ruler toggle switch should be ON for {testName}");
@@ -59,13 +73,24 @@ public static class TestHelper
Assert.IsNotNull(activationKeys, "Should be able to read activation shortcut");
Assert.IsTrue(activationKeys.Length > 0, "Activation shortcut should contain at least one key");
Log($"InitializeTest: ready; activation shortcut = {string.Join(" + ", activationKeys)}");
return activationKeys;
}
/// <summary>Close the Screen Ruler UI (best-effort).</summary>
/// <summary>Close the Screen Ruler UI (best-effort) and flush the execution-log artifact.</summary>
public static void CleanupTest(UITestBase testBase)
{
CloseScreenRulerUI(testBase);
try
{
Log("CleanupTest: closing the Screen Ruler UI");
CloseScreenRulerUI(testBase);
}
finally
{
log?.Save();
log = null;
activeRuler = null;
}
}
/// <summary>Navigate to the Screen Ruler (Measure Tool) settings page.</summary>
@@ -236,32 +261,29 @@ public static class TestHelper
WaitForScreenRulerUIState(testBase, shouldBeOpen: false, timeoutMs);
/// <summary>
/// Close the Measure Tool UI by force-stopping its transient overlay process(es). Deliberately
/// avoids winappcli: a process-scoped <see cref="Session.FromProcess"/> and
/// <see cref="WindowControl.TryCloseByApp"/> both run <c>list-windows</c> over the now-FROZEN
/// post-measurement overlay, which hangs the CLI for 60s (the cleanup timeout). Killing the process
/// never hangs and the runner re-creates it on the next activation.
/// Close the Measure Tool UI by clicking the toolbar's Close button — the explicit, user-facing
/// close. We do NOT kill the process. Uses the already-open toolbar session from
/// <see cref="ActivateScreenRuler"/>, so it's a TARGETED <c>search</c> for that one button rather
/// than a full <c>list-windows</c> enumeration. Best-effort + logged so a close hiccup never masks
/// the real measurement result.
/// </summary>
public static void CloseScreenRulerUI(UITestBase testBase) => KillScreenRulerProcesses();
/// <summary>Force-stop every transient MeasureToolUI overlay process (to close, or to clear a stale one before activating).</summary>
private static void KillScreenRulerProcesses()
public static void CloseScreenRulerUI(UITestBase testBase)
{
foreach (var p in Process.GetProcessesByName(ScreenRulerProcess))
if (activeRuler is null)
{
try
{
p.Kill();
p.WaitForExit(2000);
}
catch
{
// Tolerant — a cleanup failure must never mask the real test result.
}
finally
{
p.Dispose();
}
Log("CloseScreenRulerUI: no active toolbar session — nothing to close");
return;
}
try
{
Log("CloseScreenRulerUI: clicking the toolbar Close button");
activeRuler.Find<Element>(By.AccessibilityId(CloseButtonId), 3000).Click(msPostAction: 300);
Log("CloseScreenRulerUI: Close button clicked");
}
catch (Exception ex)
{
Log($"CloseScreenRulerUI: clicking the Close button failed: {ex.GetType().Name}: {ex.Message}");
}
}
@@ -300,11 +322,15 @@ public static class TestHelper
for (int i = 0; i < attempts; i++)
{
Log($"SendShortcutUntilVisible: attempt {i + 1}/{attempts} — sending the activation chord");
KeyboardHelper.SendKeys(activationKeys);
if (WaitForScreenRulerUI(testBase, perAttemptMs))
{
Log($"SendShortcutUntilVisible: MeasureToolUI process detected on attempt {i + 1}");
return true;
}
Log($"SendShortcutUntilVisible: still not visible after attempt {i + 1}");
}
return false;
@@ -315,23 +341,23 @@ public static class TestHelper
{
ClearClipboard();
// Clear any stale overlay from a prior test before activating, so the process-based open check
// (and the activation chord) see a clean slate rather than a leftover MeasureToolUI.
KillScreenRulerProcesses();
// Park the cursor on the primary-monitor centre so the Measure Tool initialises tracking at a
// predictable on-screen spot before activation (the cursor can otherwise be anywhere).
var (cx, cy) = ScreenCenter();
MouseHelper.MoveTo(cx, cy);
Thread.Sleep(200);
Log($"ActivateScreenRuler: sending activation chord {string.Join(" + ", activationKeys)}");
Assert.IsTrue(
SendShortcutUntilVisible(testBase, activationKeys),
$"ScreenRulerUI should appear after pressing activation shortcut for {testName}: {string.Join(" + ", activationKeys)}");
// Process-scoped session so the toolbar buttons resolve regardless of which Measure Tool
// window owns them (the winappcli equivalent of the legacy global Find).
return Session.FromProcess(ScreenRulerProcess, PowerToysModule.ScreenRuler, timeoutMS: 5000);
Log("ActivateScreenRuler: toolbar is up; building the process-scoped session");
activeRuler = Session.FromProcess(ScreenRulerProcess, PowerToysModule.ScreenRuler, timeoutMS: 5000);
Log("ActivateScreenRuler: session ready");
return activeRuler;
}
/// <summary>Run a spacing-tool measurement and validate the clipboard output.</summary>
@@ -345,6 +371,7 @@ public static class TestHelper
PerformMeasurementAction();
var clipboardText = GetClipboardText();
Log($"PerformSpacingToolTest[{testName}]: clipboard after measurement = '{clipboardText}' (length {clipboardText.Length})");
Assert.IsFalse(string.IsNullOrEmpty(clipboardText), $"{testName}: Clipboard should contain measurement data");
Assert.IsTrue(
ValidateSpacingClipboardContent(clipboardText, testName),
@@ -380,6 +407,7 @@ public static class TestHelper
Thread.Sleep(300);
var clipboardText = GetClipboardText();
Log($"PerformBoundsToolTest: clipboard after drag = '{clipboardText}' (length {clipboardText.Length})");
Assert.IsFalse(string.IsNullOrEmpty(clipboardText), "Clipboard should contain measurement data");
Assert.IsTrue(
clipboardText.Contains("100 × 100") || clipboardText.Contains("100 x 100"),
@@ -408,18 +436,24 @@ public static class TestHelper
for (int attempt = 1; attempt <= attempts; attempt++)
{
// (a) Accessibility invoke via winappcli — coordinate-free, so a 0×0 button rect is fine.
Log($"SelectToolAndVerify[{testName}]: attempt {attempt}/{attempts} — UIA invoke of {buttonId}");
ruler.Find<Element>(By.AccessibilityId(buttonId), 15000).Click(msPostAction: 300);
if (MoveOffToolbarAndWaitForOverlay(cx, cy))
{
Log($"SelectToolAndVerify[{testName}]: overlay present after UIA invoke (attempt {attempt})");
return;
}
// (b) Keyboard accelerator backup (Ctrl+<n>) — the toolbar is the foreground window.
Log($"SelectToolAndVerify[{testName}]: no overlay after invoke; keyboard backup Ctrl+{acceleratorDigit}");
KeyboardHelper.SendKeys(Key.Ctrl, acceleratorDigit);
if (MoveOffToolbarAndWaitForOverlay(cx, cy))
{
Log($"SelectToolAndVerify[{testName}]: overlay present after keyboard backup (attempt {attempt})");
return;
}
Log($"SelectToolAndVerify[{testName}]: still no overlay after attempt {attempt}");
}
Assert.Fail(
@@ -459,11 +493,20 @@ public static class TestHelper
/// once a tool is engaged and the cursor is over the capture surface. This is the reliable
/// "we're in capture state" signal that the blind click-then-measure approach was missing.
/// </summary>
private static bool IsMeasureOverlayPresent() =>
WindowsFinder.ListByApp(ScreenRulerProcess).Any(w =>
private static bool IsMeasureOverlayPresent()
{
var windows = WindowsFinder.ListByApp(ScreenRulerProcess);
var present = windows.Any(w =>
w.Title.Contains("MeasureToolOverlay", StringComparison.OrdinalIgnoreCase) ||
w.ClassName.Contains("OverlayWindow", StringComparison.OrdinalIgnoreCase));
var summary = windows.Count == 0
? "(none)"
: string.Join(", ", windows.Select(w => $"'{w.Title}'[{w.ClassName}]"));
Log($"IsMeasureOverlayPresent: {windows.Count} window(s): {summary} => overlay {(present ? "PRESENT" : "absent")}");
return present;
}
/// <summary>The toolbar keyboard accelerator (Ctrl+1..4) that selects each tool.</summary>
private static Key AcceleratorFor(string buttonId) => buttonId switch
{
@@ -481,12 +524,14 @@ public static class TestHelper
// SetCursorPos can land without a tracked move, leaving the measurement empty), then click
// to capture.
var (cx, cy) = ScreenCenter();
Log($"PerformMeasurementAction: two-step move to centre ({cx},{cy}), then left-click to capture");
MouseHelper.MoveTo(cx - 60, cy - 60);
Thread.Sleep(200);
MouseHelper.MoveTo(cx, cy);
Thread.Sleep(400);
MouseHelper.LeftClick();
Thread.Sleep(500);
Log("PerformMeasurementAction: right-click to dismiss the selection");
MouseHelper.RightClick();
Thread.Sleep(400);
}