test(ui): retain timing evidence for published acceptance

Measure fixture launch, slow lookups, owned closure and Appearance PDF phases in existing hosted artifacts. Preserve every case, assertion and deadline. Refs #21, #22.

Co-Authored-By: GPT-6 <noreply@openai.com>
Signed-off-by: James Maes <jmaes@dmdbrands.com>

docs/SESSION-STATE.md

@@ -2,6 +2,31 @@
 
 Updated: 2026-10-12
 
+## Published acceptance timing investigation - 2026-10-12
+
+Exact d0526ef / CI38207252597 is terminal failure only in installed-updates.
+Core677/100% measured lines, focused28, native111 and fuzz9+2 pass, zero skips.
+Published process15 records110/111 passes, including native picker cancellation,
+with no assertion failure or final TRX before the unchanged600-second bound.
+The only uncompleted case is Appearance_WidthCssAndPrint. Prior822 published
+109/109 took590.96 seconds, including13.07 seconds for that unchanged case;
+three current fixture close fallbacks versus four in the prior passing run do
+not establish a new close regression. Native111 takes9m55. Retain actual logs
+and distinguish aggregate runtime from an operation hang; installed lifecycle
+was not reached.
+
+Prepare temporary hosted fixture timings for launch readiness, waits lasting
+at least2 seconds, owned-window closure and exact Appearance/PDF phases, retained
+in existing installed-smoke-ui session logs even if the outer process is stopped.
+No cases, assertions, waits/deadlines, source behavior or release gates change.
+Local isolated full Release passes with0 warnings/errors; formatting and direct
+Markdown lint of both changed documents pass.
+Full hosted proof is still required; remove DEBUG-ui-timing once the cause is
+measured and the original acceptance passes. Current required fuzz context remains
+unapplied. Shared approvals, actual enrollment/inventory, Azure verification/
+identity and shipped signatures, genuine final-head acknowledgement and owner
+visual/default-chooser acceptance remain open; no signing/release is claimed.
+
 ## Assurance push accepted natively; published picker failure investigated - 2026-10-12
 
 Signed/DCOe6fd281 is pushed. Hosted fuzz38204215912 passes core9/9 and activation2/2,

docs/TODO.md

@@ -3,7 +3,8 @@
 ## Current release checklist
 
 - [x] Pushe6fd281 and verify hosted fuzz9/9 core+2/2 activation,677 core/100% lines, focused28 and full native111, zero skips; retain actual evidence.
