Skip to content

Surface the real cause when the diagnostic log file cannot be created - #10374

Open
Evangelink wants to merge 2 commits into
mainfrom
dev/amauryleve/automatic-adventure
Open

Surface the real cause when the diagnostic log file cannot be created#10374
Evangelink wants to merge 2 commits into
mainfrom
dev/amauryleve/automatic-adventure

Conversation

@Evangelink

Copy link
Copy Markdown
Member

Why

A .NET SDK CI run crashed at MTP test host startup with an error that made the actual problem impossible to diagnose:

Unhandled exception. System.InvalidOperationException: Failed to create a unique log file after 3 seconds.
Lastly tried file name is 'Microsoft.DotNet.PackageInstall.Tests_net11.0_x64_260730124750326.diag'.
   at Microsoft.Testing.Platform.Logging.FileLogger.CreateFileStream(...)

Two createdump full crash dumps had just been written to the same Helix disk immediately before, so the real cause was almost certainly disk exhaustion, not a file name collision. FileLogger.CreateFileStream caught every IOException in a 3 second retry loop, swallowed it, and then reported a generic "cannot create a unique log file" with no inner exception. Retrying only ever recovers from a name collision, so disk-full, missing-folder, and path-too-long failures were spun on and then reported as something they were not.

Investigating that turned up two further defects in the same loop.

What changed

The deadline was evaluated before the first attempt. IClock.UtcNow is wall time, not monotonic. A stall of more than 3 seconds, or a forward clock jump (NTP / VM time sync), between two adjacent statements made the loop throw without ever calling Create, leaving fileName null and rendering Lastly tried file name is ''. A Helix agent that just flushed two full crash dumps is exactly the environment where that happens, so this may well be the shape of the reported failure. The loop is now bounded by attempt count, which is provably terminating and immune to the clock.

Every retry regenerated the identical name. The candidate came from a millisecond-resolution timestamp, so a lost race was retried unchanged until the clock ticked (about 15ms on Windows), burning thousands of doomed attempts over the 3 second window on a machine that is often already sick. Retry candidates now carry the process id and the attempt index, making them unique both within the process and against any other process racing on the same log folder, so a collision can only ever happen on the first attempt. The first candidate keeps its existing name shape, so the file name users see in the normal case is unchanged.

The real error is now reported. On exhaustion we throw IOException (the same type a single failed attempt throws, so a caller needs only one filter rather than IOException plus InvalidOperationException) carrying the last failure in the message and chained as InnerException. The message now reports the full path and the attempt count instead of a hardcoded "3 seconds" that was baked into 13 translations.

Notes for reviewers

The .xlf files were regenerated with /t:UpdateXlf, not hand-edited.

