Stabilize 3 ToolTask_Tests flakes with diagnostics + timing fix

[jankratochvilcz]

Three ToolTask_Tests flakes share a common timing / process-output capture failure mode. Combined they account for the loudest cluster of CI noise in Microsoft.Build.Utilities.UnitTests over a 7-day flake survey on dnceng-public pipeline 75.

Changes

ToolTaskCanChangeCanonicalErrorFormat — diagnostic-only. Logs Execute() return, ExitCode, Errors, Warnings, MessageCount, elapsedMs, and full engine.Log before the assertions, so the next failure is actionable instead of just showing the command line.

HandleExecutionErrorsWhenToolLogsError — diagnostic-only. Same counters + elapsedMs. Shouldly customMessage on ShouldBeFalse so we can see ExitCode / engine.Errors when Execute() unexpectedly returns true. Drops a redundant log dump (the engine already streams to _output live).

ToolTaskThatTimeoutAndRetry — widens the slow / fast gap so process startup overhead on slow CI agents can't cause the "slow" path to outrun its timeout: slowDelay 5 s -> 20 s, Timeout 2 s -> 5 s. Logs per-attempt elapsedMs alongside configuredTimeoutMs so a follow-up can shrink these back once CI data accumulates.

Likely-suspect for the two diagnostic-only tests: async pipe drain race in ToolTask (Execute returns before stdout EOF, so engine.Log only captures the cmd echo). Confirmation signal would be MessageCount==0 with non-empty exit. These PRs make that signal visible.

Risk

Test-only changes. All 12 affected test instances pass locally.

[Copilot]

Pull request overview

This PR updates ToolTask_Tests to reduce CI flakiness by adding targeted diagnostics to two flaky tests and by widening the timing gap in the timeout/retry test so slow agents don’t accidentally miss the intended timeout path.

Changes:

• Add per-test diagnostics (Execute result, ExitCode, error/warning/message counters, elapsed time) to make future failures actionable.
• Dump engine.Log for ToolTaskCanChangeCanonicalErrorFormat to capture truncated/missing output scenarios.
• Increase the delay/timeout budgets in ToolTaskThatTimeoutAndRetry and log per-attempt elapsed vs configured timeout.

[github-actions]

Review Summary

This is a well-structured diagnostic-instrumentation PR that follows MSBuild test conventions correctly. The approach of adding Stopwatch timing + _output.WriteLine diagnostics to capture flaky test state is sound and non-invasive.

✅ Looks Good

• Test semantics preserved: All original assertions are maintained; new custom messages in ShouldBe/ShouldBeFalse add context without changing pass/fail behavior.
• Test infrastructure patterns: Correctly uses ITestOutputHelper (_output), Shouldly assertions with custom messages, and TestEnvironment.
• System.Diagnostics.Stopwatch: Already imported — no missing using.
• engine.Messages: Confirmed to be an int count on MockEngine3 — the interpolated string is correct.
• ToolTaskCanChangeCanonicalErrorFormat: Not asserting on executeResult is intentional and matches original behavior.

⚠️ Minor Concerns (non-blocking)

1. No tracking issue linked: The TODO comments should reference a GitHub issue so the diagnostics don't become permanent.
2. Test duration increase: The timeout bump (2s→5s) adds ~3s per timeout-path Theory case. Acceptable short-term but should be tightened once data is collected (as the comments state).
3. Line 1 whitespace: Trivial cosmetic change — consider reverting to keep git blame clean.

Overall this is a pragmatic approach to debugging a known flaky test. No blocking issues.

Note

🔒 Integrity filter blocked 1 item

The following item were blocked because they don't meet the GitHub integrity level.

• #13830 pull_request_read: has lower integrity than agent requires. The agent cannot read data with integrity below "approved".

To allow these resources, lower min-integrity in your GitHub frontmatter:

tools:
  github:
    min-integrity: approved  # merged | approved | unapproved | none

Generated by Expert Code Review (on open) for issue #13830 · ● 847.9K

[jankratochvilcz]

Thanks for the review. Triage:

Addressed (force-pushed):

• Reverted unintended UTF-8 BOM strip on line 1 of ToolTask_Tests.cs. Diff is now purely the three intended test changes.

Not addressed (left as-is):

• TODO comments should reference a GitHub issue. These TODOs (e.g. TODO: re-tighten once telemetry confirms ) are deliberately not tied to an upstream issue — they are anchored to the elapsed-time telemetry this PR introduces, which is the data source we'll use to tighten the bumps. Filing a tracking issue just to point at telemetry that lives in the same diff would be noise.
• Theory cases now take ~3s longer due to the 2s → 5s bump. Acknowledged in code comments. The point of the elapsed-time telemetry added here is precisely to gather data to tighten this back down; it is intended as a short-term widening, not a permanent budget.

This PR is test-only (src/Utilities.UnitTests/ToolTask_Tests.cs); production concerns (allocations, Span<T> etc.) don't apply.

[jankratochvilcz]

/azp run msbuild-pr

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[jankratochvilcz]

24h post-merge telemetry from main (dnceng-public pipeline 75, builds 1430301, 1430551, 1430938, 1431045, 1431261):

ToolTaskCanChangeCanonicalErrorFormat

TFM/arch	Runs	min ms	p50 ms	p95 ms	max ms	Failed
net10.0/x64	18	12	46	99	100	0
net472/x86	10	64	90	1154	1667	0

HandleExecutionErrorsWhenToolLogsError

TFM/arch	Runs	min ms	p50 ms	p95 ms	max ms	Failed
net10.0/x64	9	32	36	124	142	0
net472/x86	10	35	54	301	453	0

MessageCount==0 with non-empty exit (the race the PR predicted)

Not observed. Across all instrumented runs (37 instances for the first test, 19 for the second), every passing run had MessageCount > 0. The async-pipe-drain race remains a plausible-but-unconfirmed hypothesis after 24 h — leaving the diagnostics in place for another wave.

ToolTaskThatTimeoutAndRetry

Fast path (target: succeed within Timeout)

TFM/arch	Runs	min ms	p50 ms	p95 ms	max ms	Failed
net10.0/x64	108	102	684	1102	1136	0
net472/x86	60	1030	1048	1226	1370	0

Slow path (target: be killed by Timeout — elapsed ≈ configured Timeout)

TFM/arch	Runs	min ms	p50 ms	p95 ms	max ms	Failed
net10.0/x64	18	5030	5069	5199	5269	0
net472/x86	10	5030	5068	5579	5991	0

Follow-up draft #13846 shrinks Timeout 5 s → 4.5 s (~3.3x of observed fast max) and slowDelay 20 s → 18 s (preserves the 4x slow/fast gap), reclaiming ~17 s of wall-clock per slow attempt.