-- [ ] Verify the owned Settings activation candidate through exact hosted native/published/installed acceptance after the observed picker failure and600-second published timeout. Preserve all cases/assertions/deadlines; current required-check addition remains unapplied.
+- [x] Exactd052 hosted core677/100%, focused28, native111 and fuzz9+2 pass; published picker cancellation passes, but110/111 hit600 seconds without assertion failure/final TRX. Installed lifecycle not reached.
+- [ ] Measure retained launch/slow-wait/closure/Appearance-PDF timings to diagnose aggregate published runtime versus a blocked final operation; preserve111 cases and every assertion/deadline. Remove temporary timings after verified resolution; required fuzz context remains unapplied.
 
 - [x] Exact82256f3 CI38201379210 passes668 core/100% lines, focused28, native/published109 and installed108 per channel, zero skips; actual lifecycle artifacts/logs retained.
 - [x] Prepare current-standard assurance record, five seeded parser/property targets and honest unenrolled Best Practices assessment (#30/#31).

tests/MarkdownViewr.Windows.UiTests/AppSession.cs

@@ -4,6 +4,7 @@
  */
 
 using System.Diagnostics;
+using System.Runtime.CompilerServices;
 using FlaUI.Core;
 using FlaUI.Core.AutomationElements;
 using FlaUI.Core.Conditions;
@@ -28,15 +29,24 @@ public sealed class AppSession : IDisposable
    private static readonly TimeSpan s_launchTimeout = TimeSpan.FromSeconds(30);
    private static readonly TimeSpan s_pollInterval = TimeSpan.FromMilliseconds(250);
    private readonly DpiAwarenessScope _dpi;
+   private readonly Stopwatch _lifetime = Stopwatch.StartNew();
+   private readonly string? _timingPath;
 
 
 
    /// <summary>Launches the app against a fresh temporary data folder and waits for its main window.</summary>
-   public AppSession(bool showSplash = false, string? document = null, bool editorProbe = false, string documentFileName = "document.md", IReadOnlyDictionary<string, byte[]>? documentAssets = null, IReadOnlyDictionary<string, string>? additionalDocuments = null)
+   public AppSession(bool showSplash = false, string? document = null, bool editorProbe = false, string documentFileName = "document.md", IReadOnlyDictionary<string, byte[]>? documentAssets = null, IReadOnlyDictionary<string, string>? additionalDocuments = null, [CallerMemberName] string fixtureName = "")
    {
       ExePath = ResolveExePath();
       DataDirectory = Path.Combine(Path.GetTempPath(), AppIdentity.Info.Id + "-uitests", Guid.NewGuid().ToString("N"));
       Directory.CreateDirectory(DataDirectory);
+      if(Environment.GetEnvironmentVariable("GITHUB_WORKSPACE") is { Length: > 0 } workspace)
+      {
+         string evidence = Path.Combine(workspace, "artifacts", "installed-smoke-ui");
+         Directory.CreateDirectory(evidence);
+         _timingPath = Path.Combine(evidence, "session-" + Path.GetFileName(DataDirectory) + ".log");
+      }
+      TraceTiming("launch-start " + fixtureName);
       File.WriteAllText(
           Path.Combine(DataDirectory, "settings.json"),
           $$"""{ "ShowSplashScreen": {{(showSplash ? "true" : "false")}}, "CheckForUpdatesOnStartup": false }""");
@@ -74,6 +84,7 @@ public sealed class AppSession : IDisposable
          Automation = new UIA3Automation();
          App = Application.Launch(startInfo);
          MainWindow = WaitForMainWindow();
+         TraceTiming("main-window-ready");
       }
       catch
       {
@@ -158,7 +169,13 @@ public sealed class AppSession : IDisposable
    public AutomationElement WaitFor(Func<AutomationElement?> lookup, string description, TimeSpan? timeout = null)
    {
       TimeSpan effective = timeout ?? s_defaultTimeout;
+      long started = Stopwatch.GetTimestamp();
       RetryResult<AutomationElement?> result = Retry.WhileNull(lookup, timeout: effective, interval: s_pollInterval, ignoreException: true);
+      TimeSpan elapsed = Stopwatch.GetElapsedTime(started);
+      if(elapsed >= TimeSpan.FromSeconds(2) || result.Result is null)
+      {
+         TraceTiming(FormattableString.Invariant($"wait elapsed={elapsed.TotalMilliseconds:0}ms completed={result.Result is not null}: {description}"));
+      }
       return result.Result
           ?? throw new TimeoutException($"Timed out after {effective.TotalSeconds:0}s waiting for {description}. (app exited: {App.HasExited})");
    }
@@ -420,6 +437,25 @@ public sealed class AppSession : IDisposable
 
 
 
+   /// <summary>Retains bounded fixture-phase timings in the existing hosted evidence directory, including before an outer process timeout.</summary>
+   public void TraceTiming(string stage)
+   {
+      if(_timingPath is null)
+      {
+         return;
+      }
+      try
+      {
+         File.AppendAllText(_timingPath, FormattableString.Invariant($"[DEBUG-ui-timing] {_lifetime.Elapsed.TotalMilliseconds:0}ms {stage}\n"));
+      }
+      catch(Exception exception) when(exception is IOException or UnauthorizedAccessException)
+      {
+         // Diagnostic retention must not replace the original acceptance result.
+      }
+   }
+
+
+
    /// <summary>FlaUI closes only the main HWND; close every fixture-owned window first so intended siblings do not force its exit timeout.</summary>
    private void CloseOwnedWindows()
    {
@@ -452,8 +488,11 @@ public sealed class AppSession : IDisposable
       {
          try
          {
+            TraceTiming("close-owned-start");
             CloseOwnedWindows();
+            TraceTiming("close-owned-complete");
             App?.Close();
+            TraceTiming("application-close-complete");
          }
          catch
          {
@@ -463,7 +502,9 @@ public sealed class AppSession : IDisposable
          {
             if(App is { HasExited: false })
             {
+               TraceTiming("kill-start");
                App.Kill();
+               TraceTiming("kill-complete");
             }
          }
          catch
@@ -484,6 +525,7 @@ public sealed class AppSession : IDisposable
       finally
       {
          _dpi.Dispose();
+         TraceTiming("session-disposed");
       }
    }
 }

tests/MarkdownViewr.Windows.UiTests/AppTests.Appearance.cs

@@ -24,6 +24,7 @@ public partial class AppTests
       using var session = new AppSession(document: "# " + Title + "\n\nOne paired appearance needle.");
       AutomationElement initial = session.WaitFor(() => session.FindInApp(cf => cf.ByAutomationId("mv-heading-0")), "the actual appearance fixture heading", TimeSpan.FromSeconds(30));
       Assert.True(initial.BoundingRectangle.Width > 350);
+      session.TraceTiming("appearance-initial-heading-ready");
       double height = initial.BoundingRectangle.Height;
       EditReadingAppearance(session, 320, "#content { background: #112233; }");
       WaitForAppearanceWindowColor(session, session.MainWindow, Color.FromArgb(17, 34, 51));
@@ -37,6 +38,7 @@ public partial class AppTests
       session.InvokeMenuItem("View", "DocumentThemesMenu");
       session.ClickElement("DocumentTheme:GitHub Light");
       WaitForAppearanceWindowColor(session, session.MainWindow, Color.FromArgb(17, 34, 51));
+      session.TraceTiming("appearance-pdf-start");
       using(Bitmap pdf = await ExportPrintFixtureAsync(session, "reader-appearance", new PrintOptions("Active Theme", Backgrounds: true, FullPage: false)))
       {
          Assert.Equal(Color.White.ToArgb(), pdf.GetPixel(pdf.Width / 2, pdf.Height / 2).ToArgb());
@@ -45,11 +47,13 @@ public partial class AppTests
       WaitForAppearanceWindowColor(session, session.MainWindow, Color.FromArgb(17, 34, 51));
       Assert.Equal(source, session.WaitForElement("SourceText").Patterns.Value.Pattern.Value.Value);
       WaitForFindCount(session, "1 of 1");
+      session.TraceTiming("appearance-pdf-and-find-complete");
       string accepted = session.ReadSettings();
       Rectangle before = session.WaitForElement("mv-heading-0").BoundingRectangle;
       EditReadingAppearance(session, 320, "#content { background: #445566; }", save: false);
       Assert.Equal(accepted, session.ReadSettings());
       Assert.Equal(before, session.WaitForElement("mv-heading-0").BoundingRectangle);
+      session.TraceTiming("appearance-cancel-complete");
       EditReadingAppearance(session, 320, "#content { background: #112233; }", limit: false);
       session.WaitFor(() => session.FindInApp(cf => cf.ByAutomationId("mv-heading-0")) is { } heading && heading.BoundingRectangle.Width > 321 ? heading : null, "the actual heading expanding after the native width limit is disabled");
       using(var settings = JsonDocument.Parse(session.ReadSettings()))
@@ -59,6 +63,7 @@ public partial class AppTests
          Assert.Equal("#content { background: #112233; }", settings.RootElement.GetProperty("GlobalCss").GetString());
       }
       RetainDocumentWindow(session, session.MainWindow, "reader-appearance");
+      session.TraceTiming("appearance-acceptance-complete");
    }