Two things I deliberately left alone, both worth a second opinion:

  • A failure to create the diagnostic log file is still fatal to the test run. This file already has the opposite documented policy on the dispose path ("a logger failing to flush must never crash an otherwise successful test run", see Microsoft.Testing.Platform test host crash on shutdown: "Failed to flush logs before the timeout of '300' seconds" (FileLogger.Dispose) dotnet/sdk#55215), and here we trade "no diagnostics" for "no test results at all". Making it degrade gracefully is a user visible behavior change that deserves its own discussion, so this PR only makes the failure precisely catchable so that can be layered on later.
  • Directory.CreateDirectory in TestApplication.CreateFileLoggerIfDiagnosticIsEnabled sits on the same fatal path with the same disk-full trigger and is not covered here.

Testing

Full repo build is clean across all target frameworks. Unit tests pass on net9.0 (1977) and net462 (1936), the latter covering the netstandard2.0 build of the platform.

The new tests were mutation checked rather than just observed passing: separately removing the name uniqueness, the process id discriminator, the message detail, and the inner exception chaining each fails between one and three tests.

FileLogger.CreateFileStream swallowed every IOException in a wall-clock-bounded
retry loop and then threw a generic "Failed to create a unique log file", losing
the original exception. Retrying only ever recovers from a name collision, so
disk-full / missing-folder / path-too-long failures were spun on for 3 seconds
and then reported as something they were not.

Fixed:

- The deadline was evaluated before the first attempt, so a >3s stall or a
  forward clock jump between two adjacent statements threw without ever trying
  to create the file, reporting an empty file name. The loop is now bounded by
  attempt count, which is provably terminating and immune to the wall clock
  (IClock.UtcNow is not monotonic).
- Each retry regenerated the very same name until the clock ticked (~15ms on
  Windows), burning thousands of doomed attempts on a machine that is often
  already sick. Retry candidates now carry the process id and the attempt index,
  so they are unique both within the process and against any other process
  racing on the same log folder; a collision can only happen on the first
  attempt. The first candidate keeps its existing name shape.
- On exhaustion we now throw IOException (the same type a single failed attempt
  throws, so a caller needs only one filter) carrying the last failure in the
  message and chained as InnerException.

Note this deliberately keeps a failure to create the diagnostic log fatal to the
test host; making diagnostics degrade gracefully is a separate behavior decision.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot-Session: cb2c4b8e-1114-4ecb-93f8-e7359646d5d1
Copilot AI review requested due to automatic review settings August 1, 2026 07:33
@Evangelink
Evangelink enabled auto-merge (squash) August 1, 2026 07:34

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Improves diagnostic log creation reliability and error reporting in Microsoft.Testing.Platform.

Changes:

  • Replaces time-based retries with bounded, distinct filename attempts.
  • Preserves and reports the underlying IOException.
  • Adds unit coverage and regenerates localization resources.
Show a summary per file
File Description
src/Platform/Microsoft.Testing.Platform/Logging/FileLogger.cs Revises file creation retries and errors.
src/Platform/Microsoft.Testing.Platform/Resources/PlatformResources.resx Updates the diagnostic failure message.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.cs.xlf Regenerates Czech localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.de.xlf Regenerates German localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.es.xlf Regenerates Spanish localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.fr.xlf Regenerates French localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.it.xlf Regenerates Italian localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ja.xlf Regenerates Japanese localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ko.xlf Regenerates Korean localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pl.xlf Regenerates Polish localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pt-BR.xlf Regenerates Brazilian Portuguese localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ru.xlf Regenerates Russian localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.tr.xlf Regenerates Turkish localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hans.xlf Regenerates Simplified Chinese localization.
src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hant.xlf Regenerates Traditional Chinese localization.
test/UnitTests/Microsoft.Testing.Platform.UnitTests/Logging/FileLoggerTests.cs Tests retry naming and exception details.

Review details

  • Files reviewed: 16/16 changed files
  • Comments generated: 1
  • Review effort level: Balanced

Comment thread src/Platform/Microsoft.Testing.Platform/Logging/FileLogger.cs Outdated
@github-actions

This comment has been minimized.

Nothing enforces a single FileLogger per process, so two loggers created in the
same clock tick derived the identical ladder of candidate names from timestamp +
process id + attempt index and raced each other through it. The XML doc claimed
process-wide uniqueness that the name shape did not actually provide.

Replace the positional attempt index with a process-wide atomic counter, so every
retry candidate is distinct across all loggers in the process.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot-Session: cb2c4b8e-1114-4ecb-93f8-e7359646d5d1
Copilot AI review requested due to automatic review settings August 1, 2026 07:43

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review details

  • Files reviewed: 16/16 changed files
  • Comments generated: 0 new
  • Review effort level: Balanced

@github-actions

github-actions Bot commented Aug 1, 2026

Copy link
Copy Markdown
Contributor

🧪 Test quality grade — PR #10374

GradeTestMutationNotesHow to improve
A (90–100) new FileLoggerTests.
FileLogger_
NullFileSyncFlush_
ConcurrentLoggersInTheSameTickNeverShareACandidateName
3/3 killed Intersection assertion kills the process-wide counter vs attempt-index mutation; shared-name identity pin is precise.
A (90–100) new FileLoggerTests.
FileLogger_
NullFileSyncFlush_
EveryAttemptUsesADistinctFileName
4/4 killed Count + distinctness + exact path[0] + StartsWith for all retries protect the uniqueness invariant and loop bound.
A (90–100) new FileLoggerTests.
FileLogger_
NullFileSyncFlush_
WhenEveryAttemptFails_
ReportsAndChainsTheLastFailure
5/5 killed ThrowsExactly + AreSame on InnerException + Contains for last path, attempt count, and original message text.
A (90–100) mod FileLoggerTests.
FileLogger_
NullFileSyncFlush_
FileStreamCreated
4/4 killed HasCount(2) + exact path[0] + StartsWith with PID prefix + fileLoggerName identity; all retry-logic mutations killed.

This advisory comment was generated automatically. Grades are heuristic
and informational — they do not block merging. Suggestions on the Files
changed tab can be applied with one click. Re-run with
/grade-tests.

🤖 Automated content by GitHub Copilot. Generated by the Grade Tests on PR (on open / sync) workflow. · sonnet46 101.1 AIC · ⌖ 4.3 AIC · ⊞ 11.8K · [◷]( · )

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants