ToolTask drops final stdout/stderr lines after Wave18_6 EOF wait — flaky ToolTaskCanChangeCanonicalErrorFormat #13734

I have seen flaky failures in ToolTaskCanChangeCanonicalErrorFormat. Below is some Copilot analysis about the possible reason, which seems plausible to me but I haven't vetted it.

Summary

Under ChangeWave 18.6, ToolTask.WaitForProcessExit waits only 2 seconds for the
async stdout/stderr pipes to reach EOF after the tool process has exited. When the
AsyncStreamReader thread takes longer than 2 s to flush its internal buffer
(common on busy CI VMs), the EOF wait expires and the final lines of tool output
are silently lost — the post-exit drain only sees what already made it into
the queues, and the loop never revisits them.

This is causing intermittent failures of
ToolTaskCanChangeCanonicalErrorFormat (and likely other ToolTask tests whose
assertions depend on the last line of tool output) in PR builds.

Where

• src/Utilities/ToolTask.cs, method WaitForProcessExit, ~lines 1083–1116.
• The 2 s constant: const int eofTimeoutSec = 2; at line 1099.
• The drop point: WaitHandle.WaitAll(eofEvents, TimeSpan.FromSeconds(eofTimeoutSec));
  at line 1102 — return value is discarded; no further drain is attempted on
  timeout.

Mechanism

1. Process.Start is called with RedirectStandardOutput/Error = true and
   BeginOutputReadLine/BeginErrorReadLine is called
   (ToolTask.cs:795-798). This wires the framework's
   AsyncStreamReader to call ReceiveStandardErrorOrOutputData
   (ToolTask.cs:1273-1321) for each line, ending with Data == null at EOF.
   That terminating callback is what signals _standardOutputEOF /
   _standardErrorEOF.

2. HandleToolNotifications reaches case 4 ("tool exited") and calls
   WaitForProcessExit (ToolTask.cs:967-979).

3. Wave 18.6 path:

   proc.WaitForExit(int.MaxValue);   // does NOT drain pipes
   WaitHandle.WaitAll(eofEvents, TimeSpan.FromSeconds(2));

   Process.WaitForExit(timeout) is documented to not wait on the async
   pipes when any timeout is supplied — only the parameterless overload does.
   So everything depends on the 2-second WaitAll.

4. After returning, HandleToolNotifications calls
   LogMessagesFromStandardError/Output once (ToolTask.cs:977-978) and then
   exits the consumer loop. Whatever is still buffered inside the
   AsyncStreamReader (i.e. has not yet been delivered via the callback that
   enqueues into _standardOutputData / _standardErrorData) is lost.

Why CI hits this and dev boxes don't

• cmd /C type <file> and sh -c "cat <file>" — used by the failing test —
  exit very quickly. The reader thread races the post-exit timer.
• CI runners typically have 2 vCPUs and run the Utilities test project alongside
  others, so the async-pipe reader thread can easily be context-switched out
  for >2 s after the process handle is already signaled.
• On a developer box with idle cores, the reader almost always wins the race.

Test symptoms

Flaky test: ToolTaskCanChangeCanonicalErrorFormat
(src/Utilities.UnitTests/ToolTask_Tests.cs:572).

The test writes two lines to a temp file:

Main.cs(17,20): warning CS0168: The variable 'foo' is declared but never used.
BADTHINGHAPPENED: This is my custom error format that's not in canonical error format.

then cmd /C type / sh -c cats the file and asserts the canonical-format
warning becomes a logged warning and the BADTHINGHAPPENED line becomes a
logged error. The BADTHINGHAPPENED line is the last non-blank line of
output, so it's exactly the line most likely to be lost when the EOF wait
expires before the reader has flushed.

Expected failure modes:

• engine.Errors.ShouldBe(1) — got 0 (BADTHINGHAPPENED line dropped before
  MyTool.LogEventsFromTextOutput saw it).
• engine.AssertLogContains("BADTHINGHAPPENED") — fails for the same reason.
• Less commonly, the warning line drops if both lines are still in the
  reader's buffer at process-exit.

The same race plausibly affects any other ToolTask test whose assertions
inspect the final lines of a short tool's output.

Reasoning trail

I asked two independent reviewers (Opus 4.7 and GPT-5.5 sub-agents) to read
src/Utilities/ToolTask.cs, src/Utilities.UnitTests/ToolTask_Tests.cs,
src/Utilities.UnitTests/MockEngine.cs, src/Shared/FileUtilities.cs, and
the project's xUnit configuration, and to rank plausible flake causes
independently. They converged on the same primary root cause (this one) and
on the same secondary issues (MockEngine3 not thread-safe, temp-file leak on
failure, return value of t.Execute() discarded). The temp-file generator
uses Guid.NewGuid() and a collision check, ruling out cross-test name
clashes; xUnit parallelism amplifies the timing window but is not itself the
cause.

The decisive evidence is the documented behavior of
Process.WaitForExit(timeout) (does not wait on async pipes), combined with
the fact that the 2 s constant predates any measurement on representative CI
hardware and the post-timeout code path discards data without retrying.

Proposed fix (sketch)

In WaitForProcessExit:

• Raise the EOF budget from 2 s to ~30 s (still bounded — the grandchild-hang
  protection that motivated Wave 18.6 is preserved).
• Drain the queues on every wait slice so that the consumer thread keeps pace
  with the reader and so that data already delivered is logged even if the
  outer wait ultimately times out.
• On timeout, log a low-importance diagnostic ("tool did not close pipes
  within {0}s; output may be truncated") so the rare grandchild case is
  recognizable.

The fix stays under the existing Wave18_6 gate; no new wave needed. Binlog
impact is limited to the new diagnostic on the rare timeout path.

A draft implementation already exists in chat history.

Secondary improvements (separate, lower priority)

• Make MockEngine3 thread-safe (src/Utilities.UnitTests/MockEngine.cs),
  or migrate test usages to the shared MockEngine. Not the proximate cause
  but eliminates a future flake source.
• In ToolTaskCanChangeCanonicalErrorFormat: wrap the temp-file delete in
  try/finally, assert t.Execute() returned true, and on failure dump
  engine.Log and the temp file contents to ITestOutputHelper so the next
  flake is diagnosable.

Acceptance criteria

• ToolTaskCanChangeCanonicalErrorFormat passes 100 / 100 runs locally and
  on CI under load.
• No regressions in existing Microsoft.Build.Utilities.UnitTests and the
  Microsoft.Build.UnitTests ToolTask suites.
• A grandchild-hang scenario (existing test, if any; otherwise a new
  targeted one) still completes in bounded time and emits the new diagnostic.