Fix race condition in UnreliableL2Tests.WriteFailureInvisible

[Copilot]

The test was intermittently failing in CI because L2 write failures are logged asynchronously after the background write task completes, but the test used a fixed 150ms delay that didn't reliably wait for logging to finish.

Changes

• LogCollector: Added WaitForLogsAsync that polls for expected log entries with timeout instead of guessing timing
• UnreliableL2Tests: Replaced fixed delay with WaitForLogsAsync(errorIds, TimeSpan.FromSeconds(5))

The polling logic matches AssertErrors exactly (count and order must match), ensuring test assertions see the same log state that will be verified.

// Before: unreliable fixed delay
await l2.LastWrite;
await Task.Delay(150); // thread jitter caused failures
log.AssertErrors(errorIds);

// After: poll until logs appear or timeout
await l2.LastWrite;
await log.WaitForLogsAsync(errorIds, TimeSpan.FromSeconds(5));
log.AssertErrors(errorIds);

Original prompt

This test failed in CI. Please either investigate the flakiness and fix it, or disable the test if it's inherently flaky:

Microsoft.Extensions.Caching.Hybrid.Tests.UnreliableL2Tests.WriteFailureInvisible(writeBreak: AsynchronousYield, errorIds: [7])

Result Details
Failed 39m ago on 642af2e5c000000
Duration0:00:00.673
Ownernot available
Date started11/21/2025, 9:29:23 AM
Date completed11/21/2025, 9:29:24 AM
Failing since37m ago
Failing since build20251121.17

Debug

Work items

Attachments

History

1ES Test Attachments

Artifacts

Error message
Assert.Equal() Failure: Strings differ
↓ (pos 0)
Expected: "7"
Actual: ""

Stack trace
at Microsoft.Extensions.Caching.Hybrid.Tests.LogCollector.AssertErrors(Int32[] errorIds) in /mnt/vss/_work/1/s/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/LogCollector.cs:line 60
at Microsoft.Extensions.Caching.Hybrid.Tests.UnreliableL2Tests.WriteFailureInvisible(BreakType writeBreak, Int32[] errorIds) in /mnt/vss/_work/1/s/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/UnreliableL2Tests.cs:line 49
--- End of stack trace from previous location ---

---

💡 You can make Copilot smarter by setting up custom instructions, customizing its development environment and configuring Model Context Protocol (MCP) servers. Learn more Copilot coding agent tips in the docs.

Microsoft Reviewers: Open in CodeFlow

[Copilot]

Pull request overview

This PR fixes a flaky test (WriteFailureInvisible) that was intermittently failing in CI due to a race condition. The test verifies that L2 cache write failures are properly logged, but because these failures are logged asynchronously after a background write task completes, the original fixed 150ms delay was insufficient to reliably wait for logging to finish.

Key Changes:

• Added WaitForLogsAsync method to LogCollector that polls for expected log entries with a timeout instead of using fixed delays
• Updated WriteFailureInvisible test to use WaitForLogsAsync(errorIds, TimeSpan.FromSeconds(5)) instead of Task.Delay(150)

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated no comments.

File	Description
test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/LogCollector.cs	Added WaitForLogsAsync method that polls for log entries matching expected error IDs with configurable timeout, using thread-safe lock-based checking that mirrors the validation logic in AssertErrors
test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/UnreliableL2Tests.cs	Replaced unreliable fixed 150ms delay with WaitForLogsAsync call that polls for up to 5 seconds, ensuring logs are present before assertion

[ericstj]

I wonder if it would be enough to just wait until this could be acquired once? Or are the items added asynchronously acquiring the lock potentially after this is called?

[stephentoub]

@copilot ?

[Copilot]

The logging itself is synchronous (line 120 adds to _items under lock), but it's called from the catch block (line 380 in DefaultHybridCache.StampedeStateT.cs) that executes asynchronously in the background task.

l2.LastWrite tracks when the write task completes, but doesn't guarantee the catch block has finished executing. The catch block could still be running after LastWrite is done, especially with thread scheduling variations.

So we need to poll: we're waiting for the logger to be called (which happens async), not just for the lock to be available. Acquiring the lock once would be a snapshot at a single point in time - we might check before the background catch block calls the logger.

[ericstj]

Looks good, just had a question that might simplify the method.