From c36f2852e13543d9549cba974b2616e58e02f7f7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Wed, 12 Feb 2025 15:59:03 +0100 Subject: [PATCH 01/32] wip --- .../Logging/FakeLogCollector.cs | 107 +++++++++++ .../Logging/FakeLogCollectorTests.cs | 180 ++++++++++++++++++ 2 files changed, 287 insertions(+) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 376cc87be8c..551e994a737 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -4,6 +4,9 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; using Microsoft.Extensions.Options; using Microsoft.Shared.Diagnostics; @@ -19,6 +22,8 @@ public class FakeLogCollector private readonly List _records = []; private readonly FakeLogCollectorOptions _options; + private readonly List _waiters = []; // modify only under _records lock + /// /// Initializes a new instance of the class. /// @@ -106,6 +111,67 @@ public FakeLogRecord LatestRecord /// public int Count => _records.Count; + + // TODO TW: add documentation + /// + /// + /// + /// + /// + /// Task which is completed when the condition is fulfilled or when the cancellation is invoked + public Task WaitForLogAsync(Func endWaiting, CancellationToken cancellationToken = default) + { + _ = Throw.IfNull(endWaiting); + + Waiter waiter; + + lock (_records) + { + if (_records.Count > 0 && endWaiting(LatestRecord)) + { + return Task.CompletedTask; + } + + waiter = new Waiter(endWaiting); + _waiters.Add(waiter); + } + + bool isCancelled = false; + + if (cancellationToken.CanBeCanceled) + { + lock (_records) + { + if (cancellationToken.IsCancellationRequested) + { + isCancelled = true; + _ = _waiters.Remove(waiter); + } + } + + _ = cancellationToken.Register(() => + { + lock (_records) + { + _ = _waiters.Remove(waiter); + } + + // trigger the task from outside the lock + _ = waiter.TaskSource.TrySetCanceled(cancellationToken); + }); + } + + if (isCancelled) + { + // trigger the task from outside the lock + _ = waiter.TaskSource.TrySetCanceled(cancellationToken); // TODO TW: <<<< is this correct? + } + +#pragma warning disable VSTHRD003 // Avoid awaiting foreign Tasks + return waiter.TaskSource.Task; +#pragma warning restore VSTHRD003 // Avoid awaiting foreign Tasks + } + internal void AddRecord(FakeLogRecord record) { if (_options.FilteredLevels.Count > 0 && !_options.FilteredLevels.Contains(record.Level)) @@ -129,13 +195,54 @@ internal void AddRecord(FakeLogRecord record) return; } + List? waitersToWakeUp = null; + lock (_records) { _records.Add(record); + + // TODO TW: To consider: + GatherWaitersForWaking(ref waitersToWakeUp, record); + } + + if (waitersToWakeUp is not null) + { + foreach (var waiterToWakeUp in waitersToWakeUp) + { + // trigger the task from outside the lock + waiterToWakeUp.TaskSource.SetResult(true); + } } _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } + private void GatherWaitersForWaking(ref List? waitersToWakeUp, FakeLogRecord currentlyLoggedRecord) + { + for (var waiterIndex = _waiters.Count - 1; waiterIndex >= 0; waiterIndex--) + { + var waiter = _waiters[waiterIndex]; + if (!waiter.ShouldEndWaiting(currentlyLoggedRecord)) + { + continue; + } + + waitersToWakeUp ??= []; + waitersToWakeUp.Add(waiter); + _ = _waiters.Remove(waiter); + } + } + internal TimeProvider TimeProvider => _options.TimeProvider; + + private readonly record struct Waiter(Func ShouldEndWaiting) + { + public Func ShouldEndWaiting { get; } = ShouldEndWaiting; + + // NOTE: In order to avoid potential dead locks, this task should + // be completed when the main lock is not being held. Otherwise, + // application code being woken up by the task could potentially + // call back into the MetricCollector code and thus trigger a deadlock. + public TaskCompletionSource TaskSource { get; } = new(); + } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 69fd33600d6..efda96ef509 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -2,7 +2,12 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Collections.Concurrent; +using System.Collections.Generic; using System.Globalization; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; using Microsoft.Extensions.Time.Testing; using Xunit; using Xunit.Abstractions; @@ -177,4 +182,179 @@ public void TestOutputHelperExtensionsGeneric() logger.Log((LogLevel)42, "Hello world!"); Assert.Contains("invld] Hello world!", output.Last); } + + private record WaitingTestCase( + int EndWaitAtAttemptCount, + int? CancellationWaitInMs, + bool StartsWithCancelledToken, + string[] ExpectedOperationSequence, + bool ExpectedTaskCancelled + ); + + private const int WaitingTscOverallLogCount = 3; + private const int WaitingTscOneLogTimeInMs = 250; + private const string WaitingTscLogAttemptPrefix = "Log attempt"; + + [Theory] + [InlineData(0)] + [InlineData(1)] + [InlineData(2)] + [InlineData(3)] + [InlineData(4)] + public async Task Waiting(int testCase) + { + // Arrange + + var testCaseData = WaitingTestCases()[testCase]; + + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + + var logger = new FakeLogger(collector); + + using var cancellationTokenSource = testCaseData.CancellationWaitInMs is not null + ? new CancellationTokenSource(TimeSpan.FromMilliseconds(testCaseData.CancellationWaitInMs.Value)) + : new CancellationTokenSource(); + + if (testCaseData.StartsWithCancelledToken) + { + cancellationTokenSource.Cancel(); + } + + var testExecutionCustomLog = new ConcurrentQueue(); + + int count = 0; + + bool EndWaiting(FakeLogRecord record) + { + Interlocked.Increment(ref count); + testExecutionCustomLog.Enqueue("Checking if should end waiting #" + count); + return count == testCaseData.EndWaitAtAttemptCount; + } + + // Act + + testExecutionCustomLog.Enqueue("Started"); + + var awaitingTask = collector.WaitForLogAsync(EndWaiting, cancellationTokenSource.Token); + + var loggingBackgroundAction = Task.Run( + () => + { + for (var logAttempt = 1; logAttempt <= WaitingTscOverallLogCount; logAttempt++) + { + Thread.Sleep(WaitingTscOneLogTimeInMs); + var message = $"{WaitingTscLogAttemptPrefix} #{logAttempt:000}"; + testExecutionCustomLog.Enqueue(message); + logger.LogDebug(message); + } + }, + CancellationToken.None); + + testExecutionCustomLog.Enqueue("Right after starting the background action"); + + bool taskCancelled = false; + + try + { + await awaitingTask; + } + catch (TaskCanceledException) + { + taskCancelled = true; + } + + testExecutionCustomLog.Enqueue("Finished waiting for the log"); + + await loggingBackgroundAction; + + testExecutionCustomLog.Enqueue("Background action has finished"); + + // Assert + Assert.True(testExecutionCustomLog.SequenceEqual(testCaseData.ExpectedOperationSequence)); + Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); + Assert.Equal(taskCancelled, testCaseData.ExpectedTaskCancelled); + } + + private static List WaitingTestCases() + { + var testCases = new List(); + + // Waiting for one record + testCases.Add(new WaitingTestCase( + 1, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if should end waiting #1", + "Finished waiting for the log", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false + )); + + // Waiting for two records + testCases.Add(new WaitingTestCase( + 2, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if should end waiting #1", + $"{WaitingTscLogAttemptPrefix} #002", + "Checking if should end waiting #2", + "Finished waiting for the log", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false + )); + + // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. + const int OneAndHalfRecordTime = WaitingTscOneLogTimeInMs + (WaitingTscOneLogTimeInMs / 2); + testCases.Add(new WaitingTestCase( + WaitingTscOverallLogCount + 1, OneAndHalfRecordTime, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if should end waiting #1", + "Finished waiting for the log", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + true + )); + + // Waiting for many log records, but starting with cancellation token already cancelled. + testCases.Add(new WaitingTestCase( + WaitingTscOverallLogCount, null, true, [ + "Started", + "Right after starting the background action", + "Finished waiting for the log", + $"{WaitingTscLogAttemptPrefix} #001", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + true + )); + + // Waiting for single log record and supplying a cancellation period that would match three logs to get writter + testCases.Add(new WaitingTestCase( + 1, 3 * WaitingTscOneLogTimeInMs, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if should end waiting #1", + "Finished waiting for the log", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false + )); + + return testCases; + } } From 1b4ccdf27ca3fda29e0284873865f9b7ca326405 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 24 Mar 2025 10:56:24 +0100 Subject: [PATCH 02/32] refactor --- .../Logging/FakeLogCollectorTests.cs | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index efda96ef509..e47c150f5d3 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -227,7 +227,7 @@ public async Task Waiting(int testCase) bool EndWaiting(FakeLogRecord record) { Interlocked.Increment(ref count); - testExecutionCustomLog.Enqueue("Checking if should end waiting #" + count); + testExecutionCustomLog.Enqueue("Checking if waiting should end #" + count); return count == testCaseData.EndWaitAtAttemptCount; } @@ -251,7 +251,7 @@ bool EndWaiting(FakeLogRecord record) CancellationToken.None); testExecutionCustomLog.Enqueue("Right after starting the background action"); - + bool taskCancelled = false; try @@ -285,7 +285,7 @@ private static List WaitingTestCases() "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", - "Checking if should end waiting #1", + "Checking if waiting should end #1", "Finished waiting for the log", $"{WaitingTscLogAttemptPrefix} #002", $"{WaitingTscLogAttemptPrefix} #003", @@ -300,9 +300,9 @@ private static List WaitingTestCases() "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", - "Checking if should end waiting #1", + "Checking if waiting should end #1", $"{WaitingTscLogAttemptPrefix} #002", - "Checking if should end waiting #2", + "Checking if waiting should end #2", "Finished waiting for the log", $"{WaitingTscLogAttemptPrefix} #003", "Background action has finished" @@ -317,7 +317,7 @@ private static List WaitingTestCases() "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", - "Checking if should end waiting #1", + "Checking if waiting should end #1", "Finished waiting for the log", $"{WaitingTscLogAttemptPrefix} #002", $"{WaitingTscLogAttemptPrefix} #003", @@ -346,7 +346,7 @@ private static List WaitingTestCases() "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", - "Checking if should end waiting #1", + "Checking if waiting should end #1", "Finished waiting for the log", $"{WaitingTscLogAttemptPrefix} #002", $"{WaitingTscLogAttemptPrefix} #003", From 721ce3e2511f05a93696cf3de5cd525901e5f4a8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 24 Mar 2025 14:59:31 +0100 Subject: [PATCH 03/32] we might actually need timeout too --- .../Logging/FakeLogCollector.cs | 18 ++- .../Logging/FakeLogCollectorTests.cs | 113 +++++++++++------- 2 files changed, 86 insertions(+), 45 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 551e994a737..22265428aca 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -112,14 +112,25 @@ public FakeLogRecord LatestRecord public int Count => _records.Count; + public Task WaitForLogAsync( + Func endWaiting, + CancellationToken cancellationToken = default) + { + return WaitForLogAsync(endWaiting, null, cancellationToken); + } + // TODO TW: add documentation /// /// /// /// + /// /// /// Task which is completed when the condition is fulfilled or when the cancellation is invoked - public Task WaitForLogAsync(Func endWaiting, CancellationToken cancellationToken = default) + public Task WaitForLogAsync( + Func endWaiting, + TimeSpan? timeout, + CancellationToken cancellationToken = default) { _ = Throw.IfNull(endWaiting); @@ -129,7 +140,7 @@ public Task WaitForLogAsync(Func endWaiting, CancellationTo { if (_records.Count > 0 && endWaiting(LatestRecord)) { - return Task.CompletedTask; + return Task.FromResult(true); } waiter = new Waiter(endWaiting); @@ -239,7 +250,8 @@ private readonly record struct Waiter(Func ShouldEndWaiting { public Func ShouldEndWaiting { get; } = ShouldEndWaiting; - // NOTE: In order to avoid potential dead locks, this task should + // TODO TW: check this + // NOTE: In order to avoid potential deadlocks, this task should // be completed when the main lock is not being held. Otherwise, // application code being woken up by the task could potentially // call back into the MetricCollector code and thus trigger a deadlock. diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index e47c150f5d3..4c3c35afe44 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -186,9 +186,11 @@ public void TestOutputHelperExtensionsGeneric() private record WaitingTestCase( int EndWaitAtAttemptCount, int? CancellationWaitInMs, + int? TimeoutWaitInMs, bool StartsWithCancelledToken, string[] ExpectedOperationSequence, - bool ExpectedTaskCancelled + bool ExpectedTaskCancelled, + bool? ExpectedAwaitedTaskResult ); private const int WaitingTscOverallLogCount = 3; @@ -201,6 +203,7 @@ bool ExpectedTaskCancelled [InlineData(2)] [InlineData(3)] [InlineData(4)] + [InlineData(5)] public async Task Waiting(int testCase) { // Arrange @@ -235,7 +238,11 @@ bool EndWaiting(FakeLogRecord record) testExecutionCustomLog.Enqueue("Started"); - var awaitingTask = collector.WaitForLogAsync(EndWaiting, cancellationTokenSource.Token); + TimeSpan? timeout = testCaseData.TimeoutWaitInMs is null + ? null + : new TimeSpan(testCaseData.TimeoutWaitInMs.Value); + + var awaitingTask = collector.WaitForLogAsync(EndWaiting, timeout, cancellationTokenSource.Token); var loggingBackgroundAction = Task.Run( () => @@ -252,24 +259,26 @@ bool EndWaiting(FakeLogRecord record) testExecutionCustomLog.Enqueue("Right after starting the background action"); + bool? result = null; bool taskCancelled = false; try { - await awaitingTask; + result = await awaitingTask; } catch (TaskCanceledException) { taskCancelled = true; } - testExecutionCustomLog.Enqueue("Finished waiting for the log"); + testExecutionCustomLog.Enqueue("Finished waiting for the log. Waiting for the background action to finish."); await loggingBackgroundAction; testExecutionCustomLog.Enqueue("Background action has finished"); // Assert + Assert.Equal(result, testCaseData.ExpectedAwaitedTaskResult); Assert.True(testExecutionCustomLog.SequenceEqual(testCaseData.ExpectedOperationSequence)); Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); Assert.Equal(taskCancelled, testCaseData.ExpectedTaskCancelled); @@ -277,83 +286,103 @@ bool EndWaiting(FakeLogRecord record) private static List WaitingTestCases() { - var testCases = new List(); + var testCases = new List + { + // Waiting for one record + new WaitingTestCase( + 1, null, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished", + ], + false, + true), + + // Waiting for two records + new WaitingTestCase( + 2, null, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + $"{WaitingTscLogAttemptPrefix} #002", + "Checking if waiting should end #2", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + true) + }; - // Waiting for one record + // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. + const int OneAndHalfRecordTime = WaitingTscOneLogTimeInMs + (WaitingTscOneLogTimeInMs / 2); testCases.Add(new WaitingTestCase( - 1, null, false, [ + WaitingTscOverallLogCount + 1, OneAndHalfRecordTime, null, false, [ "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", "Checking if waiting should end #1", - "Finished waiting for the log", + "Finished waiting for the log. Waiting for the background action to finish.", $"{WaitingTscLogAttemptPrefix} #002", $"{WaitingTscLogAttemptPrefix} #003", "Background action has finished" ], - false - )); + true, + null)); - // Waiting for two records + // Waiting for many log records, but starting with cancellation token already cancelled. testCases.Add(new WaitingTestCase( - 2, null, false, [ + WaitingTscOverallLogCount, null, null, true, [ "Started", "Right after starting the background action", + "Finished waiting for the log. Waiting for the background action to finish.", $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log", $"{WaitingTscLogAttemptPrefix} #003", "Background action has finished" ], - false - )); + true, + null) + ); - // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. - const int OneAndHalfRecordTime = WaitingTscOneLogTimeInMs + (WaitingTscOneLogTimeInMs / 2); + // Waiting for single log record and supplying a cancellation period that would match three logs to get writer testCases.Add(new WaitingTestCase( - WaitingTscOverallLogCount + 1, OneAndHalfRecordTime, false, [ + 1, 3 * WaitingTscOneLogTimeInMs, null, false, [ "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", "Checking if waiting should end #1", - "Finished waiting for the log", + "Finished waiting for the log. Waiting for the background action to finish.", $"{WaitingTscLogAttemptPrefix} #002", $"{WaitingTscLogAttemptPrefix} #003", "Background action has finished" ], - true - )); + false, + true) + ); - // Waiting for many log records, but starting with cancellation token already cancelled. + // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. testCases.Add(new WaitingTestCase( - WaitingTscOverallLogCount, null, true, [ - "Started", - "Right after starting the background action", - "Finished waiting for the log", - $"{WaitingTscLogAttemptPrefix} #001", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - true - )); - - // Waiting for single log record and supplying a cancellation period that would match three logs to get writter - testCases.Add(new WaitingTestCase( - 1, 3 * WaitingTscOneLogTimeInMs, false, [ + 3, null, (2 * WaitingTscOneLogTimeInMs) + (WaitingTscOneLogTimeInMs / 2), false, [ "Started", "Right after starting the background action", $"{WaitingTscLogAttemptPrefix} #001", "Checking if waiting should end #1", - "Finished waiting for the log", $"{WaitingTscLogAttemptPrefix} #002", + "Checking if waiting should end #2", + "Finished waiting for the log. Waiting for the background action to finish.", $"{WaitingTscLogAttemptPrefix} #003", "Background action has finished" ], - false - )); + false, + false) + ); return testCases; } From 233e23a491c826abc43020740836c0234f81a2a3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 24 Mar 2025 17:54:56 +0100 Subject: [PATCH 04/32] WIP --- .../Logging/FakeLogCollector.cs | 70 +++++++++++++------ .../Logging/FakeLogCollectorTests.cs | 3 +- 2 files changed, 51 insertions(+), 22 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 22265428aca..1f4556cb8f0 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -138,28 +138,30 @@ public Task WaitForLogAsync( lock (_records) { + // Before we even start waiting, we check if the latest record already fulfills the condition and if yes, we exit early with success if (_records.Count > 0 && endWaiting(LatestRecord)) { return Task.FromResult(true); } - waiter = new Waiter(endWaiting); + // Before we even start waiting, we checked if the cancellation token is already canceled and if yes, we exit early with a canceled task + if (cancellationToken.IsCancellationRequested) + { + var tcs = new TaskCompletionSource(); + _ = tcs.TrySetCanceled(cancellationToken); + return tcs.Task; + } + + // We register the waiter + + // TODO TW: flc also very nice + waiter = new Waiter(this, endWaiting, timeout); _waiters.Add(waiter); } - bool isCancelled = false; - if (cancellationToken.CanBeCanceled) { - lock (_records) - { - if (cancellationToken.IsCancellationRequested) - { - isCancelled = true; - _ = _waiters.Remove(waiter); - } - } - + // When the cancellation token is canceled, we resolve the waiter and cancel the awaited task _ = cancellationToken.Register(() => { lock (_records) @@ -168,16 +170,11 @@ public Task WaitForLogAsync( } // trigger the task from outside the lock + // TODO TW: nice, but why outside precisely? _ = waiter.TaskSource.TrySetCanceled(cancellationToken); }); } - if (isCancelled) - { - // trigger the task from outside the lock - _ = waiter.TaskSource.TrySetCanceled(cancellationToken); // TODO TW: <<<< is this correct? - } - #pragma warning disable VSTHRD003 // Avoid awaiting foreign Tasks return waiter.TaskSource.Task; #pragma warning restore VSTHRD003 // Avoid awaiting foreign Tasks @@ -221,13 +218,14 @@ internal void AddRecord(FakeLogRecord record) foreach (var waiterToWakeUp in waitersToWakeUp) { // trigger the task from outside the lock - waiterToWakeUp.TaskSource.SetResult(true); + _ = waiterToWakeUp.TaskSource.TrySetResult(true); } } _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } + // Must be called inside lock(_records) private void GatherWaitersForWaking(ref List? waitersToWakeUp, FakeLogRecord currentlyLoggedRecord) { for (var waiterIndex = _waiters.Count - 1; waiterIndex >= 0; waiterIndex--) @@ -246,9 +244,11 @@ private void GatherWaitersForWaking(ref List? waitersToWakeUp, FakeLogRe internal TimeProvider TimeProvider => _options.TimeProvider; - private readonly record struct Waiter(Func ShouldEndWaiting) + private readonly record struct Waiter { - public Func ShouldEndWaiting { get; } = ShouldEndWaiting; + public Func ShouldEndWaiting { get; } + + public ITimer? TimeoutTimer { get; } // TODO TW: check this // NOTE: In order to avoid potential deadlocks, this task should @@ -256,5 +256,33 @@ private readonly record struct Waiter(Func ShouldEndWaiting // application code being woken up by the task could potentially // call back into the MetricCollector code and thus trigger a deadlock. public TaskCompletionSource TaskSource { get; } = new(); + + public Waiter(FakeLogCollector fakeLogCollector, Func shouldEndWaiting, TimeSpan? timeout) + { + // TODO TW: beautiful + var t = this; + + ShouldEndWaiting = shouldEndWaiting; + + // TODO TW: you need to stop the timer when you resolve the task from task source + TimeoutTimer = timeout.HasValue + ? fakeLogCollector.TimeProvider + .CreateTimer( + __ => + { + lock (fakeLogCollector._records) + { + _ = fakeLogCollector._waiters.Remove(t); // TODO TW: hmmmm, it's a copy i guess + } + + // trigger the task from outside the lock + _ = t.TaskSource.TrySetResult(false); + }, + null, + timeout.Value, + Timeout.InfiniteTimeSpan + ) + : null; + } } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 4c3c35afe44..1fa9636d526 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -204,6 +204,7 @@ private record WaitingTestCase( [InlineData(3)] [InlineData(4)] [InlineData(5)] + [InlineData(6)] public async Task Waiting(int testCase) { // Arrange @@ -240,7 +241,7 @@ bool EndWaiting(FakeLogRecord record) TimeSpan? timeout = testCaseData.TimeoutWaitInMs is null ? null - : new TimeSpan(testCaseData.TimeoutWaitInMs.Value); + : TimeSpan.FromMilliseconds(testCaseData.TimeoutWaitInMs.Value); var awaitingTask = collector.WaitForLogAsync(EndWaiting, timeout, cancellationTokenSource.Token); From 38c1d9aafece795c1fa1a9bb3551aa0264317993 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 31 Mar 2025 14:23:32 +0200 Subject: [PATCH 05/32] timeout capability --- .../Logging/FakeLogCollector.cs | 172 ++++++++++++------ .../Logging/FakeLogCollectorTests.cs | 10 +- 2 files changed, 120 insertions(+), 62 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 1f4556cb8f0..098c1d88043 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -4,10 +4,11 @@ using System; using System.Collections.Generic; using System.Diagnostics; -using System.Linq; +using System.Diagnostics.CodeAnalysis; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Options; +using Microsoft.Shared.DiagnosticIds; using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; @@ -119,20 +120,21 @@ public Task WaitForLogAsync( return WaitForLogAsync(endWaiting, null, cancellationToken); } - // TODO TW: add documentation - /// - /// + /// // TODO TW: add documentation + /// TODO TW: Placeholder /// - /// - /// - /// + /// TODO TW placeholder + /// TODO TW placeholder + /// TODO TW placeholder /// Task which is completed when the condition is fulfilled or when the cancellation is invoked + [Experimental(diagnosticId: DiagnosticIds.Experiments.TimeProvider, UrlFormat = DiagnosticIds.UrlFormat)] // TODO TW: << placeholder public Task WaitForLogAsync( Func endWaiting, TimeSpan? timeout, CancellationToken cancellationToken = default) { _ = Throw.IfNull(endWaiting); + _ = Throw.IfNull(cancellationToken); Waiter waiter; @@ -144,17 +146,13 @@ public Task WaitForLogAsync( return Task.FromResult(true); } - // Before we even start waiting, we checked if the cancellation token is already canceled and if yes, we exit early with a canceled task + // Before we even start waiting, we check if the cancellation token is already canceled and if yes, we exit early with a canceled task if (cancellationToken.IsCancellationRequested) { - var tcs = new TaskCompletionSource(); - _ = tcs.TrySetCanceled(cancellationToken); - return tcs.Task; + return Task.FromCanceled(cancellationToken); } // We register the waiter - - // TODO TW: flc also very nice waiter = new Waiter(this, endWaiting, timeout); _waiters.Add(waiter); } @@ -164,19 +162,16 @@ public Task WaitForLogAsync( // When the cancellation token is canceled, we resolve the waiter and cancel the awaited task _ = cancellationToken.Register(() => { - lock (_records) - { - _ = _waiters.Remove(waiter); - } + waiter.RemoveFromWaiting(); // trigger the task from outside the lock - // TODO TW: nice, but why outside precisely? - _ = waiter.TaskSource.TrySetCanceled(cancellationToken); + // TODO TW: I don't see it + waiter.ResolveByCancellation(cancellationToken); }); } #pragma warning disable VSTHRD003 // Avoid awaiting foreign Tasks - return waiter.TaskSource.Task; + return waiter.Task; #pragma warning restore VSTHRD003 // Avoid awaiting foreign Tasks } @@ -203,14 +198,21 @@ internal void AddRecord(FakeLogRecord record) return; } - List? waitersToWakeUp = null; + List? waitersToWakeUp; lock (_records) { _records.Add(record); - // TODO TW: To consider: - GatherWaitersForWaking(ref waitersToWakeUp, record); + Span waitersToWakeUpOrderedByIndices = stackalloc bool[_waiters.Count]; + CheckWaiting(record, waitersToWakeUpOrderedByIndices, out waitersToWakeUp); + for (var i = 0; i < waitersToWakeUpOrderedByIndices.Length; i++) + { + if (waitersToWakeUpOrderedByIndices[i]) + { + _waiters[i].RemoveFromWaiting(false); + } + } } if (waitersToWakeUp is not null) @@ -218,7 +220,7 @@ internal void AddRecord(FakeLogRecord record) foreach (var waiterToWakeUp in waitersToWakeUp) { // trigger the task from outside the lock - _ = waiterToWakeUp.TaskSource.TrySetResult(true); + waiterToWakeUp.ResolveByResult(true); } } @@ -226,8 +228,10 @@ internal void AddRecord(FakeLogRecord record) } // Must be called inside lock(_records) - private void GatherWaitersForWaking(ref List? waitersToWakeUp, FakeLogRecord currentlyLoggedRecord) + private void CheckWaiting(FakeLogRecord currentlyLoggedRecord, Span waitersToRemoveOrderedByIndices, out List? waitersToWakeUp) { + waitersToWakeUp = null; + for (var waiterIndex = _waiters.Count - 1; waiterIndex >= 0; waiterIndex--) { var waiter = _waiters[waiterIndex]; @@ -238,51 +242,109 @@ private void GatherWaitersForWaking(ref List? waitersToWakeUp, FakeLogRe waitersToWakeUp ??= []; waitersToWakeUp.Add(waiter); - _ = _waiters.Remove(waiter); + + waitersToRemoveOrderedByIndices[waiterIndex] = true; } } internal TimeProvider TimeProvider => _options.TimeProvider; - private readonly record struct Waiter + // TODO TW: I don't think we need/want record struct for this + // A) it is put into List so we don't benefit from structs ability to live on the stack + // B) I don't want to compare by fields/field-values, but rather by instance, so don't need record for this (or suboptimal struct for that matter) + private sealed class Waiter { + public Task Task => _taskSource.Task; public Func ShouldEndWaiting { get; } - public ITimer? TimeoutTimer { get; } - - // TODO TW: check this + // TODO TW: I don't see it // NOTE: In order to avoid potential deadlocks, this task should // be completed when the main lock is not being held. Otherwise, // application code being woken up by the task could potentially - // call back into the MetricCollector code and thus trigger a deadlock. - public TaskCompletionSource TaskSource { get; } = new(); + // call back into the FakeLogCollector code and thus trigger a deadlock. + private readonly TaskCompletionSource _taskSource; + + private readonly FakeLogCollector _fakeLogCollector; + + private readonly object _timerLock = new(); + private ITimer? _timeoutTimer; public Waiter(FakeLogCollector fakeLogCollector, Func shouldEndWaiting, TimeSpan? timeout) { - // TODO TW: beautiful - var t = this; - ShouldEndWaiting = shouldEndWaiting; - - // TODO TW: you need to stop the timer when you resolve the task from task source - TimeoutTimer = timeout.HasValue - ? fakeLogCollector.TimeProvider - .CreateTimer( - __ => - { - lock (fakeLogCollector._records) - { - _ = fakeLogCollector._waiters.Remove(t); // TODO TW: hmmmm, it's a copy i guess - } - - // trigger the task from outside the lock - _ = t.TaskSource.TrySetResult(false); - }, - null, - timeout.Value, - Timeout.InfiniteTimeSpan - ) - : null; + _fakeLogCollector = fakeLogCollector; + _taskSource = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + _timeoutTimer = timeout.HasValue ? CreateTimoutTimer(fakeLogCollector, timeout.Value) : null; + } + + public void RemoveFromWaiting(bool performUnderLock = true) + { + if (performUnderLock) + { + lock(_fakeLogCollector._records) + { + RemoveFromWaitingInternal(); + } + + return; + } + + RemoveFromWaitingInternal(); + } + + public void ResolveByResult(bool result) + { + StopTimer(); + _ = _taskSource.TrySetResult(result); + } + + public void ResolveByCancellation(CancellationToken cancellationToken) + { + StopTimer(); + _ = _taskSource.TrySetCanceled(cancellationToken); + } + + private void RemoveFromWaitingInternal() => _ = _fakeLogCollector._waiters.Remove(this); + + private void StopTimer() + { + lock (_timerLock) + { + if (_timeoutTimer is null) + { + return; + } + + try + { + _timeoutTimer.Dispose(); + } + catch (ObjectDisposedException) + { + // Timer was already disposed + } + finally + { + _timeoutTimer = null; + } + } + } + + private ITimer CreateTimoutTimer(FakeLogCollector fakeLogCollector, TimeSpan timeout) + { + return fakeLogCollector.TimeProvider + .CreateTimer( + _ => + { + RemoveFromWaiting(); + + // trigger the task from outside the lock + ResolveByResult(false); + }, + null, + timeout, // perform after + Timeout.InfiniteTimeSpan // don't repeat + ); } } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 1fa9636d526..87410272e61 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -204,7 +204,6 @@ private record WaitingTestCase( [InlineData(3)] [InlineData(4)] [InlineData(5)] - [InlineData(6)] public async Task Waiting(int testCase) { // Arrange @@ -349,8 +348,7 @@ private static List WaitingTestCases() "Background action has finished" ], true, - null) - ); + null)); // Waiting for single log record and supplying a cancellation period that would match three logs to get writer testCases.Add(new WaitingTestCase( @@ -365,8 +363,7 @@ private static List WaitingTestCases() "Background action has finished" ], false, - true) - ); + true)); // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. testCases.Add(new WaitingTestCase( @@ -382,8 +379,7 @@ private static List WaitingTestCases() "Background action has finished" ], false, - false) - ); + false)); return testCases; } From 84a5a3c3ff2837063fbdc305181a7669e68a976d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 31 Mar 2025 14:37:07 +0200 Subject: [PATCH 06/32] separate test cases into separate tests --- .../Logging/FakeLogCollectorTests.cs | 252 ++++++++++-------- 1 file changed, 143 insertions(+), 109 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 87410272e61..ecb63f7468b 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -197,19 +197,153 @@ private record WaitingTestCase( private const int WaitingTscOneLogTimeInMs = 250; private const string WaitingTscLogAttemptPrefix = "Log attempt"; - [Theory] - [InlineData(0)] - [InlineData(1)] - [InlineData(2)] - [InlineData(3)] - [InlineData(4)] - [InlineData(5)] - public async Task Waiting(int testCase) + [Fact] + public async Task Waiting_ForOneRecord() + { + // Arrange + var testCaseData = new WaitingTestCase( + 1, null, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished", + ], + false, + true); + + // Act, Assert + await WaitingInternal(testCaseData); + } + + [Fact] + public async Task Waiting_ForTwoRecords() + { + // Waiting for two records + + + // Arrange + var waitingTestCase = new WaitingTestCase( + 2, null, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + $"{WaitingTscLogAttemptPrefix} #002", + "Checking if waiting should end #2", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + true); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_CancellingBeforeWaitFulfilled() + { + // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. + + // Arrange + const int OneAndHalfRecordTime = WaitingTscOneLogTimeInMs + (WaitingTscOneLogTimeInMs / 2); + var waitingTestCase = new WaitingTestCase( + WaitingTscOverallLogCount + 1, OneAndHalfRecordTime, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + true, + null); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_StartingWaitWithCanceledToken() { + // Waiting for many log records, but starting with cancellation token already cancelled. + // Arrange + var waitingTestCase = new WaitingTestCase( + WaitingTscOverallLogCount, null, null, true, [ + "Started", + "Right after starting the background action", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #001", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + true, + null); - var testCaseData = WaitingTestCases()[testCase]; + // Act, Assert + await WaitingInternal(waitingTestCase); + } + [Fact] + public async Task Waiting_WithCancellationAfterWaitFulfilled() + { + // Waiting for single log record and supplying a cancellation period that would match three logs to get writer + + // Arrange + var waitingTestCase = new WaitingTestCase( + 1, 3 * WaitingTscOneLogTimeInMs, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + true); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_TimeoutBeforeWaitIsFulfilled() + { + // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. + + // Arrange + var waitingTestCase = new WaitingTestCase( + 3, null, (2 * WaitingTscOneLogTimeInMs) + (WaitingTscOneLogTimeInMs / 2), false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + $"{WaitingTscLogAttemptPrefix} #002", + "Checking if waiting should end #2", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + false); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + private async Task WaitingInternal(WaitingTestCase testCaseData) + { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); var logger = new FakeLogger(collector); @@ -283,104 +417,4 @@ bool EndWaiting(FakeLogRecord record) Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); Assert.Equal(taskCancelled, testCaseData.ExpectedTaskCancelled); } - - private static List WaitingTestCases() - { - var testCases = new List - { - // Waiting for one record - new WaitingTestCase( - 1, null, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished", - ], - false, - true), - - // Waiting for two records - new WaitingTestCase( - 2, null, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - false, - true) - }; - - // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. - const int OneAndHalfRecordTime = WaitingTscOneLogTimeInMs + (WaitingTscOneLogTimeInMs / 2); - testCases.Add(new WaitingTestCase( - WaitingTscOverallLogCount + 1, OneAndHalfRecordTime, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - true, - null)); - - // Waiting for many log records, but starting with cancellation token already cancelled. - testCases.Add(new WaitingTestCase( - WaitingTscOverallLogCount, null, null, true, [ - "Started", - "Right after starting the background action", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #001", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - true, - null)); - - // Waiting for single log record and supplying a cancellation period that would match three logs to get writer - testCases.Add(new WaitingTestCase( - 1, 3 * WaitingTscOneLogTimeInMs, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - false, - true)); - - // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. - testCases.Add(new WaitingTestCase( - 3, null, (2 * WaitingTscOneLogTimeInMs) + (WaitingTscOneLogTimeInMs / 2), false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - false, - false)); - - return testCases; - } } From 32d426e9048b34b069b6bf636462f01224816621 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 31 Mar 2025 14:38:26 +0200 Subject: [PATCH 07/32] cleanup --- .../Logging/FakeLogCollectorTests.cs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index ecb63f7468b..66dbad18b2a 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -200,6 +200,8 @@ private record WaitingTestCase( [Fact] public async Task Waiting_ForOneRecord() { + // Waiting for one record, fulfilling this wait + // Arrange var testCaseData = new WaitingTestCase( 1, null, null, false, [ @@ -222,8 +224,7 @@ public async Task Waiting_ForOneRecord() [Fact] public async Task Waiting_ForTwoRecords() { - // Waiting for two records - + // Waiting for two records, fulfilling this wait // Arrange var waitingTestCase = new WaitingTestCase( From 562db9518928f6ba46880d2020b3e37c37c29a10 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 31 Mar 2025 14:49:34 +0200 Subject: [PATCH 08/32] cleanup --- .../Logging/FakeLogCollector.cs | 12 ++++++------ .../Logging/FakeLogCollectorTests.cs | 1 - 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 098c1d88043..319b172e7f1 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -136,6 +136,12 @@ public Task WaitForLogAsync( _ = Throw.IfNull(endWaiting); _ = Throw.IfNull(cancellationToken); + // Before we even start waiting, we check if the cancellation token is already canceled and if yes, we exit early with a canceled task + if (cancellationToken.IsCancellationRequested) + { + return Task.FromCanceled(cancellationToken); + } + Waiter waiter; lock (_records) @@ -146,12 +152,6 @@ public Task WaitForLogAsync( return Task.FromResult(true); } - // Before we even start waiting, we check if the cancellation token is already canceled and if yes, we exit early with a canceled task - if (cancellationToken.IsCancellationRequested) - { - return Task.FromCanceled(cancellationToken); - } - // We register the waiter waiter = new Waiter(this, endWaiting, timeout); _waiters.Add(waiter); diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 66dbad18b2a..3ab71e7bf96 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -3,7 +3,6 @@ using System; using System.Collections.Concurrent; -using System.Collections.Generic; using System.Globalization; using System.Linq; using System.Threading; From aa9be3ff62af10ad96a3a5ad83acdf33b1270bf7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 15 May 2025 14:48:57 +0200 Subject: [PATCH 09/32] stackallock threshold + test run infrastructure timeout --- .../Logging/FakeLogCollector.cs | 7 +- .../Logging/FakeLogCollectorTests.cs | 131 +++++++++++------- 2 files changed, 84 insertions(+), 54 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 319b172e7f1..468982e91a1 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -20,6 +20,11 @@ namespace Microsoft.Extensions.Logging.Testing; [DebuggerTypeProxy(typeof(FakeLogCollectorDebugView))] public class FakeLogCollector { + /// + /// Arbitrary low number threshold for stack allocation path to avoid stack overflow. + /// + private const int StackAllocThreshold = 100; + private readonly List _records = []; private readonly FakeLogCollectorOptions _options; @@ -204,7 +209,7 @@ internal void AddRecord(FakeLogRecord record) { _records.Add(record); - Span waitersToWakeUpOrderedByIndices = stackalloc bool[_waiters.Count]; + Span waitersToWakeUpOrderedByIndices = _waiters.Count < StackAllocThreshold ? stackalloc bool[_waiters.Count]: new bool[_waiters.Count]; CheckWaiting(record, waitersToWakeUpOrderedByIndices, out waitersToWakeUp); for (var i = 0; i < waitersToWakeUpOrderedByIndices.Length; i++) { diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 3ab71e7bf96..671681d0593 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -7,6 +7,7 @@ using System.Linq; using System.Threading; using System.Threading.Tasks; +using FluentAssertions; using Microsoft.Extensions.Time.Testing; using Xunit; using Xunit.Abstractions; @@ -194,7 +195,7 @@ private record WaitingTestCase( private const int WaitingTscOverallLogCount = 3; private const int WaitingTscOneLogTimeInMs = 250; - private const string WaitingTscLogAttemptPrefix = "Log attempt"; + private const string WaitingTscLogAttemptPrefix = "Log"; [Fact] public async Task Waiting_ForOneRecord() @@ -344,77 +345,101 @@ public async Task Waiting_TimeoutBeforeWaitIsFulfilled() private async Task WaitingInternal(WaitingTestCase testCaseData) { - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + // Testing infrastructure: keeping track of when the implementation checks the users callback + var testExecutionCustomLog = new ConcurrentQueue(); + int callbackCallCounter = 0; + + // Testing infrastructure: capping the time of the test run + bool stoppedByInfrastructure = false; + const int TestRunCapMs = 2_000; + var testInfrastructureCircuitBreakerTask = Task.Run(() => + { + Thread.Sleep(TestRunCapMs); + stoppedByInfrastructure = true; + return false; + }, CancellationToken.None); + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); var logger = new FakeLogger(collector); - using var cancellationTokenSource = testCaseData.CancellationWaitInMs is not null + var userDefinedCancellation = testCaseData.CancellationWaitInMs is not null ? new CancellationTokenSource(TimeSpan.FromMilliseconds(testCaseData.CancellationWaitInMs.Value)) : new CancellationTokenSource(); - if (testCaseData.StartsWithCancelledToken) + using (userDefinedCancellation) { - cancellationTokenSource.Cancel(); - } - - var testExecutionCustomLog = new ConcurrentQueue(); - - int count = 0; + if (testCaseData.StartsWithCancelledToken) + { + await CancelTokenSource(userDefinedCancellation); + } - bool EndWaiting(FakeLogRecord record) - { - Interlocked.Increment(ref count); - testExecutionCustomLog.Enqueue("Checking if waiting should end #" + count); - return count == testCaseData.EndWaitAtAttemptCount; - } + bool UsersWaitingConditionCallback(FakeLogRecord record) + { + Interlocked.Increment(ref callbackCallCounter); + testExecutionCustomLog.Enqueue("Checking if waiting should end #" + callbackCallCounter); + return callbackCallCounter == testCaseData.EndWaitAtAttemptCount; + } - // Act + // Act - testExecutionCustomLog.Enqueue("Started"); + testExecutionCustomLog.Enqueue("Started"); - TimeSpan? timeout = testCaseData.TimeoutWaitInMs is null - ? null - : TimeSpan.FromMilliseconds(testCaseData.TimeoutWaitInMs.Value); + TimeSpan? timeout = testCaseData.TimeoutWaitInMs is null + ? null + : TimeSpan.FromMilliseconds(testCaseData.TimeoutWaitInMs.Value); - var awaitingTask = collector.WaitForLogAsync(EndWaiting, timeout, cancellationTokenSource.Token); + var awaitingTask = collector.WaitForLogAsync(UsersWaitingConditionCallback, timeout, userDefinedCancellation.Token); + var awaitingTaskWrapped = Task.WhenAny(awaitingTask, testInfrastructureCircuitBreakerTask); - var loggingBackgroundAction = Task.Run( - () => - { - for (var logAttempt = 1; logAttempt <= WaitingTscOverallLogCount; logAttempt++) + var loggingBackgroundAction = Task.Run( + () => { - Thread.Sleep(WaitingTscOneLogTimeInMs); - var message = $"{WaitingTscLogAttemptPrefix} #{logAttempt:000}"; - testExecutionCustomLog.Enqueue(message); - logger.LogDebug(message); - } - }, - CancellationToken.None); + for (var logAttempt = 1; logAttempt <= WaitingTscOverallLogCount; logAttempt++) + { + Thread.Sleep(WaitingTscOneLogTimeInMs); + var message = $"{WaitingTscLogAttemptPrefix} #{logAttempt:000}"; + testExecutionCustomLog.Enqueue(message); + logger.LogDebug(message); + } + }, + CancellationToken.None + ); + var loggingBackgroundActionWrapped = Task.WhenAny(loggingBackgroundAction, testInfrastructureCircuitBreakerTask); + + testExecutionCustomLog.Enqueue("Right after starting the background action"); + + bool? result = null; + bool taskCancelled = false; + + try + { + result = await await awaitingTaskWrapped; + } + catch (TaskCanceledException) + { + taskCancelled = true; + } - testExecutionCustomLog.Enqueue("Right after starting the background action"); + testExecutionCustomLog.Enqueue("Finished waiting for the log. Waiting for the background action to finish."); - bool? result = null; - bool taskCancelled = false; + await await loggingBackgroundActionWrapped; - try - { - result = await awaitingTask; - } - catch (TaskCanceledException) - { - taskCancelled = true; - } + testExecutionCustomLog.Enqueue("Background action has finished"); - testExecutionCustomLog.Enqueue("Finished waiting for the log. Waiting for the background action to finish."); - - await loggingBackgroundAction; + // Assert + Assert.False(stoppedByInfrastructure, "None of the test cases is expected to reach test infrastructure timeout"); + Assert.Equal(result, testCaseData.ExpectedAwaitedTaskResult); + testExecutionCustomLog.Should().Equal(testCaseData.ExpectedOperationSequence); + Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); + Assert.Equal(taskCancelled, testCaseData.ExpectedTaskCancelled); + } - testExecutionCustomLog.Enqueue("Background action has finished"); + async Task CancelTokenSource(CancellationTokenSource cts) => +#if NET8_0_OR_GREATER + await cts.CancelAsync(); +#else + cts.Cancel(); +#endif - // Assert - Assert.Equal(result, testCaseData.ExpectedAwaitedTaskResult); - Assert.True(testExecutionCustomLog.SequenceEqual(testCaseData.ExpectedOperationSequence)); - Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); - Assert.Equal(taskCancelled, testCaseData.ExpectedTaskCancelled); } } From 9332616fae9fd74a3fc5d95c0331aa3e14542559 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Fri, 16 May 2025 12:13:04 +0200 Subject: [PATCH 10/32] fake time provider based tests instead of real time --- .../Logging/FakeLogCollector.cs | 21 +- .../Logging/FakeLogCollectorTests.Waiting.cs | 304 ++++++++++++++++++ .../Logging/FakeLogCollectorTests.cs | 267 +-------------- 3 files changed, 319 insertions(+), 273 deletions(-) create mode 100644 test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 468982e91a1..e97eb4461d9 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -117,7 +117,12 @@ public FakeLogRecord LatestRecord /// public int Count => _records.Count; - + /// + /// Allows waiting for the point in time in which a newly processed log record fulfilled custom condition supplied by the caller. + /// + /// Custom condition terminating waiting upon fulfillment. + /// Token based cancellation of the waiting. + /// Awaitable task that completes upon condition fulfillment, timeout expiration or cancellation. public Task WaitForLogAsync( Func endWaiting, CancellationToken cancellationToken = default) @@ -125,13 +130,13 @@ public Task WaitForLogAsync( return WaitForLogAsync(endWaiting, null, cancellationToken); } - /// // TODO TW: add documentation - /// TODO TW: Placeholder + /// + /// Allows waiting for the point in time in which a newly processed log record fulfilled custom condition supplied by the caller. /// - /// TODO TW placeholder + /// Custom condition terminating waiting upon fulfillment. /// TODO TW placeholder - /// TODO TW placeholder - /// Task which is completed when the condition is fulfilled or when the cancellation is invoked + /// Token based cancellation of the waiting. + /// Awaitable task that completes upon condition fulfillment, timeout expiration or cancellation. [Experimental(diagnosticId: DiagnosticIds.Experiments.TimeProvider, UrlFormat = DiagnosticIds.UrlFormat)] // TODO TW: << placeholder public Task WaitForLogAsync( Func endWaiting, @@ -209,7 +214,9 @@ internal void AddRecord(FakeLogRecord record) { _records.Add(record); - Span waitersToWakeUpOrderedByIndices = _waiters.Count < StackAllocThreshold ? stackalloc bool[_waiters.Count]: new bool[_waiters.Count]; + Span waitersToWakeUpOrderedByIndices = _waiters.Count < StackAllocThreshold + ? stackalloc bool[_waiters.Count] + : new bool[_waiters.Count]; CheckWaiting(record, waitersToWakeUpOrderedByIndices, out waitersToWakeUp); for (var i = 0; i < waitersToWakeUpOrderedByIndices.Length; i++) { diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs new file mode 100644 index 00000000000..f3bd7305a7b --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -0,0 +1,304 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Concurrent; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using FluentAssertions; +using Microsoft.Extensions.Time.Testing; +using Xunit; + +namespace Microsoft.Extensions.Logging.Testing.Test.Logging; + +public partial class FakeLogCollectorTests +{ + private record WaitingTestCase( + int EndWaitAtAttemptCount, + double? CancellationAfterLogAttemptCount, + double? TimeoutAfterLogAttemptCount, + bool StartsWithCancelledToken, + string[] ExpectedOperationSequence, + bool ExpectedTaskCancelled, + bool? ExpectedAwaitedTaskResult + ); + + private const int WaitingTscOverallLogCount = 3; + private const int LogAttemptHalfTimePeriod = 250; + private const int LogAttemptFullTimePeriod = LogAttemptHalfTimePeriod * 2; + private const string WaitingTscLogAttemptPrefix = "Log"; + + [Fact] + public async Task Waiting_ForOneRecord() + { + // Waiting for one record, fulfilling this wait + + // Arrange + var testCaseData = new WaitingTestCase( + 1, null, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished", + ], + false, + true); + + // Act, Assert + await WaitingInternal(testCaseData); + } + + [Fact] + public async Task Waiting_ForTwoRecords() + { + // Waiting for two records, fulfilling this wait + + // Arrange + var waitingTestCase = new WaitingTestCase( + 2, null, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + $"{WaitingTscLogAttemptPrefix} #002", + "Checking if waiting should end #2", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + true); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_CancellingBeforeWaitFulfilled() + { + // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. + + // Arrange + var waitingTestCase = new WaitingTestCase( + WaitingTscOverallLogCount + 1, 1.5, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + true, + null); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_StartingWaitWithCanceledToken() + { + // Waiting for many log records, but starting with cancellation token already cancelled. + + // Arrange + var waitingTestCase = new WaitingTestCase( + WaitingTscOverallLogCount, null, null, true, [ + "Started", + "Right after starting the background action", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #001", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + true, + null); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_WithCancellationAfterWaitFulfilled() + { + // Waiting for single log record and supplying a cancellation period that would match three logs to get writer + + // Arrange + var waitingTestCase = new WaitingTestCase( + 1, 3 * LogAttemptFullTimePeriod, null, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #002", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + true); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + [Fact] + public async Task Waiting_TimeoutBeforeWaitIsFulfilled() + { + // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. + + // Arrange + var waitingTestCase = new WaitingTestCase( + 3, null, 2.5, false, [ + "Started", + "Right after starting the background action", + $"{WaitingTscLogAttemptPrefix} #001", + "Checking if waiting should end #1", + $"{WaitingTscLogAttemptPrefix} #002", + "Checking if waiting should end #2", + "Finished waiting for the log. Waiting for the background action to finish.", + $"{WaitingTscLogAttemptPrefix} #003", + "Background action has finished" + ], + false, + false); + + // Act, Assert + await WaitingInternal(waitingTestCase); + } + + private async Task WaitingInternal(WaitingTestCase testCaseData) + { + // Testing infrastructure: capping the time of the test run + bool stoppedByInfrastructure = false; + const int TestRunCapMs = 2_000; + using var circuitBreakerCts = new CancellationTokenSource(); + var testInfrastructureCircuitBreakerTask = Task.Run(async () => + { + await Task.Delay(TestRunCapMs, CancellationToken.None); + stoppedByInfrastructure = true; + return false; + }, circuitBreakerCts.Token); + + // Wrapped test case run + await await Task.WhenAny(WaitingInternalCore(testCaseData), testInfrastructureCircuitBreakerTask); + + // Test infrastructure assert + Assert.False(stoppedByInfrastructure, "None of the test cases is expected to reach test infrastructure timeout"); + circuitBreakerCts.Cancel(); // avoid resource leaking when core task finishes first + } + + private async Task WaitingInternalCore(WaitingTestCase testCaseData) + { + // Testing infrastructure: keeping track of when the implementation checks the users callback + var testExecutionCustomLog = new ConcurrentQueue(); + int callbackCallCounter = 0; + const int AllLogAttemptsInHalfPeriods = WaitingTscOverallLogCount * 2; + var fakeTimeProvider = new FakeTimeProvider(); + + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions {TimeProvider = fakeTimeProvider }); + var logger = new FakeLogger(collector); + + bool UserDefinedWaitingCondition(FakeLogRecord record) + { + Interlocked.Increment(ref callbackCallCounter); + testExecutionCustomLog.Enqueue("Checking if waiting should end #" + callbackCallCounter); + return callbackCallCounter == testCaseData.EndWaitAtAttemptCount; + } + + TimeSpan? userDefinedTimeout = testCaseData.TimeoutAfterLogAttemptCount is null + ? null + : TimeSpan.FromMilliseconds(LogAttemptFullTimePeriod * testCaseData.TimeoutAfterLogAttemptCount.Value); + + var userDefinedCancellation = testCaseData.CancellationAfterLogAttemptCount.HasValue + ? CreateCtsWithTimeProvider(TimeSpan.FromMilliseconds(LogAttemptFullTimePeriod * testCaseData.CancellationAfterLogAttemptCount.Value), fakeTimeProvider) + : new CancellationTokenSource(); + + using (userDefinedCancellation) + { + if (testCaseData.StartsWithCancelledToken) + { +#if NET8_0_OR_GREATER + await CancelTokenSource(userDefinedCancellation); +#else + CancelTokenSource(userDefinedCancellation); +#endif + } + + // Act + + testExecutionCustomLog.Enqueue("Started"); + + var awaitingTask = collector.WaitForLogAsync(UserDefinedWaitingCondition, userDefinedTimeout, userDefinedCancellation.Token); + + var loggingBackgroundAction = Task.Run( + async () => + { + // Simulating time progression in half-time periods to allow for mid-period timeout waiting completions + for (var logAttemptHalfPeriodCount = 1; logAttemptHalfPeriodCount <= AllLogAttemptsInHalfPeriods; logAttemptHalfPeriodCount++) + { + await Task.Delay(100, CancellationToken.None); // even though the test is not real time-based, we need to give room for the parallel post task completion operations + fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(LogAttemptHalfTimePeriod)); + + var logAttemptPeriodReached = logAttemptHalfPeriodCount % 2 == 0; + if (logAttemptPeriodReached) + { + var logAttemptNumber = logAttemptHalfPeriodCount / 2; + var logMessage = $"{WaitingTscLogAttemptPrefix} #{logAttemptNumber:000}"; + testExecutionCustomLog.Enqueue(logMessage); // Testing infrastructure log + logger.LogDebug(logMessage); // Actual log + } + } + }, + CancellationToken.None); + + testExecutionCustomLog.Enqueue("Right after starting the background action"); + + bool? result = null; + bool taskCancelled = false; + + try + { + result = await awaitingTask; + } + catch (TaskCanceledException) + { + taskCancelled = true; + } + + testExecutionCustomLog.Enqueue("Finished waiting for the log. Waiting for the background action to finish."); + + await loggingBackgroundAction; + + testExecutionCustomLog.Enqueue("Background action has finished"); + + // Assert + Assert.Equal(testCaseData.ExpectedAwaitedTaskResult, result); + testExecutionCustomLog.Should().Equal(testCaseData.ExpectedOperationSequence); + Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); + Assert.Equal(testCaseData.ExpectedTaskCancelled, taskCancelled); + } + } + +#if NET8_0_OR_GREATER + async Task CancelTokenSource(CancellationTokenSource cts) => await cts.CancelAsync(); +#else + void CancelTokenSource(CancellationTokenSource cts) => cts.Cancel(); +#endif + + CancellationTokenSource CreateCtsWithTimeProvider(TimeSpan timeSpan, TimeProvider timeProvider) + { +#if NET8_0_OR_GREATER + return new CancellationTokenSource(timeSpan, timeProvider); +#else + return timeProvider.CreateCancellationTokenSource(timeSpan); +#endif + } +} diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs index 671681d0593..63ce2a7e718 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -2,19 +2,14 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; -using System.Collections.Concurrent; using System.Globalization; -using System.Linq; -using System.Threading; -using System.Threading.Tasks; -using FluentAssertions; using Microsoft.Extensions.Time.Testing; using Xunit; using Xunit.Abstractions; namespace Microsoft.Extensions.Logging.Testing.Test.Logging; -public class FakeLogCollectorTests +public partial class FakeLogCollectorTests { private class Output : ITestOutputHelper { @@ -182,264 +177,4 @@ public void TestOutputHelperExtensionsGeneric() logger.Log((LogLevel)42, "Hello world!"); Assert.Contains("invld] Hello world!", output.Last); } - - private record WaitingTestCase( - int EndWaitAtAttemptCount, - int? CancellationWaitInMs, - int? TimeoutWaitInMs, - bool StartsWithCancelledToken, - string[] ExpectedOperationSequence, - bool ExpectedTaskCancelled, - bool? ExpectedAwaitedTaskResult - ); - - private const int WaitingTscOverallLogCount = 3; - private const int WaitingTscOneLogTimeInMs = 250; - private const string WaitingTscLogAttemptPrefix = "Log"; - - [Fact] - public async Task Waiting_ForOneRecord() - { - // Waiting for one record, fulfilling this wait - - // Arrange - var testCaseData = new WaitingTestCase( - 1, null, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished", - ], - false, - true); - - // Act, Assert - await WaitingInternal(testCaseData); - } - - [Fact] - public async Task Waiting_ForTwoRecords() - { - // Waiting for two records, fulfilling this wait - - // Arrange - var waitingTestCase = new WaitingTestCase( - 2, null, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - false, - true); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } - - [Fact] - public async Task Waiting_CancellingBeforeWaitFulfilled() - { - // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. - - // Arrange - const int OneAndHalfRecordTime = WaitingTscOneLogTimeInMs + (WaitingTscOneLogTimeInMs / 2); - var waitingTestCase = new WaitingTestCase( - WaitingTscOverallLogCount + 1, OneAndHalfRecordTime, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - true, - null); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } - - [Fact] - public async Task Waiting_StartingWaitWithCanceledToken() - { - // Waiting for many log records, but starting with cancellation token already cancelled. - - // Arrange - var waitingTestCase = new WaitingTestCase( - WaitingTscOverallLogCount, null, null, true, [ - "Started", - "Right after starting the background action", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #001", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - true, - null); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } - - [Fact] - public async Task Waiting_WithCancellationAfterWaitFulfilled() - { - // Waiting for single log record and supplying a cancellation period that would match three logs to get writer - - // Arrange - var waitingTestCase = new WaitingTestCase( - 1, 3 * WaitingTscOneLogTimeInMs, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - false, - true); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } - - [Fact] - public async Task Waiting_TimeoutBeforeWaitIsFulfilled() - { - // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. - - // Arrange - var waitingTestCase = new WaitingTestCase( - 3, null, (2 * WaitingTscOneLogTimeInMs) + (WaitingTscOneLogTimeInMs / 2), false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" - ], - false, - false); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } - - private async Task WaitingInternal(WaitingTestCase testCaseData) - { - // Testing infrastructure: keeping track of when the implementation checks the users callback - var testExecutionCustomLog = new ConcurrentQueue(); - int callbackCallCounter = 0; - - // Testing infrastructure: capping the time of the test run - bool stoppedByInfrastructure = false; - const int TestRunCapMs = 2_000; - var testInfrastructureCircuitBreakerTask = Task.Run(() => - { - Thread.Sleep(TestRunCapMs); - stoppedByInfrastructure = true; - return false; - }, CancellationToken.None); - - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var logger = new FakeLogger(collector); - - var userDefinedCancellation = testCaseData.CancellationWaitInMs is not null - ? new CancellationTokenSource(TimeSpan.FromMilliseconds(testCaseData.CancellationWaitInMs.Value)) - : new CancellationTokenSource(); - - using (userDefinedCancellation) - { - if (testCaseData.StartsWithCancelledToken) - { - await CancelTokenSource(userDefinedCancellation); - } - - bool UsersWaitingConditionCallback(FakeLogRecord record) - { - Interlocked.Increment(ref callbackCallCounter); - testExecutionCustomLog.Enqueue("Checking if waiting should end #" + callbackCallCounter); - return callbackCallCounter == testCaseData.EndWaitAtAttemptCount; - } - - // Act - - testExecutionCustomLog.Enqueue("Started"); - - TimeSpan? timeout = testCaseData.TimeoutWaitInMs is null - ? null - : TimeSpan.FromMilliseconds(testCaseData.TimeoutWaitInMs.Value); - - var awaitingTask = collector.WaitForLogAsync(UsersWaitingConditionCallback, timeout, userDefinedCancellation.Token); - var awaitingTaskWrapped = Task.WhenAny(awaitingTask, testInfrastructureCircuitBreakerTask); - - var loggingBackgroundAction = Task.Run( - () => - { - for (var logAttempt = 1; logAttempt <= WaitingTscOverallLogCount; logAttempt++) - { - Thread.Sleep(WaitingTscOneLogTimeInMs); - var message = $"{WaitingTscLogAttemptPrefix} #{logAttempt:000}"; - testExecutionCustomLog.Enqueue(message); - logger.LogDebug(message); - } - }, - CancellationToken.None - ); - var loggingBackgroundActionWrapped = Task.WhenAny(loggingBackgroundAction, testInfrastructureCircuitBreakerTask); - - testExecutionCustomLog.Enqueue("Right after starting the background action"); - - bool? result = null; - bool taskCancelled = false; - - try - { - result = await await awaitingTaskWrapped; - } - catch (TaskCanceledException) - { - taskCancelled = true; - } - - testExecutionCustomLog.Enqueue("Finished waiting for the log. Waiting for the background action to finish."); - - await await loggingBackgroundActionWrapped; - - testExecutionCustomLog.Enqueue("Background action has finished"); - - // Assert - Assert.False(stoppedByInfrastructure, "None of the test cases is expected to reach test infrastructure timeout"); - Assert.Equal(result, testCaseData.ExpectedAwaitedTaskResult); - testExecutionCustomLog.Should().Equal(testCaseData.ExpectedOperationSequence); - Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); - Assert.Equal(taskCancelled, testCaseData.ExpectedTaskCancelled); - } - - async Task CancelTokenSource(CancellationTokenSource cts) => -#if NET8_0_OR_GREATER - await cts.CancelAsync(); -#else - cts.Cancel(); -#endif - - } } From 45d9eafabac725da1eed9d377437525783a68501 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Tue, 20 May 2025 15:46:05 +0200 Subject: [PATCH 11/32] enriching test cases by logs before awaiting and between interesting log attempts --- .../Logging/FakeLogCollectorTests.Waiting.cs | 182 ++++++++++++------ 1 file changed, 122 insertions(+), 60 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index f3bd7305a7b..39fe69ae690 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -27,7 +27,16 @@ private record WaitingTestCase( private const int WaitingTscOverallLogCount = 3; private const int LogAttemptHalfTimePeriod = 250; private const int LogAttemptFullTimePeriod = LogAttemptHalfTimePeriod * 2; - private const string WaitingTscLogAttemptPrefix = "Log"; + + /* Testing infrastructure messages */ + private const string StartedWaitingMessage = "Started awaiting"; + private const string AfterStartingBackgroundActionMessage = "Right after starting the background action"; + private const string CheckingWaitingCallbackMessagePrefix = "Checking if waiting should end"; + private const string BackgroundActionFinishedMessage = "Background action has finished"; + private const string FinishedWaitingMessage = "Finished waiting for the log. Waiting for the background action to finish."; + + private const string AwaitedLogMessagePrefix = "Awaited log message"; + private const string IrrelevantLogMessage = "Irrelevant log message"; [Fact] public async Task Waiting_ForOneRecord() @@ -37,14 +46,20 @@ public async Task Waiting_ForOneRecord() // Arrange var testCaseData = new WaitingTestCase( 1, null, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished", + IrrelevantLogMessage, // log message before start of waiting + StartedWaitingMessage, + $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled + AfterStartingBackgroundActionMessage, + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #002", + $"{AwaitedLogMessagePrefix} #001", + $"{CheckingWaitingCallbackMessagePrefix} #003", + FinishedWaitingMessage, + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #002", + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #003", + BackgroundActionFinishedMessage, ], false, true); @@ -61,15 +76,22 @@ public async Task Waiting_ForTwoRecords() // Arrange var waitingTestCase = new WaitingTestCase( 2, null, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" + IrrelevantLogMessage, // log message before start of waiting + StartedWaitingMessage, + $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled + AfterStartingBackgroundActionMessage, + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #002", + $"{AwaitedLogMessagePrefix} #001", + $"{CheckingWaitingCallbackMessagePrefix} #003", + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #004", + $"{AwaitedLogMessagePrefix} #002", + $"{CheckingWaitingCallbackMessagePrefix} #005", + FinishedWaitingMessage, + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #003", + BackgroundActionFinishedMessage, ], false, true); @@ -86,14 +108,20 @@ public async Task Waiting_CancellingBeforeWaitFulfilled() // Arrange var waitingTestCase = new WaitingTestCase( WaitingTscOverallLogCount + 1, 1.5, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" + IrrelevantLogMessage, // log message before start of waiting + StartedWaitingMessage, + $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled + AfterStartingBackgroundActionMessage, + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #002", + $"{AwaitedLogMessagePrefix} #001", + $"{CheckingWaitingCallbackMessagePrefix} #003", + IrrelevantLogMessage, // different message logged each half period + FinishedWaitingMessage, + $"{AwaitedLogMessagePrefix} #002", + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #003", + BackgroundActionFinishedMessage ], true, null); @@ -110,13 +138,17 @@ public async Task Waiting_StartingWaitWithCanceledToken() // Arrange var waitingTestCase = new WaitingTestCase( WaitingTscOverallLogCount, null, null, true, [ - "Started", - "Right after starting the background action", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #001", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" + IrrelevantLogMessage, // log message before start of waiting + StartedWaitingMessage, + AfterStartingBackgroundActionMessage, + FinishedWaitingMessage, + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #001", + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #002", + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #003", + BackgroundActionFinishedMessage ], true, null); @@ -133,14 +165,20 @@ public async Task Waiting_WithCancellationAfterWaitFulfilled() // Arrange var waitingTestCase = new WaitingTestCase( 1, 3 * LogAttemptFullTimePeriod, null, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #002", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" + IrrelevantLogMessage, // log message before start of waiting + StartedWaitingMessage, + $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled + AfterStartingBackgroundActionMessage, + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #002", + $"{AwaitedLogMessagePrefix} #001", + $"{CheckingWaitingCallbackMessagePrefix} #003", + FinishedWaitingMessage, + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #002", + IrrelevantLogMessage, // different message logged each half period + $"{AwaitedLogMessagePrefix} #003", + BackgroundActionFinishedMessage, ], false, true); @@ -157,15 +195,22 @@ public async Task Waiting_TimeoutBeforeWaitIsFulfilled() // Arrange var waitingTestCase = new WaitingTestCase( 3, null, 2.5, false, [ - "Started", - "Right after starting the background action", - $"{WaitingTscLogAttemptPrefix} #001", - "Checking if waiting should end #1", - $"{WaitingTscLogAttemptPrefix} #002", - "Checking if waiting should end #2", - "Finished waiting for the log. Waiting for the background action to finish.", - $"{WaitingTscLogAttemptPrefix} #003", - "Background action has finished" + IrrelevantLogMessage, // log message before start of waiting + StartedWaitingMessage, + $"{CheckingWaitingCallbackMessagePrefix} #001", + AfterStartingBackgroundActionMessage, + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #002", + $"{AwaitedLogMessagePrefix} #001", + $"{CheckingWaitingCallbackMessagePrefix} #003", + IrrelevantLogMessage, // different message logged each half period + $"{CheckingWaitingCallbackMessagePrefix} #004", + $"{AwaitedLogMessagePrefix} #002", + $"{CheckingWaitingCallbackMessagePrefix} #005", + IrrelevantLogMessage, // different message logged each half period + FinishedWaitingMessage, + $"{AwaitedLogMessagePrefix} #003", + BackgroundActionFinishedMessage ], false, false); @@ -200,17 +245,24 @@ private async Task WaitingInternalCore(WaitingTestCase testCaseData) // Testing infrastructure: keeping track of when the implementation checks the users callback var testExecutionCustomLog = new ConcurrentQueue(); int callbackCallCounter = 0; + int awaitedLogMessageCount = 0; const int AllLogAttemptsInHalfPeriods = WaitingTscOverallLogCount * 2; var fakeTimeProvider = new FakeTimeProvider(); - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions {TimeProvider = fakeTimeProvider }); + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions { TimeProvider = fakeTimeProvider }); var logger = new FakeLogger(collector); bool UserDefinedWaitingCondition(FakeLogRecord record) { - Interlocked.Increment(ref callbackCallCounter); - testExecutionCustomLog.Enqueue("Checking if waiting should end #" + callbackCallCounter); - return callbackCallCounter == testCaseData.EndWaitAtAttemptCount; + callbackCallCounter++; + testExecutionCustomLog.Enqueue($"{CheckingWaitingCallbackMessagePrefix} #{callbackCallCounter:000}"); + + if (record.Message.StartsWith(AwaitedLogMessagePrefix)) + { + awaitedLogMessageCount++; + } + + return awaitedLogMessageCount == testCaseData.EndWaitAtAttemptCount; } TimeSpan? userDefinedTimeout = testCaseData.TimeoutAfterLogAttemptCount is null @@ -233,8 +285,10 @@ bool UserDefinedWaitingCondition(FakeLogRecord record) } // Act + logger.LogDebug(IrrelevantLogMessage); + testExecutionCustomLog.Enqueue(IrrelevantLogMessage); - testExecutionCustomLog.Enqueue("Started"); + testExecutionCustomLog.Enqueue("Started awaiting"); var awaitingTask = collector.WaitForLogAsync(UserDefinedWaitingCondition, userDefinedTimeout, userDefinedCancellation.Token); @@ -251,15 +305,20 @@ bool UserDefinedWaitingCondition(FakeLogRecord record) if (logAttemptPeriodReached) { var logAttemptNumber = logAttemptHalfPeriodCount / 2; - var logMessage = $"{WaitingTscLogAttemptPrefix} #{logAttemptNumber:000}"; + var logMessage = $"{AwaitedLogMessagePrefix} #{logAttemptNumber:000}"; testExecutionCustomLog.Enqueue(logMessage); // Testing infrastructure log logger.LogDebug(logMessage); // Actual log } + else + { + testExecutionCustomLog.Enqueue(IrrelevantLogMessage); // Testing infrastructure log + logger.LogDebug(IrrelevantLogMessage); + } } }, CancellationToken.None); - testExecutionCustomLog.Enqueue("Right after starting the background action"); + testExecutionCustomLog.Enqueue(AfterStartingBackgroundActionMessage); bool? result = null; bool taskCancelled = false; @@ -273,16 +332,19 @@ bool UserDefinedWaitingCondition(FakeLogRecord record) taskCancelled = true; } - testExecutionCustomLog.Enqueue("Finished waiting for the log. Waiting for the background action to finish."); + testExecutionCustomLog.Enqueue(FinishedWaitingMessage); await loggingBackgroundAction; - testExecutionCustomLog.Enqueue("Background action has finished"); + testExecutionCustomLog.Enqueue(BackgroundActionFinishedMessage); // Assert Assert.Equal(testCaseData.ExpectedAwaitedTaskResult, result); testExecutionCustomLog.Should().Equal(testCaseData.ExpectedOperationSequence); - Assert.Equal(testExecutionCustomLog.Count(r => r.StartsWith(WaitingTscLogAttemptPrefix)), logger.Collector.Count); + Assert.Equal( + testExecutionCustomLog.Count(r => r.StartsWith(AwaitedLogMessagePrefix)), + logger.Collector.GetSnapshot().Count(r => r.Message.StartsWith(AwaitedLogMessagePrefix)) + ); Assert.Equal(testCaseData.ExpectedTaskCancelled, taskCancelled); } } From 985ed4617bb8e266bfce199466364aae1fdf0f70 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Wed, 20 Aug 2025 12:23:26 +0200 Subject: [PATCH 12/32] continue with enumeration --- .../FakeLogCollector.LogEnumeration.cs | 160 ++++++++++++++++++ .../Logging/FakeLogCollector.cs | 14 +- .../Logging/FakeLogCollectorTests.Waiting.cs | 2 + .../Logging/FakeLogCollectorTests.Waiting2.cs | 91 ++++++++++ 4 files changed, 266 insertions(+), 1 deletion(-) create mode 100644 src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs create mode 100644 test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs new file mode 100644 index 00000000000..35bd655661e --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -0,0 +1,160 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Threading; +using System.Threading.Tasks; + +namespace Microsoft.Extensions.Logging.Testing; + +public partial class FakeLogCollector +{ + private readonly List> _streamWaiters = []; + + public IAsyncEnumerable GetLogsAsync( + bool continueOnMultipleEnumerations = false, + CancellationToken cancellationToken = default) + => new LogAsyncEnumerable(continueOnMultipleEnumerations, this, cancellationToken); + + private class LogAsyncEnumerable : IAsyncEnumerable + { + internal readonly object EnumeratorLock = new(); + internal int LastIndex; + internal StreamEnumerator? Enumerator; + + private readonly bool _continueOnMultipleEnumerations; + private readonly FakeLogCollector _collector; + private readonly CancellationToken _externalToken; + + internal LogAsyncEnumerable( + bool continueOnMultipleEnumerations, + FakeLogCollector collector, + CancellationToken externalToken) + { + _continueOnMultipleEnumerations = continueOnMultipleEnumerations; + _collector = collector; + _externalToken = externalToken; + } + + public IAsyncEnumerator GetAsyncEnumerator(CancellationToken cancellationToken = default) + { + lock (EnumeratorLock) + { + int startingPos = _continueOnMultipleEnumerations ? LastIndex : 0; + + var linked = CancellationTokenSource.CreateLinkedTokenSource(_externalToken, cancellationToken); + Enumerator = new StreamEnumerator( + startingPos, + this, + _collector, + linked); + } + + return Enumerator; + } + } + + private sealed class StreamEnumerator : IAsyncEnumerator + { + internal int Index; + private readonly LogAsyncEnumerable _logAsyncEnumerable; + + private readonly FakeLogCollector _collector; + private readonly CancellationTokenSource _cts; + private readonly CancellationToken _cancellationToken; + private TaskCompletionSource? _waitingTsc; + private bool _disposed; + private FakeLogRecord? _current; + + public StreamEnumerator( + int startingPos, + LogAsyncEnumerable logAsyncEnumerable, + FakeLogCollector collector, + CancellationTokenSource cts) + { + _collector = collector; + _cts = cts; + _cancellationToken = cts.Token; + Index = startingPos; + _logAsyncEnumerable = logAsyncEnumerable; + } + + public FakeLogRecord Current => _current ?? throw new InvalidOperationException("Enumeration not started."); + + public async ValueTask MoveNextAsync() + { + ThrowIfDisposed(); + + while (true) + { + _cancellationToken.ThrowIfCancellationRequested(); + + lock (_collector._records) + { + if (Index < _collector._records.Count) + { + _logAsyncEnumerable.LastIndex = Index; + _current = _collector._records[Index++]; + return true; + } + + _waitingTsc ??= new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + _collector._streamWaiters.Add(_waitingTsc); + } + + try + { + await (_waitingTsc?.Task ?? Task.CompletedTask).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + return false; + } + finally + { + _waitingTsc = null; + } + } + } + + public ValueTask DisposeAsync() + { + if (_disposed) + { + return default; + } + + _disposed = true; + + _cts.Cancel(); + + if (_waitingTsc is not null) + { + lock (_collector._records) + { + _ = _collector._streamWaiters.Remove(_waitingTsc); + } + + _ = _waitingTsc.TrySetCanceled(_cancellationToken); + } + + _cts.Dispose(); + + lock (_logAsyncEnumerable.EnumeratorLock) + { + _logAsyncEnumerable.Enumerator = null; + } + + return default; + } + + private void ThrowIfDisposed() + { + if (_disposed) + { + throw new ObjectDisposedException(nameof(StreamEnumerator)); + } + } + } +} diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 004ae35da4c..8f1009910fa 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -18,7 +18,7 @@ namespace Microsoft.Extensions.Logging.Testing; /// [DebuggerDisplay("Count = {Count}, LatestRecord = {LatestRecord}")] [DebuggerTypeProxy(typeof(FakeLogCollectorDebugView))] -public class FakeLogCollector +public partial class FakeLogCollector { /// /// Arbitrary low number threshold for stack allocation path to avoid stack overflow. @@ -216,6 +216,7 @@ internal void AddRecord(FakeLogRecord record) } List? waitersToWakeUp; + List>? streamWaitersToWake; lock (_records) { @@ -232,6 +233,8 @@ internal void AddRecord(FakeLogRecord record) _waiters[i].RemoveFromWaiting(false); } } + + streamWaitersToWake = _streamWaiters.Count > 0 ? [.._streamWaiters] : null; } if (waitersToWakeUp is not null) @@ -243,6 +246,15 @@ internal void AddRecord(FakeLogRecord record) } } + if (streamWaitersToWake is not null) + { + foreach (var streamWaiterToWake in streamWaitersToWake) + { + _ = streamWaiterToWake.TrySetResult(true); // it is possible the task was already completed, but it does not matter and we can avoid locking + _ = _streamWaiters.Remove(streamWaiterToWake); + } + } + _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 39fe69ae690..7d7dda357c7 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -3,12 +3,14 @@ using System; using System.Collections.Concurrent; +using System.Collections.Generic; using System.Linq; using System.Threading; using System.Threading.Tasks; using FluentAssertions; using Microsoft.Extensions.Time.Testing; using Xunit; +using Xunit.Abstractions; namespace Microsoft.Extensions.Logging.Testing.Test.Logging; diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs new file mode 100644 index 00000000000..7de23d08d6d --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs @@ -0,0 +1,91 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using FluentAssertions; +using Microsoft.Extensions.Time.Testing; +using Xunit; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing.Test.Logging; + +public partial class FakeLogCollectorTests +{ + private readonly ITestOutputHelper _outputHelper; + + public FakeLogCollectorTests(ITestOutputHelper outputHelper) + { + _outputHelper = outputHelper; + } + + [Fact] + public async Task Test() + { + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var logger = new FakeLogger(collector); + + _ = Task.Run(async () => + { + int i = 0; + while (i < 21) + { + logger.Log(LogLevel.Critical, $"Item {i}"); + _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); + + await Task.Delay(3_000, CancellationToken.None); + i++; + } + }); + + var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; + var collected = new HashSet(); + + var enumeration = collector.GetLogsAsync(true, CancellationToken.None); + + await foreach (var log in enumeration) + { + _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); + + if (toCollect.Contains(log.Message)) + { + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected.Add(log.Message); + } + + if (collected.Count == toCollect.Count) + { + break; + } + } + + _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); + + await Task.Delay(20_000); + + var toCollect2 = new HashSet {"Item 20",}; + var collected2 = new HashSet(); + + await foreach (var log in enumeration) + { + _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); + + if (toCollect2.Contains(log.Message)) + { + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected2.Add(log.Message); + } + + if (collected2.Count == toCollect2.Count) + { + break; + } + } + + _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + } +} From 5ece729401459da945b925c89bef38e4efdfce6a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Wed, 20 Aug 2025 22:58:26 +0200 Subject: [PATCH 13/32] wip --- .../FakeLogCollector.LogEnumeration.cs | 142 ++++++++++-------- .../Logging/FakeLogCollector.cs | 18 ++- .../Logging/FakeLogCollectorTests.Waiting2.cs | 14 +- 3 files changed, 102 insertions(+), 72 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 35bd655661e..3bfbfb7b8e1 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -10,74 +10,80 @@ namespace Microsoft.Extensions.Logging.Testing; public partial class FakeLogCollector { - private readonly List> _streamWaiters = []; + private List> _logEnumerationWaiters = []; public IAsyncEnumerable GetLogsAsync( - bool continueOnMultipleEnumerations = false, + int startingIndex = 0, + TimeSpan? timeout = null, CancellationToken cancellationToken = default) - => new LogAsyncEnumerable(continueOnMultipleEnumerations, this, cancellationToken); + => new LogAsyncEnumerable(this, startingIndex, timeout, cancellationToken); private class LogAsyncEnumerable : IAsyncEnumerable { - internal readonly object EnumeratorLock = new(); - internal int LastIndex; - internal StreamEnumerator? Enumerator; - - private readonly bool _continueOnMultipleEnumerations; + private readonly int _startingIndex; + private readonly TimeSpan? _timeout; private readonly FakeLogCollector _collector; - private readonly CancellationToken _externalToken; + private readonly CancellationToken _enumerableCancellationToken; internal LogAsyncEnumerable( - bool continueOnMultipleEnumerations, FakeLogCollector collector, - CancellationToken externalToken) + int startingIndex, + TimeSpan? timeout, + CancellationToken enumerableCancellationToken) { - _continueOnMultipleEnumerations = continueOnMultipleEnumerations; _collector = collector; - _externalToken = externalToken; + _startingIndex = startingIndex; + _timeout = timeout; + _enumerableCancellationToken = enumerableCancellationToken; } - public IAsyncEnumerator GetAsyncEnumerator(CancellationToken cancellationToken = default) + public IAsyncEnumerator GetAsyncEnumerator(CancellationToken enumeratorCancellationToken = default) { - lock (EnumeratorLock) - { - int startingPos = _continueOnMultipleEnumerations ? LastIndex : 0; - - var linked = CancellationTokenSource.CreateLinkedTokenSource(_externalToken, cancellationToken); - Enumerator = new StreamEnumerator( - startingPos, - this, - _collector, - linked); - } - - return Enumerator; + return new StreamEnumerator( + _collector, + _startingIndex, + _enumerableCancellationToken, + enumeratorCancellationToken, + _timeout); } } private sealed class StreamEnumerator : IAsyncEnumerator { - internal int Index; - private readonly LogAsyncEnumerable _logAsyncEnumerable; - private readonly FakeLogCollector _collector; - private readonly CancellationTokenSource _cts; - private readonly CancellationToken _cancellationToken; - private TaskCompletionSource? _waitingTsc; - private bool _disposed; + + private readonly CancellationTokenSource _masterCts; + private readonly CancellationTokenSource? _timeoutCts; + private TaskCompletionSource? _waitingTcs; + private FakeLogRecord? _current; + private int _index; + private bool _disposed; + private bool _completed; public StreamEnumerator( - int startingPos, - LogAsyncEnumerable logAsyncEnumerable, FakeLogCollector collector, - CancellationTokenSource cts) + int startingIndex, + CancellationToken enumerableCancellationToken, + CancellationToken enumeratorCancellationToken, + TimeSpan? timeout = null) { _collector = collector; - _cts = cts; - _cancellationToken = cts.Token; - Index = startingPos; - _logAsyncEnumerable = logAsyncEnumerable; + _index = startingIndex; + + CancellationToken[] cancellationTokens; + if (timeout.HasValue) + { + var timeoutCts = new CancellationTokenSource(timeout.Value); + _timeoutCts = timeoutCts; + cancellationTokens = [enumerableCancellationToken, enumeratorCancellationToken, timeoutCts.Token]; + } + else + { + cancellationTokens = [enumerableCancellationToken, enumeratorCancellationToken]; + } + + _masterCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationTokens); } public FakeLogRecord Current => _current ?? throw new InvalidOperationException("Enumeration not started."); @@ -86,34 +92,54 @@ public async ValueTask MoveNextAsync() { ThrowIfDisposed(); + if (_completed) + { + return false; + } + while (true) { - _cancellationToken.ThrowIfCancellationRequested(); + _masterCts.Token.ThrowIfCancellationRequested(); + + TaskCompletionSource waitingTcs; + CancellationTokenRegistration cancellationTokenRegistration; lock (_collector._records) { - if (Index < _collector._records.Count) + if (_index < _collector._records.Count) { - _logAsyncEnumerable.LastIndex = Index; - _current = _collector._records[Index++]; + _current = _collector._records[_index++]; return true; } - _waitingTsc ??= new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - _collector._streamWaiters.Add(_waitingTsc); + waitingTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + _waitingTcs = waitingTcs; + + // pass tcs as state to avoid closure allocation + cancellationTokenRegistration = _masterCts.Token.Register( + static state => ((TaskCompletionSource)state!).TrySetCanceled(), + waitingTcs); + + // waiter needs to be added within records lock + // if not: more records could be added in the meantime and the waiter could be stuck waiting even though the index is behind the actual count + _collector._logEnumerationWaiters.Add(waitingTcs); } try { - await (_waitingTsc?.Task ?? Task.CompletedTask).ConfigureAwait(false); + using (cancellationTokenRegistration) + { + await waitingTcs.Task.ConfigureAwait(false); + } } catch (OperationCanceledException) { + _completed = true; return false; } finally { - _waitingTsc = null; + _waitingTcs = null; } } } @@ -127,24 +153,20 @@ public ValueTask DisposeAsync() _disposed = true; - _cts.Cancel(); + _masterCts.Cancel(); - if (_waitingTsc is not null) + var waitingTcs = Interlocked.Exchange(ref _waitingTcs, null); + if (waitingTcs is not null) { + // TODO TW: explain very well how exactly is this lock is needed lock (_collector._records) { - _ = _collector._streamWaiters.Remove(_waitingTsc); + _ = _collector._logEnumerationWaiters.Remove(waitingTcs); } - - _ = _waitingTsc.TrySetCanceled(_cancellationToken); } - _cts.Dispose(); - - lock (_logAsyncEnumerable.EnumeratorLock) - { - _logAsyncEnumerable.Enumerator = null; - } + _masterCts.Dispose(); + _timeoutCts?.Dispose(); return default; } diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 8f1009910fa..e927dd2e5d6 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -216,7 +216,7 @@ internal void AddRecord(FakeLogRecord record) } List? waitersToWakeUp; - List>? streamWaitersToWake; + List>? logEnumerationWaitersToWake = null; lock (_records) { @@ -233,8 +233,12 @@ internal void AddRecord(FakeLogRecord record) _waiters[i].RemoveFromWaiting(false); } } - - streamWaitersToWake = _streamWaiters.Count > 0 ? [.._streamWaiters] : null; + + if (_logEnumerationWaiters.Count != 0) + { + logEnumerationWaitersToWake = _logEnumerationWaiters; + _logEnumerationWaiters = []; + } } if (waitersToWakeUp is not null) @@ -246,12 +250,12 @@ internal void AddRecord(FakeLogRecord record) } } - if (streamWaitersToWake is not null) + if (logEnumerationWaitersToWake is not null) { - foreach (var streamWaiterToWake in streamWaitersToWake) + foreach (var logEnumerationWaiterToWake in logEnumerationWaitersToWake) { - _ = streamWaiterToWake.TrySetResult(true); // it is possible the task was already completed, but it does not matter and we can avoid locking - _ = _streamWaiters.Remove(streamWaiterToWake); + // it is possible the task was already completed, but it does not matter and we can avoid locking + _ = logEnumerationWaiterToWake.TrySetResult(true); } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs index 7de23d08d6d..7b0cd4c460b 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs @@ -23,6 +23,12 @@ public FakeLogCollectorTests(ITestOutputHelper outputHelper) _outputHelper = outputHelper; } + [Fact] + public async Task JustSomeTest() + { + + } + [Fact] public async Task Test() { @@ -45,9 +51,7 @@ public async Task Test() var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; var collected = new HashSet(); - var enumeration = collector.GetLogsAsync(true, CancellationToken.None); - - await foreach (var log in enumeration) + await foreach (var log in collector.GetLogsAsync(0, null, CancellationToken.None)) { _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); @@ -65,12 +69,12 @@ public async Task Test() _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); - await Task.Delay(20_000); + //await Task.Delay(20_000); var toCollect2 = new HashSet {"Item 20",}; var collected2 = new HashSet(); - await foreach (var log in enumeration) + await foreach (var log in collector.GetLogsAsync(3, null, CancellationToken.None)) { _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); From 64a2775bc43463b363f99c3d4e502a9549844d28 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 00:14:08 +0200 Subject: [PATCH 14/32] wip --- .../FakeLogCollector.LogEnumeration.cs | 114 +++++++++++------- .../Logging/FakeLogCollector.cs | 20 ++- 2 files changed, 77 insertions(+), 57 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 3bfbfb7b8e1..0a46b207291 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Threading; using System.Threading.Tasks; @@ -10,7 +11,10 @@ namespace Microsoft.Extensions.Logging.Testing; public partial class FakeLogCollector { - private List> _logEnumerationWaiters = []; + private TaskCompletionSource _logEnumerationSharedWaiter = + new(TaskCreationOptions.RunContinuationsAsynchronously); + + private int _waitingEnumeratorCount; public IAsyncEnumerable GetLogsAsync( int startingIndex = 0, @@ -54,7 +58,6 @@ private sealed class StreamEnumerator : IAsyncEnumerator private readonly CancellationTokenSource _masterCts; private readonly CancellationTokenSource? _timeoutCts; - private TaskCompletionSource? _waitingTcs; private FakeLogRecord? _current; private int _index; @@ -96,51 +99,83 @@ public async ValueTask MoveNextAsync() { return false; } + + var masterCancellationToken = _masterCts.Token; - while (true) + if (masterCancellationToken.IsCancellationRequested) { - _masterCts.Token.ThrowIfCancellationRequested(); - - TaskCompletionSource waitingTcs; - CancellationTokenRegistration cancellationTokenRegistration; - - lock (_collector._records) - { - if (_index < _collector._records.Count) - { - _current = _collector._records[_index++]; - return true; - } - - waitingTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - _waitingTcs = waitingTcs; - - // pass tcs as state to avoid closure allocation - cancellationTokenRegistration = _masterCts.Token.Register( - static state => ((TaskCompletionSource)state!).TrySetCanceled(), - waitingTcs); - - // waiter needs to be added within records lock - // if not: more records could be added in the meantime and the waiter could be stuck waiting even though the index is behind the actual count - _collector._logEnumerationWaiters.Add(waitingTcs); - } + _completed = true; + _current = null; + return false; + } + while (true) + { + TaskCompletionSource? waiter = null; + try { - using (cancellationTokenRegistration) + masterCancellationToken.ThrowIfCancellationRequested(); + + lock (_collector._records) { - await waitingTcs.Task.ConfigureAwait(false); + if (_index < _collector._records.Count) + { + _current = _collector._records[_index++]; + return true; + } + + // waiter needs to be subscribed within records lock + // if not: more records could be added in the meantime and the waiter could be stuck waiting even though the index is behind the actual count + waiter = _collector._logEnumerationSharedWaiter; + _collector._waitingEnumeratorCount++; } + + // Compatibility path for net462: emulate Task.WaitAsync(cancellationToken). + await AwaitWithCancellationAsync(waiter.Task, masterCancellationToken).ConfigureAwait(false); } catch (OperationCanceledException) { + lock (_collector._records) + { + // We only decrement if the shared waiter has not yet been swaped. Otherwise, the counter has been reset. + if ( + waiter is not null + && _collector._waitingEnumeratorCount > 0 + && waiter == _collector._logEnumerationSharedWaiter) + { + _collector._waitingEnumeratorCount--; + } + } + _completed = true; + _current = null; return false; } - finally - { - _waitingTcs = null; - } + } + } + + private static async Task AwaitWithCancellationAsync(Task task, CancellationToken cancellationToken) + { + if (!cancellationToken.CanBeCanceled || task.IsCompleted) + { + await task.ConfigureAwait(false); + return; + } + + var cancelTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + CancellationTokenRegistration ctr = default; + try + { + ctr = cancellationToken.Register(static s => + ((TaskCompletionSource)s!).TrySetCanceled(), cancelTcs); + + var completed = await Task.WhenAny(task, cancelTcs.Task).ConfigureAwait(false); + await completed.ConfigureAwait(false); + } + finally + { + ctr.Dispose(); } } @@ -154,17 +189,6 @@ public ValueTask DisposeAsync() _disposed = true; _masterCts.Cancel(); - - var waitingTcs = Interlocked.Exchange(ref _waitingTcs, null); - if (waitingTcs is not null) - { - // TODO TW: explain very well how exactly is this lock is needed - lock (_collector._records) - { - _ = _collector._logEnumerationWaiters.Remove(waitingTcs); - } - } - _masterCts.Dispose(); _timeoutCts?.Dispose(); diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index e927dd2e5d6..87f4f7f3e1f 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -216,7 +216,7 @@ internal void AddRecord(FakeLogRecord record) } List? waitersToWakeUp; - List>? logEnumerationWaitersToWake = null; + TaskCompletionSource? logEnumerationSharedWaiterToWake = null; lock (_records) { @@ -234,10 +234,11 @@ internal void AddRecord(FakeLogRecord record) } } - if (_logEnumerationWaiters.Count != 0) + if (_waitingEnumeratorCount > 0) { - logEnumerationWaitersToWake = _logEnumerationWaiters; - _logEnumerationWaiters = []; + logEnumerationSharedWaiterToWake = _logEnumerationSharedWaiter; + _logEnumerationSharedWaiter = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + _waitingEnumeratorCount = 0; } } @@ -250,14 +251,9 @@ internal void AddRecord(FakeLogRecord record) } } - if (logEnumerationWaitersToWake is not null) - { - foreach (var logEnumerationWaiterToWake in logEnumerationWaitersToWake) - { - // it is possible the task was already completed, but it does not matter and we can avoid locking - _ = logEnumerationWaiterToWake.TrySetResult(true); - } - } + // it is possible the task was already completed, but it does not matter and we can avoid locking + // TODO TW: is the above still true? + _ = logEnumerationSharedWaiterToWake?.TrySetResult(true); _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } From da4dc798a5b9c18f45418b81873be5f320c9f311 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 09:45:36 +0200 Subject: [PATCH 15/32] wip --- .../FakeLogCollector.LogEnumeration.cs | 59 ++++++++------ .../Logging/FakeLogCollectorTests.Waiting2.cs | 79 +++++++++++++++++++ 2 files changed, 115 insertions(+), 23 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 0a46b207291..8366fa4aa4d 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -3,9 +3,9 @@ using System; using System.Collections.Generic; -using System.Diagnostics; using System.Threading; using System.Threading.Tasks; +using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; @@ -16,11 +16,37 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; + public async Task WaitForLogAsync2( + Func predicate, + int startingIndex = 0, + TimeSpan? timeout = null, + CancellationToken cancellationToken = default) + { + _ = Throw.IfNull(predicate); + + int index = startingIndex; + await foreach (var item in GetLogsAsync(startingIndex, timeout, cancellationToken).ConfigureAwait(false)) + { + if (predicate(item)) + { + return index; + } + + index++; + } + + return -1; + } + public IAsyncEnumerable GetLogsAsync( int startingIndex = 0, TimeSpan? timeout = null, CancellationToken cancellationToken = default) - => new LogAsyncEnumerable(this, startingIndex, timeout, cancellationToken); + { + _ = Throw.IfOutOfRange(startingIndex, 0, int.MaxValue); + + return new LogAsyncEnumerable(this, startingIndex, timeout, cancellationToken); + } private class LogAsyncEnumerable : IAsyncEnumerable { @@ -60,9 +86,8 @@ private sealed class StreamEnumerator : IAsyncEnumerator private readonly CancellationTokenSource? _timeoutCts; private FakeLogRecord? _current; - private int _index; + private int _index; // TODO TW: when the logs are cleared, this index remains at the value... private bool _disposed; - private bool _completed; public StreamEnumerator( FakeLogCollector collector, @@ -95,28 +120,18 @@ public async ValueTask MoveNextAsync() { ThrowIfDisposed(); - if (_completed) - { - return false; - } - var masterCancellationToken = _masterCts.Token; - if (masterCancellationToken.IsCancellationRequested) - { - _completed = true; - _current = null; - return false; - } + masterCancellationToken.ThrowIfCancellationRequested(); while (true) { TaskCompletionSource? waiter = null; - + try { masterCancellationToken.ThrowIfCancellationRequested(); - + lock (_collector._records) { if (_index < _collector._records.Count) @@ -124,13 +139,13 @@ public async ValueTask MoveNextAsync() _current = _collector._records[_index++]; return true; } - + // waiter needs to be subscribed within records lock // if not: more records could be added in the meantime and the waiter could be stuck waiting even though the index is behind the actual count waiter = _collector._logEnumerationSharedWaiter; _collector._waitingEnumeratorCount++; } - + // Compatibility path for net462: emulate Task.WaitAsync(cancellationToken). await AwaitWithCancellationAsync(waiter.Task, masterCancellationToken).ConfigureAwait(false); } @@ -148,13 +163,11 @@ waiter is not null } } - _completed = true; - _current = null; - return false; + throw; } } } - + private static async Task AwaitWithCancellationAsync(Task task, CancellationToken cancellationToken) { if (!cancellationToken.CanBeCanceled || task.IsCompleted) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs index 7b0cd4c460b..34758c5e20f 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs @@ -92,4 +92,83 @@ public async Task Test() _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); } + + [Fact] + public async Task Test2() + { + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var logger = new FakeLogger(collector); + + _ = Task.Run(async () => + { + int i = 0; + while (i < 21) + { + logger.Log(LogLevel.Critical, $"Item {i}"); + _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); + + await Task.Delay(3_000, CancellationToken.None); + i++; + } + }); + + var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; + var collected = new HashSet(); + + await collector.WaitForLogAsync2(log => + { + _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); + + if (toCollect.Contains(log.Message)) + { + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected.Add(log.Message); + } + + if (collected.Count == toCollect.Count) + { + return true; + } + + return false; + }); + + _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); + + //await Task.Delay(20_000); + + var toCollect2 = new HashSet {"Item 20",}; + var collected2 = new HashSet(); + + var waitingForLogs = collector.WaitForLogAsync2(log => + { + _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); + + if (toCollect2.Contains(log.Message)) + { + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected2.Add(log.Message); + } + + if (collected2.Count == toCollect2.Count) + { + return true; + } + + return false; + }, timeout: TimeSpan.FromMilliseconds(30_000)); + + var justAPause = Task.Delay(20_000); + + try + { + await await Task.WhenAny(waitingForLogs, justAPause); + } + catch (OperationCanceledException) + { + _outputHelper.WriteLine($"Waiting exception!!!!!!! at {DateTime.Now}"); + } + + _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + } } From 367bae618bb1b1145ae9ac842288ef5e5a4dca0b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 10:18:10 +0200 Subject: [PATCH 16/32] removing previous implementation of easier review --- .../FakeLogCollector.LogEnumeration.cs | 3 +- .../Logging/FakeLogCollector.cs | 213 --------- .../Logging/FakeLogCollectorTests.Waiting.cs | 424 +++++------------- .../Logging/FakeLogCollectorTests.Waiting2.cs | 174 ------- 4 files changed, 112 insertions(+), 702 deletions(-) delete mode 100644 test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 8366fa4aa4d..fbaec5e40fd 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -16,7 +16,7 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; - public async Task WaitForLogAsync2( + public async Task WaitForLogsAsync( Func predicate, int startingIndex = 0, TimeSpan? timeout = null, @@ -192,6 +192,7 @@ private static async Task AwaitWithCancellationAsync(Task task, CancellationToke } } + // TODO TW: consider pending wait and exception handling public ValueTask DisposeAsync() { if (_disposed) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 87f4f7f3e1f..3aad4dcf1c6 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -4,11 +4,9 @@ using System; using System.Collections.Generic; using System.Diagnostics; -using System.Diagnostics.CodeAnalysis; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Options; -using Microsoft.Shared.DiagnosticIds; using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; @@ -28,8 +26,6 @@ public partial class FakeLogCollector private readonly List _records = []; private readonly FakeLogCollectorOptions _options; - private readonly List _waiters = []; // modify only under _records lock - /// /// Initializes a new instance of the class. /// @@ -117,74 +113,6 @@ public FakeLogRecord LatestRecord /// public int Count => _records.Count; - /// - /// Allows waiting for the point in time in which a newly processed log record fulfilled custom condition supplied by the caller. - /// - /// Custom condition terminating waiting upon fulfillment. - /// Token based cancellation of the waiting. - /// Awaitable task that completes upon condition fulfillment, timeout expiration or cancellation. - public Task WaitForLogAsync( - Func endWaiting, - CancellationToken cancellationToken = default) - { - return WaitForLogAsync(endWaiting, null, cancellationToken); - } - - /// - /// Allows waiting for the point in time in which a newly processed log record fulfilled custom condition supplied by the caller. - /// - /// Custom condition terminating waiting upon fulfillment. - /// TODO TW placeholder - /// Token based cancellation of the waiting. - /// Awaitable task that completes upon condition fulfillment, timeout expiration or cancellation. - [Experimental(diagnosticId: DiagnosticIds.Experiments.TimeProvider, UrlFormat = DiagnosticIds.UrlFormat)] // TODO TW: << placeholder - public Task WaitForLogAsync( - Func endWaiting, - TimeSpan? timeout, - CancellationToken cancellationToken = default) - { - _ = Throw.IfNull(endWaiting); - _ = Throw.IfNull(cancellationToken); - - // Before we even start waiting, we check if the cancellation token is already canceled and if yes, we exit early with a canceled task - if (cancellationToken.IsCancellationRequested) - { - return Task.FromCanceled(cancellationToken); - } - - Waiter waiter; - - lock (_records) - { - // Before we even start waiting, we check if the latest record already fulfills the condition and if yes, we exit early with success - if (_records.Count > 0 && endWaiting(LatestRecord)) - { - return Task.FromResult(true); - } - - // We register the waiter - waiter = new Waiter(this, endWaiting, timeout); - _waiters.Add(waiter); - } - - if (cancellationToken.CanBeCanceled) - { - // When the cancellation token is canceled, we resolve the waiter and cancel the awaited task - _ = cancellationToken.Register(() => - { - waiter.RemoveFromWaiting(); - - // trigger the task from outside the lock - // TODO TW: I don't see it - waiter.ResolveByCancellation(cancellationToken); - }); - } - -#pragma warning disable VSTHRD003 // Avoid awaiting foreign Tasks - return waiter.Task; -#pragma warning restore VSTHRD003 // Avoid awaiting foreign Tasks - } - internal void AddRecord(FakeLogRecord record) { if (_options.FilteredLevels.Count > 0 && !_options.FilteredLevels.Contains(record.Level)) @@ -215,25 +143,12 @@ internal void AddRecord(FakeLogRecord record) return; } - List? waitersToWakeUp; TaskCompletionSource? logEnumerationSharedWaiterToWake = null; lock (_records) { _records.Add(record); - Span waitersToWakeUpOrderedByIndices = _waiters.Count < StackAllocThreshold - ? stackalloc bool[_waiters.Count] - : new bool[_waiters.Count]; - CheckWaiting(record, waitersToWakeUpOrderedByIndices, out waitersToWakeUp); - for (var i = 0; i < waitersToWakeUpOrderedByIndices.Length; i++) - { - if (waitersToWakeUpOrderedByIndices[i]) - { - _waiters[i].RemoveFromWaiting(false); - } - } - if (_waitingEnumeratorCount > 0) { logEnumerationSharedWaiterToWake = _logEnumerationSharedWaiter; @@ -242,15 +157,6 @@ internal void AddRecord(FakeLogRecord record) } } - if (waitersToWakeUp is not null) - { - foreach (var waiterToWakeUp in waitersToWakeUp) - { - // trigger the task from outside the lock - waiterToWakeUp.ResolveByResult(true); - } - } - // it is possible the task was already completed, but it does not matter and we can avoid locking // TODO TW: is the above still true? _ = logEnumerationSharedWaiterToWake?.TrySetResult(true); @@ -258,124 +164,5 @@ internal void AddRecord(FakeLogRecord record) _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } - // Must be called inside lock(_records) - private void CheckWaiting(FakeLogRecord currentlyLoggedRecord, Span waitersToRemoveOrderedByIndices, out List? waitersToWakeUp) - { - waitersToWakeUp = null; - - for (var waiterIndex = _waiters.Count - 1; waiterIndex >= 0; waiterIndex--) - { - var waiter = _waiters[waiterIndex]; - if (!waiter.ShouldEndWaiting(currentlyLoggedRecord)) - { - continue; - } - - waitersToWakeUp ??= []; - waitersToWakeUp.Add(waiter); - - waitersToRemoveOrderedByIndices[waiterIndex] = true; - } - } - internal TimeProvider TimeProvider => _options.TimeProvider; - - // TODO TW: I don't think we need/want record struct for this - // A) it is put into List so we don't benefit from structs ability to live on the stack - // B) I don't want to compare by fields/field-values, but rather by instance, so don't need record for this (or suboptimal struct for that matter) - private sealed class Waiter - { - public Task Task => _taskSource.Task; - public Func ShouldEndWaiting { get; } - - // TODO TW: I don't see it - // NOTE: In order to avoid potential deadlocks, this task should - // be completed when the main lock is not being held. Otherwise, - // application code being woken up by the task could potentially - // call back into the FakeLogCollector code and thus trigger a deadlock. - private readonly TaskCompletionSource _taskSource; - - private readonly FakeLogCollector _fakeLogCollector; - - private readonly object _timerLock = new(); - private ITimer? _timeoutTimer; - - public Waiter(FakeLogCollector fakeLogCollector, Func shouldEndWaiting, TimeSpan? timeout) - { - ShouldEndWaiting = shouldEndWaiting; - _fakeLogCollector = fakeLogCollector; - _taskSource = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - _timeoutTimer = timeout.HasValue ? CreateTimoutTimer(fakeLogCollector, timeout.Value) : null; - } - - public void RemoveFromWaiting(bool performUnderLock = true) - { - if (performUnderLock) - { - lock(_fakeLogCollector._records) - { - RemoveFromWaitingInternal(); - } - - return; - } - - RemoveFromWaitingInternal(); - } - - public void ResolveByResult(bool result) - { - StopTimer(); - _ = _taskSource.TrySetResult(result); - } - - public void ResolveByCancellation(CancellationToken cancellationToken) - { - StopTimer(); - _ = _taskSource.TrySetCanceled(cancellationToken); - } - - private void RemoveFromWaitingInternal() => _ = _fakeLogCollector._waiters.Remove(this); - - private void StopTimer() - { - lock (_timerLock) - { - if (_timeoutTimer is null) - { - return; - } - - try - { - _timeoutTimer.Dispose(); - } - catch (ObjectDisposedException) - { - // Timer was already disposed - } - finally - { - _timeoutTimer = null; - } - } - } - - private ITimer CreateTimoutTimer(FakeLogCollector fakeLogCollector, TimeSpan timeout) - { - return fakeLogCollector.TimeProvider - .CreateTimer( - _ => - { - RemoveFromWaiting(); - - // trigger the task from outside the lock - ResolveByResult(false); - }, - null, - timeout, // perform after - Timeout.InfiniteTimeSpan // don't repeat - ); - } - } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 7d7dda357c7..8f8fef88f24 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -2,13 +2,9 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; -using System.Collections.Concurrent; using System.Collections.Generic; -using System.Linq; using System.Threading; using System.Threading.Tasks; -using FluentAssertions; -using Microsoft.Extensions.Time.Testing; using Xunit; using Xunit.Abstractions; @@ -16,353 +12,153 @@ namespace Microsoft.Extensions.Logging.Testing.Test.Logging; public partial class FakeLogCollectorTests { - private record WaitingTestCase( - int EndWaitAtAttemptCount, - double? CancellationAfterLogAttemptCount, - double? TimeoutAfterLogAttemptCount, - bool StartsWithCancelledToken, - string[] ExpectedOperationSequence, - bool ExpectedTaskCancelled, - bool? ExpectedAwaitedTaskResult - ); - - private const int WaitingTscOverallLogCount = 3; - private const int LogAttemptHalfTimePeriod = 250; - private const int LogAttemptFullTimePeriod = LogAttemptHalfTimePeriod * 2; - - /* Testing infrastructure messages */ - private const string StartedWaitingMessage = "Started awaiting"; - private const string AfterStartingBackgroundActionMessage = "Right after starting the background action"; - private const string CheckingWaitingCallbackMessagePrefix = "Checking if waiting should end"; - private const string BackgroundActionFinishedMessage = "Background action has finished"; - private const string FinishedWaitingMessage = "Finished waiting for the log. Waiting for the background action to finish."; - - private const string AwaitedLogMessagePrefix = "Awaited log message"; - private const string IrrelevantLogMessage = "Irrelevant log message"; + private readonly ITestOutputHelper _outputHelper; - [Fact] - public async Task Waiting_ForOneRecord() + public FakeLogCollectorTests(ITestOutputHelper outputHelper) { - // Waiting for one record, fulfilling this wait - - // Arrange - var testCaseData = new WaitingTestCase( - 1, null, null, false, [ - IrrelevantLogMessage, // log message before start of waiting - StartedWaitingMessage, - $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled - AfterStartingBackgroundActionMessage, - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #002", - $"{AwaitedLogMessagePrefix} #001", - $"{CheckingWaitingCallbackMessagePrefix} #003", - FinishedWaitingMessage, - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #002", - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #003", - BackgroundActionFinishedMessage, - ], - false, - true); - - // Act, Assert - await WaitingInternal(testCaseData); + _outputHelper = outputHelper; } [Fact] - public async Task Waiting_ForTwoRecords() + public async Task Test() { - // Waiting for two records, fulfilling this wait - - // Arrange - var waitingTestCase = new WaitingTestCase( - 2, null, null, false, [ - IrrelevantLogMessage, // log message before start of waiting - StartedWaitingMessage, - $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled - AfterStartingBackgroundActionMessage, - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #002", - $"{AwaitedLogMessagePrefix} #001", - $"{CheckingWaitingCallbackMessagePrefix} #003", - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #004", - $"{AwaitedLogMessagePrefix} #002", - $"{CheckingWaitingCallbackMessagePrefix} #005", - FinishedWaitingMessage, - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #003", - BackgroundActionFinishedMessage, - ], - false, - true); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var logger = new FakeLogger(collector); - [Fact] - public async Task Waiting_CancellingBeforeWaitFulfilled() - { - // Waiting for many log records, but cancelling the wait before this condition is reached at the time of one log record being actually logged. - - // Arrange - var waitingTestCase = new WaitingTestCase( - WaitingTscOverallLogCount + 1, 1.5, null, false, [ - IrrelevantLogMessage, // log message before start of waiting - StartedWaitingMessage, - $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled - AfterStartingBackgroundActionMessage, - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #002", - $"{AwaitedLogMessagePrefix} #001", - $"{CheckingWaitingCallbackMessagePrefix} #003", - IrrelevantLogMessage, // different message logged each half period - FinishedWaitingMessage, - $"{AwaitedLogMessagePrefix} #002", - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #003", - BackgroundActionFinishedMessage - ], - true, - null); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } + _ = Task.Run(async () => + { + int i = 0; + while (i < 21) + { + logger.Log(LogLevel.Critical, $"Item {i}"); + _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); - [Fact] - public async Task Waiting_StartingWaitWithCanceledToken() - { - // Waiting for many log records, but starting with cancellation token already cancelled. - - // Arrange - var waitingTestCase = new WaitingTestCase( - WaitingTscOverallLogCount, null, null, true, [ - IrrelevantLogMessage, // log message before start of waiting - StartedWaitingMessage, - AfterStartingBackgroundActionMessage, - FinishedWaitingMessage, - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #001", - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #002", - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #003", - BackgroundActionFinishedMessage - ], - true, - null); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } + await Task.Delay(3_000, CancellationToken.None); + i++; + } + }); - [Fact] - public async Task Waiting_WithCancellationAfterWaitFulfilled() - { - // Waiting for single log record and supplying a cancellation period that would match three logs to get writer - - // Arrange - var waitingTestCase = new WaitingTestCase( - 1, 3 * LogAttemptFullTimePeriod, null, false, [ - IrrelevantLogMessage, // log message before start of waiting - StartedWaitingMessage, - $"{CheckingWaitingCallbackMessagePrefix} #001", // condition is checked at the waiting start if not immediately cancelled - AfterStartingBackgroundActionMessage, - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #002", - $"{AwaitedLogMessagePrefix} #001", - $"{CheckingWaitingCallbackMessagePrefix} #003", - FinishedWaitingMessage, - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #002", - IrrelevantLogMessage, // different message logged each half period - $"{AwaitedLogMessagePrefix} #003", - BackgroundActionFinishedMessage, - ], - false, - true); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } + var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; + var collected = new HashSet(); - [Fact] - public async Task Waiting_TimeoutBeforeWaitIsFulfilled() - { - // Waiting for 3 log attempts, but setting timeout to expire after the second attempt. - - // Arrange - var waitingTestCase = new WaitingTestCase( - 3, null, 2.5, false, [ - IrrelevantLogMessage, // log message before start of waiting - StartedWaitingMessage, - $"{CheckingWaitingCallbackMessagePrefix} #001", - AfterStartingBackgroundActionMessage, - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #002", - $"{AwaitedLogMessagePrefix} #001", - $"{CheckingWaitingCallbackMessagePrefix} #003", - IrrelevantLogMessage, // different message logged each half period - $"{CheckingWaitingCallbackMessagePrefix} #004", - $"{AwaitedLogMessagePrefix} #002", - $"{CheckingWaitingCallbackMessagePrefix} #005", - IrrelevantLogMessage, // different message logged each half period - FinishedWaitingMessage, - $"{AwaitedLogMessagePrefix} #003", - BackgroundActionFinishedMessage - ], - false, - false); - - // Act, Assert - await WaitingInternal(waitingTestCase); - } - - private async Task WaitingInternal(WaitingTestCase testCaseData) - { - // Testing infrastructure: capping the time of the test run - bool stoppedByInfrastructure = false; - const int TestRunCapMs = 2_000; - using var circuitBreakerCts = new CancellationTokenSource(); - var testInfrastructureCircuitBreakerTask = Task.Run(async () => + await foreach (var log in collector.GetLogsAsync(0, null, CancellationToken.None)) { - await Task.Delay(TestRunCapMs, CancellationToken.None); - stoppedByInfrastructure = true; - return false; - }, circuitBreakerCts.Token); + _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); - // Wrapped test case run - await await Task.WhenAny(WaitingInternalCore(testCaseData), testInfrastructureCircuitBreakerTask); + if (toCollect.Contains(log.Message)) + { + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected.Add(log.Message); + } - // Test infrastructure assert - Assert.False(stoppedByInfrastructure, "None of the test cases is expected to reach test infrastructure timeout"); - circuitBreakerCts.Cancel(); // avoid resource leaking when core task finishes first - } + if (collected.Count == toCollect.Count) + { + break; + } + } - private async Task WaitingInternalCore(WaitingTestCase testCaseData) - { - // Testing infrastructure: keeping track of when the implementation checks the users callback - var testExecutionCustomLog = new ConcurrentQueue(); - int callbackCallCounter = 0; - int awaitedLogMessageCount = 0; - const int AllLogAttemptsInHalfPeriods = WaitingTscOverallLogCount * 2; - var fakeTimeProvider = new FakeTimeProvider(); - - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions { TimeProvider = fakeTimeProvider }); - var logger = new FakeLogger(collector); + _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); + + //await Task.Delay(20_000); + + var toCollect2 = new HashSet {"Item 20",}; + var collected2 = new HashSet(); - bool UserDefinedWaitingCondition(FakeLogRecord record) + await foreach (var log in collector.GetLogsAsync(3, null, CancellationToken.None)) { - callbackCallCounter++; - testExecutionCustomLog.Enqueue($"{CheckingWaitingCallbackMessagePrefix} #{callbackCallCounter:000}"); + _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); - if (record.Message.StartsWith(AwaitedLogMessagePrefix)) + if (toCollect2.Contains(log.Message)) { - awaitedLogMessageCount++; + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected2.Add(log.Message); } - return awaitedLogMessageCount == testCaseData.EndWaitAtAttemptCount; + if (collected2.Count == toCollect2.Count) + { + break; + } } - TimeSpan? userDefinedTimeout = testCaseData.TimeoutAfterLogAttemptCount is null - ? null - : TimeSpan.FromMilliseconds(LogAttemptFullTimePeriod * testCaseData.TimeoutAfterLogAttemptCount.Value); + _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + } - var userDefinedCancellation = testCaseData.CancellationAfterLogAttemptCount.HasValue - ? CreateCtsWithTimeProvider(TimeSpan.FromMilliseconds(LogAttemptFullTimePeriod * testCaseData.CancellationAfterLogAttemptCount.Value), fakeTimeProvider) - : new CancellationTokenSource(); + [Fact] + public async Task Test2() + { + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var logger = new FakeLogger(collector); - using (userDefinedCancellation) + _ = Task.Run(async () => { - if (testCaseData.StartsWithCancelledToken) + int i = 0; + while (i < 21) { -#if NET8_0_OR_GREATER - await CancelTokenSource(userDefinedCancellation); -#else - CancelTokenSource(userDefinedCancellation); -#endif + logger.Log(LogLevel.Critical, $"Item {i}"); + _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); + + await Task.Delay(3_000, CancellationToken.None); + i++; } + }); + + var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; + var collected = new HashSet(); - // Act - logger.LogDebug(IrrelevantLogMessage); - testExecutionCustomLog.Enqueue(IrrelevantLogMessage); - - testExecutionCustomLog.Enqueue("Started awaiting"); - - var awaitingTask = collector.WaitForLogAsync(UserDefinedWaitingCondition, userDefinedTimeout, userDefinedCancellation.Token); - - var loggingBackgroundAction = Task.Run( - async () => - { - // Simulating time progression in half-time periods to allow for mid-period timeout waiting completions - for (var logAttemptHalfPeriodCount = 1; logAttemptHalfPeriodCount <= AllLogAttemptsInHalfPeriods; logAttemptHalfPeriodCount++) - { - await Task.Delay(100, CancellationToken.None); // even though the test is not real time-based, we need to give room for the parallel post task completion operations - fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(LogAttemptHalfTimePeriod)); - - var logAttemptPeriodReached = logAttemptHalfPeriodCount % 2 == 0; - if (logAttemptPeriodReached) - { - var logAttemptNumber = logAttemptHalfPeriodCount / 2; - var logMessage = $"{AwaitedLogMessagePrefix} #{logAttemptNumber:000}"; - testExecutionCustomLog.Enqueue(logMessage); // Testing infrastructure log - logger.LogDebug(logMessage); // Actual log - } - else - { - testExecutionCustomLog.Enqueue(IrrelevantLogMessage); // Testing infrastructure log - logger.LogDebug(IrrelevantLogMessage); - } - } - }, - CancellationToken.None); - - testExecutionCustomLog.Enqueue(AfterStartingBackgroundActionMessage); - - bool? result = null; - bool taskCancelled = false; - - try + await collector.WaitForLogsAsync(log => + { + _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); + + if (toCollect.Contains(log.Message)) { - result = await awaitingTask; + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected.Add(log.Message); } - catch (TaskCanceledException) + + if (collected.Count == toCollect.Count) { - taskCancelled = true; + return true; } - testExecutionCustomLog.Enqueue(FinishedWaitingMessage); + return false; + }); - await loggingBackgroundAction; + _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); - testExecutionCustomLog.Enqueue(BackgroundActionFinishedMessage); + //await Task.Delay(20_000); - // Assert - Assert.Equal(testCaseData.ExpectedAwaitedTaskResult, result); - testExecutionCustomLog.Should().Equal(testCaseData.ExpectedOperationSequence); - Assert.Equal( - testExecutionCustomLog.Count(r => r.StartsWith(AwaitedLogMessagePrefix)), - logger.Collector.GetSnapshot().Count(r => r.Message.StartsWith(AwaitedLogMessagePrefix)) - ); - Assert.Equal(testCaseData.ExpectedTaskCancelled, taskCancelled); - } - } + var toCollect2 = new HashSet {"Item 20",}; + var collected2 = new HashSet(); + + var waitingForLogs = collector.WaitForLogsAsync(log => + { + _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); -#if NET8_0_OR_GREATER - async Task CancelTokenSource(CancellationTokenSource cts) => await cts.CancelAsync(); -#else - void CancelTokenSource(CancellationTokenSource cts) => cts.Cancel(); -#endif + if (toCollect2.Contains(log.Message)) + { + _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + collected2.Add(log.Message); + } - CancellationTokenSource CreateCtsWithTimeProvider(TimeSpan timeSpan, TimeProvider timeProvider) - { -#if NET8_0_OR_GREATER - return new CancellationTokenSource(timeSpan, timeProvider); -#else - return timeProvider.CreateCancellationTokenSource(timeSpan); -#endif + if (collected2.Count == toCollect2.Count) + { + return true; + } + + return false; + }, timeout: TimeSpan.FromMilliseconds(2_000)); + + var pauseToTimeout = Task.Delay(99_000_000); + + try + { + await await Task.WhenAny(waitingForLogs, pauseToTimeout); + } + catch (OperationCanceledException) + { + _outputHelper.WriteLine($"Waiting exception!!!!!!! at {DateTime.Now}"); + } + + _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs deleted file mode 100644 index 34758c5e20f..00000000000 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting2.cs +++ /dev/null @@ -1,174 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Collections.Concurrent; -using System.Collections.Generic; -using System.Linq; -using System.Threading; -using System.Threading.Tasks; -using FluentAssertions; -using Microsoft.Extensions.Time.Testing; -using Xunit; -using Xunit.Abstractions; - -namespace Microsoft.Extensions.Logging.Testing.Test.Logging; - -public partial class FakeLogCollectorTests -{ - private readonly ITestOutputHelper _outputHelper; - - public FakeLogCollectorTests(ITestOutputHelper outputHelper) - { - _outputHelper = outputHelper; - } - - [Fact] - public async Task JustSomeTest() - { - - } - - [Fact] - public async Task Test() - { - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var logger = new FakeLogger(collector); - - _ = Task.Run(async () => - { - int i = 0; - while (i < 21) - { - logger.Log(LogLevel.Critical, $"Item {i}"); - _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); - - await Task.Delay(3_000, CancellationToken.None); - i++; - } - }); - - var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; - var collected = new HashSet(); - - await foreach (var log in collector.GetLogsAsync(0, null, CancellationToken.None)) - { - _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); - - if (toCollect.Contains(log.Message)) - { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected.Add(log.Message); - } - - if (collected.Count == toCollect.Count) - { - break; - } - } - - _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); - - //await Task.Delay(20_000); - - var toCollect2 = new HashSet {"Item 20",}; - var collected2 = new HashSet(); - - await foreach (var log in collector.GetLogsAsync(3, null, CancellationToken.None)) - { - _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); - - if (toCollect2.Contains(log.Message)) - { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected2.Add(log.Message); - } - - if (collected2.Count == toCollect2.Count) - { - break; - } - } - - _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); - } - - [Fact] - public async Task Test2() - { - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var logger = new FakeLogger(collector); - - _ = Task.Run(async () => - { - int i = 0; - while (i < 21) - { - logger.Log(LogLevel.Critical, $"Item {i}"); - _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); - - await Task.Delay(3_000, CancellationToken.None); - i++; - } - }); - - var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; - var collected = new HashSet(); - - await collector.WaitForLogAsync2(log => - { - _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); - - if (toCollect.Contains(log.Message)) - { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected.Add(log.Message); - } - - if (collected.Count == toCollect.Count) - { - return true; - } - - return false; - }); - - _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); - - //await Task.Delay(20_000); - - var toCollect2 = new HashSet {"Item 20",}; - var collected2 = new HashSet(); - - var waitingForLogs = collector.WaitForLogAsync2(log => - { - _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); - - if (toCollect2.Contains(log.Message)) - { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected2.Add(log.Message); - } - - if (collected2.Count == toCollect2.Count) - { - return true; - } - - return false; - }, timeout: TimeSpan.FromMilliseconds(30_000)); - - var justAPause = Task.Delay(20_000); - - try - { - await await Task.WhenAny(waitingForLogs, justAPause); - } - catch (OperationCanceledException) - { - _outputHelper.WriteLine($"Waiting exception!!!!!!! at {DateTime.Now}"); - } - - _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); - } -} From eb342f3598efe46f4b203fbb288be8298315104e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 10:29:09 +0200 Subject: [PATCH 17/32] old waiting logic removal --- .../Logging/FakeLogCollector.cs | 5 ----- 1 file changed, 5 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 3aad4dcf1c6..c414bf8d61b 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -18,11 +18,6 @@ namespace Microsoft.Extensions.Logging.Testing; [DebuggerTypeProxy(typeof(FakeLogCollectorDebugView))] public partial class FakeLogCollector { - /// - /// Arbitrary low number threshold for stack allocation path to avoid stack overflow. - /// - private const int StackAllocThreshold = 100; - private readonly List _records = []; private readonly FakeLogCollectorOptions _options; From 7c4b5d633ebc01fd57d2b1c3aab735b6bf2ce15d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 10:51:06 +0200 Subject: [PATCH 18/32] minor test cleanup --- .../FakeLogCollector.LogEnumeration.cs | 2 +- .../Logging/FakeLogCollectorTests.Waiting.cs | 66 ++++++++++--------- 2 files changed, 35 insertions(+), 33 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index fbaec5e40fd..9a845796263 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -24,7 +24,7 @@ public async Task WaitForLogsAsync( { _ = Throw.IfNull(predicate); - int index = startingIndex; + int index = startingIndex; // This index may be too weak await foreach (var item in GetLogsAsync(startingIndex, timeout, cancellationToken).ConfigureAwait(false)) { if (predicate(item)) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 8f8fef88f24..8d485990350 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -23,20 +23,8 @@ public FakeLogCollectorTests(ITestOutputHelper outputHelper) public async Task Test() { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var logger = new FakeLogger(collector); - _ = Task.Run(async () => - { - int i = 0; - while (i < 21) - { - logger.Log(LogLevel.Critical, $"Item {i}"); - _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); - - await Task.Delay(3_000, CancellationToken.None); - i++; - } - }); + var logEmittingTask = EmitLogs(collector, 20, TimeSpan.FromMilliseconds(1_000)); var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; var collected = new HashSet(); @@ -61,7 +49,7 @@ public async Task Test() //await Task.Delay(20_000); - var toCollect2 = new HashSet {"Item 20",}; + var toCollect2 = new HashSet {"Item 17",}; var collected2 = new HashSet(); await foreach (var log in collector.GetLogsAsync(3, null, CancellationToken.None)) @@ -81,26 +69,16 @@ public async Task Test() } _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + + await logEmittingTask; } [Fact] public async Task Test2() { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var logger = new FakeLogger(collector); - _ = Task.Run(async () => - { - int i = 0; - while (i < 21) - { - logger.Log(LogLevel.Critical, $"Item {i}"); - _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); - - await Task.Delay(3_000, CancellationToken.None); - i++; - } - }); + var logEmittingTask = EmitLogs(collector, 20, TimeSpan.FromMilliseconds(1_000)); var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; var collected = new HashSet(); @@ -127,7 +105,7 @@ await collector.WaitForLogsAsync(log => //await Task.Delay(20_000); - var toCollect2 = new HashSet {"Item 20",}; + var toCollect2 = new HashSet {"Item 9999",}; var collected2 = new HashSet(); var waitingForLogs = collector.WaitForLogsAsync(log => @@ -146,13 +124,11 @@ await collector.WaitForLogsAsync(log => } return false; - }, timeout: TimeSpan.FromMilliseconds(2_000)); - - var pauseToTimeout = Task.Delay(99_000_000); + }, timeout: TimeSpan.FromMilliseconds(3_000)); try { - await await Task.WhenAny(waitingForLogs, pauseToTimeout); + await waitingForLogs; } catch (OperationCanceledException) { @@ -160,5 +136,31 @@ await collector.WaitForLogsAsync(log => } _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + + await logEmittingTask; + } + + private async Task EmitLogs(FakeLogCollector fakeLogCollector, int count, TimeSpan? delayBetweenEmissions = null) + { + var logger = new FakeLogger(fakeLogCollector); + + await Task.Run(async () => + { + int i = 0; + while (i < count) + { + logger.Log(LogLevel.Debug, $"Item {i}"); + _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); + + if (delayBetweenEmissions.HasValue) + { + await Task.Delay(delayBetweenEmissions.Value, CancellationToken.None); + } + + i++; + } + }); + + _outputHelper.WriteLine($"Finished emitting logs at {DateTime.Now}"); } } From a92bf7abe907dc42f1777b6aa886dcdeee63fe75 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 10:59:48 +0200 Subject: [PATCH 19/32] using retrieved index in test --- .../Logging/FakeLogCollectorTests.Waiting.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 8d485990350..0f7b977822d 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -83,7 +83,7 @@ public async Task Test2() var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; var collected = new HashSet(); - await collector.WaitForLogsAsync(log => + var index = await collector.WaitForLogsAsync(log => { _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); @@ -101,7 +101,7 @@ await collector.WaitForLogsAsync(log => return false; }); - _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); + _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}. Got index: {index}"); //await Task.Delay(20_000); @@ -124,7 +124,7 @@ await collector.WaitForLogsAsync(log => } return false; - }, timeout: TimeSpan.FromMilliseconds(3_000)); + }, startingIndex: index + 1, timeout: TimeSpan.FromMilliseconds(3_000)); try { From a6f4f2e7869949d29d2efda3d92f2806f3186df1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 14:50:17 +0200 Subject: [PATCH 20/32] guarding against concurrent movenextasync calls --- .../FakeLogCollector.LogEnumeration.cs | 79 +++++++++++-------- 1 file changed, 48 insertions(+), 31 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 9a845796263..26f60cf54e5 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -89,6 +89,9 @@ private sealed class StreamEnumerator : IAsyncEnumerator private int _index; // TODO TW: when the logs are cleared, this index remains at the value... private bool _disposed; + // Concurrent MoveNextAsync guard + private int _moveNextActive; // 0 = inactive, 1 = active (for net462 compatibility) + public StreamEnumerator( FakeLogCollector collector, int startingIndex, @@ -118,53 +121,67 @@ public StreamEnumerator( public async ValueTask MoveNextAsync() { - ThrowIfDisposed(); + if (Interlocked.CompareExchange(ref _moveNextActive, 1, 0) == 1) + { + throw new InvalidOperationException("MoveNextAsync is already in progress. Await the previous call before calling again."); + } - var masterCancellationToken = _masterCts.Token; + try + { - masterCancellationToken.ThrowIfCancellationRequested(); + ThrowIfDisposed(); - while (true) - { - TaskCompletionSource? waiter = null; + var masterCancellationToken = _masterCts.Token; + + masterCancellationToken.ThrowIfCancellationRequested(); - try + while (true) { - masterCancellationToken.ThrowIfCancellationRequested(); + TaskCompletionSource? waiter = null; - lock (_collector._records) + try { - if (_index < _collector._records.Count) + masterCancellationToken.ThrowIfCancellationRequested(); + + lock (_collector._records) { - _current = _collector._records[_index++]; - return true; + if (_index < _collector._records.Count) + { + _current = _collector._records[_index++]; + return true; + } + + // waiter needs to be subscribed within records lock + // if not: more records could be added in the meantime and the waiter could be stuck waiting even though the index is behind the actual count + waiter = _collector._logEnumerationSharedWaiter; + _collector._waitingEnumeratorCount++; } - // waiter needs to be subscribed within records lock - // if not: more records could be added in the meantime and the waiter could be stuck waiting even though the index is behind the actual count - waiter = _collector._logEnumerationSharedWaiter; - _collector._waitingEnumeratorCount++; + // Compatibility path for net462: emulate Task.WaitAsync(cancellationToken). + await AwaitWithCancellationAsync(waiter.Task, masterCancellationToken).ConfigureAwait(false); } - - // Compatibility path for net462: emulate Task.WaitAsync(cancellationToken). - await AwaitWithCancellationAsync(waiter.Task, masterCancellationToken).ConfigureAwait(false); - } - catch (OperationCanceledException) - { - lock (_collector._records) + catch (OperationCanceledException) { - // We only decrement if the shared waiter has not yet been swaped. Otherwise, the counter has been reset. - if ( - waiter is not null - && _collector._waitingEnumeratorCount > 0 - && waiter == _collector._logEnumerationSharedWaiter) + lock (_collector._records) { - _collector._waitingEnumeratorCount--; + // We only decrement if the shared waiter has not yet been swaped. Otherwise, the counter has been reset. + if ( + waiter is not null + && _collector._waitingEnumeratorCount > 0 + && waiter == _collector._logEnumerationSharedWaiter) + { + _collector._waitingEnumeratorCount--; + } } - } - throw; + throw; + } } + + } + finally + { + Volatile.Write(ref _moveNextActive, 0); } } From 1cc522a9ab319d97269debd6238e23bd8d472ae6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 16:12:31 +0200 Subject: [PATCH 21/32] minor tweaks --- .../FakeLogCollector.LogEnumeration.cs | 20 ++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 26f60cf54e5..df4c521a467 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -123,12 +123,11 @@ public async ValueTask MoveNextAsync() { if (Interlocked.CompareExchange(ref _moveNextActive, 1, 0) == 1) { - throw new InvalidOperationException("MoveNextAsync is already in progress. Await the previous call before calling again."); + throw new InvalidOperationException("MoveNextAsync is already in progress. Concurrent calls are not allowed."); } try { - ThrowIfDisposed(); var masterCancellationToken = _masterCts.Token; @@ -158,19 +157,22 @@ public async ValueTask MoveNextAsync() } // Compatibility path for net462: emulate Task.WaitAsync(cancellationToken). + // After the wait is complete in normal flow, no need to decrement because the shared waiter will be swapped and counter reset. await AwaitWithCancellationAsync(waiter.Task, masterCancellationToken).ConfigureAwait(false); } catch (OperationCanceledException) { - lock (_collector._records) + if (waiter is not null) { - // We only decrement if the shared waiter has not yet been swaped. Otherwise, the counter has been reset. - if ( - waiter is not null - && _collector._waitingEnumeratorCount > 0 - && waiter == _collector._logEnumerationSharedWaiter) + lock (_collector._records) { - _collector._waitingEnumeratorCount--; + if ( + _collector._waitingEnumeratorCount > 0 // counter can be zero during the cancellation path + && waiter == _collector._logEnumerationSharedWaiter // makes sure we adjust the counter for the same shared waiting session + ) + { + _collector._waitingEnumeratorCount--; + } } } From 9c79cda6b1dca14067f1bee61ad731082b0f39ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 19:27:48 +0200 Subject: [PATCH 22/32] wip --- .../FakeLogCollector.LogEnumeration.cs | 22 --- .../Logging/FakeLogCollector.cs | 13 +- .../Logging/FakeLogCollectorTests.Waiting.cs | 181 +++++++++++++----- 3 files changed, 137 insertions(+), 79 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index df4c521a467..2a54da3fe39 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -16,28 +16,6 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; - public async Task WaitForLogsAsync( - Func predicate, - int startingIndex = 0, - TimeSpan? timeout = null, - CancellationToken cancellationToken = default) - { - _ = Throw.IfNull(predicate); - - int index = startingIndex; // This index may be too weak - await foreach (var item in GetLogsAsync(startingIndex, timeout, cancellationToken).ConfigureAwait(false)) - { - if (predicate(item)) - { - return index; - } - - index++; - } - - return -1; - } - public IAsyncEnumerable GetLogsAsync( int startingIndex = 0, TimeSpan? timeout = null, diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index c414bf8d61b..fa5c085f515 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using System.Diagnostics; -using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Options; using Microsoft.Shared.Diagnostics; @@ -51,11 +50,18 @@ public static FakeLogCollector Create(FakeLogCollectorOptions options) /// /// Removes all accumulated log records from the collector. /// - public void Clear() + public void Clear(int? count = 0) { lock (_records) { - _records.Clear(); + if (!count.HasValue || count.Value == _records.Count) + { + _records.Clear(); + } + else + { + _records.RemoveRange(0, count.Value); + } } } @@ -153,7 +159,6 @@ internal void AddRecord(FakeLogRecord record) } // it is possible the task was already completed, but it does not matter and we can avoid locking - // TODO TW: is the above still true? _ = logEnumerationSharedWaiterToWake?.TrySetResult(true); _options.OutputSink?.Invoke(_options.OutputFormatter(record)); diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 0f7b977822d..1fa6bd1175f 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -2,9 +2,13 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Collections.Concurrent; using System.Collections.Generic; +using System.Linq; using System.Threading; using System.Threading.Tasks; +using AutoFixture.Kernel; +using Castle.Components.DictionaryAdapter; using Xunit; using Xunit.Abstractions; @@ -24,18 +28,24 @@ public async Task Test() { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var logEmittingTask = EmitLogs(collector, 20, TimeSpan.FromMilliseconds(1_000)); + var eventTracker = new ConcurrentQueue(); + + var logEmittingTask = EmitLogs( + collector, + Enumerable.Range(0, 20).Select(i => $"Item {i}"), + eventTracker, + TimeSpan.FromMilliseconds(1_000)); var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; var collected = new HashSet(); await foreach (var log in collector.GetLogsAsync(0, null, CancellationToken.None)) { - _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); + eventTracker.Enqueue($"-- Got new item: {log.Message} at {DateTime.Now}"); if (toCollect.Contains(log.Message)) { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + eventTracker.Enqueue($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); collected.Add(log.Message); } @@ -45,7 +55,7 @@ public async Task Test() } } - _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}"); + eventTracker.Enqueue($"------ Finished waiting for the first set at {DateTime.Now}"); //await Task.Delay(20_000); @@ -54,11 +64,11 @@ public async Task Test() await foreach (var log in collector.GetLogsAsync(3, null, CancellationToken.None)) { - _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); + eventTracker.Enqueue($"Got new item: {log.Message} at {DateTime.Now}"); if (toCollect2.Contains(log.Message)) { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); + eventTracker.Enqueue($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); collected2.Add(log.Message); } @@ -68,99 +78,164 @@ public async Task Test() } } - _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + eventTracker.Enqueue($"------ Finished waiting for the second set at {DateTime.Now}"); await logEmittingTask; + + OutputEventTracker(_outputHelper, eventTracker); } - [Fact] - public async Task Test2() + [Theory] + [InlineData(true, false, false)] + [InlineData(true, false, true)] + [InlineData(false, true, false)] + public async Task Test3(bool arrivesInAwaitedOrder, bool expectedToCancel, bool useClear) { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var eventTracker = new ConcurrentQueue(); - var logEmittingTask = EmitLogs(collector, 20, TimeSpan.FromMilliseconds(1_000)); + var waitingTimeout = TimeSpan.FromMilliseconds(1_000); - var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; - var collected = new HashSet(); + string[] logsToEmit = arrivesInAwaitedOrder + ? ["Sync", "Log A", "Sync", "Sync", "Log B", "Sync", "Sync", "Log C", "Sync", "Sync", "Sync"] + : ["Sync", "Log A", "Sync", "Sync", "Log B", "Sync", "Sync", "Log C", "Log D"] // Log C is not followed by Sync + ; - var index = await collector.WaitForLogsAsync(log => - { - _outputHelper.WriteLine($"-- Got new item: {log.Message} at {DateTime.Now}"); + var logEmittingTask = EmitLogs(collector, logsToEmit, eventTracker); - if (toCollect.Contains(log.Message)) - { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected.Add(log.Message); - } + var res = await AwaitSequence( + new Queue(["Log A", "Log B", "Sync"]), // Wait for event A and B followed by Sync + fromIndex: 0, + collector, + eventTracker, + timeout: waitingTimeout); - if (collected.Count == toCollect.Count) - { - return true; - } + Assert.False(res.wasCancelled); + Assert.Equal(5, res.index); - return false; - }); + if (useClear) + { + var countToClear = res.index + 1; + eventTracker.Enqueue($"Clearing collector by {countToClear} items at {DateTime.Now}"); + collector.Clear(countToClear); + } - _outputHelper.WriteLine($"------ Finished waiting for the first set at {DateTime.Now}. Got index: {index}"); + // This gap simulates an action on the tested running code expected to trigger event C followed by Sync + await Task.Delay(2_000); - //await Task.Delay(20_000); + res = await AwaitSequence( + new Queue(["Log C", "Sync"]), // Wait for Log C followed by Sync + fromIndex: useClear ? 0 : res.index + 1, + collector, + eventTracker, + timeout: waitingTimeout); - var toCollect2 = new HashSet {"Item 9999",}; - var collected2 = new HashSet(); + Assert.Equal(expectedToCancel, res.wasCancelled); + Assert.Equal(expectedToCancel ? -1 : (useClear ? 2 : 8), res.index); + + await logEmittingTask; - var waitingForLogs = collector.WaitForLogsAsync(log => + if (!useClear && !expectedToCancel) { - _outputHelper.WriteLine($"Got new item: {log.Message} at {DateTime.Now}"); + // The user may want to await partial states to perform actions, but then perform a sanity check on the whole history + var snapshot = collector.GetSnapshot(); - if (toCollect2.Contains(log.Message)) + var expectedProgression = new Queue(["Log A", "Log B", "Sync", "Log C", "Sync"]); + foreach (var item in snapshot.Select(x => x.Message)) { - _outputHelper.WriteLine($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected2.Add(log.Message); - } + if (expectedProgression.Count == 0) + { + break; + } - if (collected2.Count == toCollect2.Count) - { - return true; + if (item == expectedProgression.Peek()) + { + expectedProgression.Dequeue(); + } } - return false; - }, startingIndex: index + 1, timeout: TimeSpan.FromMilliseconds(3_000)); + Assert.Empty(expectedProgression); + } + + OutputEventTracker(_outputHelper, eventTracker); + } + private static async Task<(bool wasCancelled, int index)> AwaitSequence( + Queue sequence, + int fromIndex, + FakeLogCollector collector, + ConcurrentQueue eventTracker, + TimeSpan? timeout = null) + { try { - await waitingForLogs; + int index = fromIndex - 1; + var enumeration = collector.GetLogsAsync(startingIndex: fromIndex, timeout: timeout); + await foreach (var log in enumeration) + { + index++; + + var msg = log.Message; + var currentExpectation = sequence.Peek(); + + eventTracker.Enqueue($"Checking log: \"{msg}\"."); + + if (msg == currentExpectation) + { + sequence.Dequeue(); + + if (sequence.Count != 0) + { + continue; + } + + eventTracker.Enqueue($"Sequence satisfied at {DateTime.Now}"); + + return (false, index); + } + } } catch (OperationCanceledException) { - _outputHelper.WriteLine($"Waiting exception!!!!!!! at {DateTime.Now}"); + eventTracker.Enqueue($"Operation cancelled at {DateTime.Now}"); + return (true, -1); } - _outputHelper.WriteLine($"------ Finished waiting for the second set at {DateTime.Now}"); + throw new Exception("Enumeration was supposed to be unbound."); + } - await logEmittingTask; + private static void OutputEventTracker(ITestOutputHelper testOutputHelper, ConcurrentQueue eventTracker) + { + while (eventTracker.TryDequeue(out var item)) + { + testOutputHelper.WriteLine(item); + } } - private async Task EmitLogs(FakeLogCollector fakeLogCollector, int count, TimeSpan? delayBetweenEmissions = null) + private async Task EmitLogs( + FakeLogCollector fakeLogCollector, + IEnumerable logsToEmit, + ConcurrentQueue eventTracker, + TimeSpan? delayBetweenEmissions = null) { var logger = new FakeLogger(fakeLogCollector); await Task.Run(async () => { - int i = 0; - while (i < count) + eventTracker.Enqueue($"Started emitting logs at {DateTime.Now}"); + + foreach(var log in logsToEmit) { - logger.Log(LogLevel.Debug, $"Item {i}"); - _outputHelper.WriteLine($"Written item: Item {i} at {DateTime.Now}, currently items: {logger.Collector.Count}"); + eventTracker.Enqueue($"Emitting item: \"{log}\" at {DateTime.Now}, currently items: {logger.Collector.Count}"); + logger.Log(LogLevel.Debug, log); if (delayBetweenEmissions.HasValue) { await Task.Delay(delayBetweenEmissions.Value, CancellationToken.None); } - - i++; } }); - _outputHelper.WriteLine($"Finished emitting logs at {DateTime.Now}"); + eventTracker.Enqueue($"Finished emitting logs at {DateTime.Now}"); } } From b2fe7eee6f9a36353b70df8df7351dd52a23983d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 22:26:51 +0200 Subject: [PATCH 23/32] adjust enumerator index on clear --- .../FakeLogCollector.LogEnumeration.cs | 42 +++++++++++++++---- .../Logging/FakeLogCollector.cs | 12 +++++- 2 files changed, 44 insertions(+), 10 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 2a54da3fe39..3a1293e794b 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -11,6 +11,8 @@ namespace Microsoft.Extensions.Logging.Testing; public partial class FakeLogCollector { + private readonly List> _indexUpdates = new(); + private TaskCompletionSource _logEnumerationSharedWaiter = new(TaskCreationOptions.RunContinuationsAsynchronously); @@ -47,24 +49,38 @@ internal LogAsyncEnumerable( public IAsyncEnumerator GetAsyncEnumerator(CancellationToken enumeratorCancellationToken = default) { - return new StreamEnumerator( - _collector, - _startingIndex, - _enumerableCancellationToken, - enumeratorCancellationToken, - _timeout); + // Locking to protect against race between the enumerator creation and callback registration + lock (_collector._records) + { + var enumerator = new StreamEnumerator( + _collector, + _startingIndex, + _enumerableCancellationToken, + enumeratorCancellationToken, + e => + { + lock (_collector._records) + { + _ = _collector._indexUpdates.Remove(e.UpdateIndexByRemoved); + } + }, + _timeout); + + _collector._indexUpdates.Add(enumerator.UpdateIndexByRemoved); + return enumerator; + } } } private sealed class StreamEnumerator : IAsyncEnumerator { private readonly FakeLogCollector _collector; - private readonly CancellationTokenSource _masterCts; private readonly CancellationTokenSource? _timeoutCts; + private readonly Action? _onDispose; private FakeLogRecord? _current; - private int _index; // TODO TW: when the logs are cleared, this index remains at the value... + private int _index; private bool _disposed; // Concurrent MoveNextAsync guard @@ -75,10 +91,12 @@ public StreamEnumerator( int startingIndex, CancellationToken enumerableCancellationToken, CancellationToken enumeratorCancellationToken, + Action? onDispose, TimeSpan? timeout = null) { _collector = collector; _index = startingIndex; + _onDispose = onDispose; CancellationToken[] cancellationTokens; if (timeout.HasValue) @@ -95,6 +113,12 @@ public StreamEnumerator( _masterCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationTokens); } + public void UpdateIndexByRemoved(int removedItems) + { + // performed under lock by the calling mechanism during Clear() + _index = Math.Max(0, _index - removedItems); + } + public FakeLogRecord Current => _current ?? throw new InvalidOperationException("Enumeration not started."); public async ValueTask MoveNextAsync() @@ -199,6 +223,8 @@ public ValueTask DisposeAsync() _disposed = true; + _onDispose?.Invoke(this); + _masterCts.Cancel(); _masterCts.Dispose(); _timeoutCts?.Dispose(); diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index fa5c085f515..c6177282107 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -50,18 +50,26 @@ public static FakeLogCollector Create(FakeLogCollectorOptions options) /// /// Removes all accumulated log records from the collector. /// - public void Clear(int? count = 0) + public void Clear(int? count = null) { lock (_records) { - if (!count.HasValue || count.Value == _records.Count) + int removedCount; + if (!count.HasValue || count.Value >= _records.Count) { + removedCount = _records.Count; _records.Clear(); } else { + removedCount = count.Value; _records.RemoveRange(0, count.Value); } + + foreach(var indexUpdate in _indexUpdates) + { + indexUpdate(removedCount); + } } } From 1c4c5a99c08e8cfa8831a573f520f906447052ee Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 21 Aug 2025 22:32:15 +0200 Subject: [PATCH 24/32] demo tests --- .../Logging/FakeLogCollectorTests.Waiting.cs | 66 +------------------ 1 file changed, 1 insertion(+), 65 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 1fa6bd1175f..6d8aa8dc3a7 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -7,8 +7,6 @@ using System.Linq; using System.Threading; using System.Threading.Tasks; -using AutoFixture.Kernel; -using Castle.Components.DictionaryAdapter; using Xunit; using Xunit.Abstractions; @@ -23,73 +21,11 @@ public FakeLogCollectorTests(ITestOutputHelper outputHelper) _outputHelper = outputHelper; } - [Fact] - public async Task Test() - { - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - - var eventTracker = new ConcurrentQueue(); - - var logEmittingTask = EmitLogs( - collector, - Enumerable.Range(0, 20).Select(i => $"Item {i}"), - eventTracker, - TimeSpan.FromMilliseconds(1_000)); - - var toCollect = new HashSet {"Item 1", "Item 4", "Item 9",}; - var collected = new HashSet(); - - await foreach (var log in collector.GetLogsAsync(0, null, CancellationToken.None)) - { - eventTracker.Enqueue($"-- Got new item: {log.Message} at {DateTime.Now}"); - - if (toCollect.Contains(log.Message)) - { - eventTracker.Enqueue($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected.Add(log.Message); - } - - if (collected.Count == toCollect.Count) - { - break; - } - } - - eventTracker.Enqueue($"------ Finished waiting for the first set at {DateTime.Now}"); - - //await Task.Delay(20_000); - - var toCollect2 = new HashSet {"Item 17",}; - var collected2 = new HashSet(); - - await foreach (var log in collector.GetLogsAsync(3, null, CancellationToken.None)) - { - eventTracker.Enqueue($"Got new item: {log.Message} at {DateTime.Now}"); - - if (toCollect2.Contains(log.Message)) - { - eventTracker.Enqueue($"⏹️ Collected item: {log.Message} at {DateTime.Now}"); - collected2.Add(log.Message); - } - - if (collected2.Count == toCollect2.Count) - { - break; - } - } - - eventTracker.Enqueue($"------ Finished waiting for the second set at {DateTime.Now}"); - - await logEmittingTask; - - OutputEventTracker(_outputHelper, eventTracker); - } - [Theory] [InlineData(true, false, false)] [InlineData(true, false, true)] [InlineData(false, true, false)] - public async Task Test3(bool arrivesInAwaitedOrder, bool expectedToCancel, bool useClear) + public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCancel, bool useClear) { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); var eventTracker = new ConcurrentQueue(); From 3c9c668e3e60acbfee88f7cbebd345d65731e019 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Fri, 22 Aug 2025 10:38:44 +0200 Subject: [PATCH 25/32] extend demo test to better illustrate --- .../Logging/FakeLogCollectorTests.Waiting.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 6d8aa8dc3a7..ba238a56648 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -33,8 +33,8 @@ public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCan var waitingTimeout = TimeSpan.FromMilliseconds(1_000); string[] logsToEmit = arrivesInAwaitedOrder - ? ["Sync", "Log A", "Sync", "Sync", "Log B", "Sync", "Sync", "Log C", "Sync", "Sync", "Sync"] - : ["Sync", "Log A", "Sync", "Sync", "Log B", "Sync", "Sync", "Log C", "Log D"] // Log C is not followed by Sync + ? ["Sync", "Log A", "LogC", "Sync", "Sync", "Log B", "Sync", "Sync", "Log C", "Sync", "Sync", "Sync"] + : ["Sync", "Log A", "LogC", "Sync", "Sync", "Log B", "Sync", "Sync", "Log C", "Log D"] // Log C after A, B, C progression is not followed by Sync ; var logEmittingTask = EmitLogs(collector, logsToEmit, eventTracker); @@ -47,7 +47,7 @@ public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCan timeout: waitingTimeout); Assert.False(res.wasCancelled); - Assert.Equal(5, res.index); + Assert.Equal(6, res.index); if (useClear) { @@ -67,7 +67,7 @@ public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCan timeout: waitingTimeout); Assert.Equal(expectedToCancel, res.wasCancelled); - Assert.Equal(expectedToCancel ? -1 : (useClear ? 2 : 8), res.index); + Assert.Equal(expectedToCancel ? -1 : (useClear ? 2 : 9), res.index); await logEmittingTask; From 2d955526594911a886ba1e9779ecf7a45b849868 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Tue, 26 Aug 2025 14:12:46 +0200 Subject: [PATCH 26/32] remove timeout param --- .../FakeLogCollector.LogEnumeration.cs | 26 +++---------------- .../Logging/FakeLogCollectorTests.Waiting.cs | 3 ++- 2 files changed, 6 insertions(+), 23 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 3a1293e794b..0fa2922ca75 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -20,30 +20,26 @@ public partial class FakeLogCollector public IAsyncEnumerable GetLogsAsync( int startingIndex = 0, - TimeSpan? timeout = null, CancellationToken cancellationToken = default) { _ = Throw.IfOutOfRange(startingIndex, 0, int.MaxValue); - return new LogAsyncEnumerable(this, startingIndex, timeout, cancellationToken); + return new LogAsyncEnumerable(this, startingIndex, cancellationToken); } private class LogAsyncEnumerable : IAsyncEnumerable { private readonly int _startingIndex; - private readonly TimeSpan? _timeout; private readonly FakeLogCollector _collector; private readonly CancellationToken _enumerableCancellationToken; internal LogAsyncEnumerable( FakeLogCollector collector, int startingIndex, - TimeSpan? timeout, CancellationToken enumerableCancellationToken) { _collector = collector; _startingIndex = startingIndex; - _timeout = timeout; _enumerableCancellationToken = enumerableCancellationToken; } @@ -63,8 +59,7 @@ public IAsyncEnumerator GetAsyncEnumerator(CancellationToken enum { _ = _collector._indexUpdates.Remove(e.UpdateIndexByRemoved); } - }, - _timeout); + }); _collector._indexUpdates.Add(enumerator.UpdateIndexByRemoved); return enumerator; @@ -91,26 +86,13 @@ public StreamEnumerator( int startingIndex, CancellationToken enumerableCancellationToken, CancellationToken enumeratorCancellationToken, - Action? onDispose, - TimeSpan? timeout = null) + Action? onDispose) { _collector = collector; _index = startingIndex; _onDispose = onDispose; - CancellationToken[] cancellationTokens; - if (timeout.HasValue) - { - var timeoutCts = new CancellationTokenSource(timeout.Value); - _timeoutCts = timeoutCts; - cancellationTokens = [enumerableCancellationToken, enumeratorCancellationToken, timeoutCts.Token]; - } - else - { - cancellationTokens = [enumerableCancellationToken, enumeratorCancellationToken]; - } - - _masterCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationTokens); + _masterCts = CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]); } public void UpdateIndexByRemoved(int removedItems) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index ba238a56648..0c16eb184fd 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -103,10 +103,11 @@ public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCan ConcurrentQueue eventTracker, TimeSpan? timeout = null) { + using var cts = timeout.HasValue ? new CancellationTokenSource(timeout.Value) : new CancellationTokenSource(); try { int index = fromIndex - 1; - var enumeration = collector.GetLogsAsync(startingIndex: fromIndex, timeout: timeout); + var enumeration = collector.GetLogsAsync(startingIndex: fromIndex, cancellationToken: cts.Token); await foreach (var log in enumeration) { index++; From 75b515397cd3d2f903382c08e5570afab757fd45 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Tue, 26 Aug 2025 14:25:38 +0200 Subject: [PATCH 27/32] remove startingIndex param support --- .../FakeLogCollector.LogEnumeration.cs | 41 ++----------------- .../Logging/FakeLogCollector.cs | 8 ---- .../Logging/FakeLogCollectorTests.Waiting.cs | 9 +++- 3 files changed, 11 insertions(+), 47 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 0fa2922ca75..67c6d88d42f 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -11,35 +11,26 @@ namespace Microsoft.Extensions.Logging.Testing; public partial class FakeLogCollector { - private readonly List> _indexUpdates = new(); - private TaskCompletionSource _logEnumerationSharedWaiter = new(TaskCreationOptions.RunContinuationsAsynchronously); private int _waitingEnumeratorCount; - public IAsyncEnumerable GetLogsAsync( - int startingIndex = 0, - CancellationToken cancellationToken = default) + public IAsyncEnumerable GetLogsAsync(CancellationToken cancellationToken = default) { - _ = Throw.IfOutOfRange(startingIndex, 0, int.MaxValue); - - return new LogAsyncEnumerable(this, startingIndex, cancellationToken); + return new LogAsyncEnumerable(this, cancellationToken); } private class LogAsyncEnumerable : IAsyncEnumerable { - private readonly int _startingIndex; private readonly FakeLogCollector _collector; private readonly CancellationToken _enumerableCancellationToken; internal LogAsyncEnumerable( FakeLogCollector collector, - int startingIndex, CancellationToken enumerableCancellationToken) { _collector = collector; - _startingIndex = startingIndex; _enumerableCancellationToken = enumerableCancellationToken; } @@ -50,18 +41,9 @@ public IAsyncEnumerator GetAsyncEnumerator(CancellationToken enum { var enumerator = new StreamEnumerator( _collector, - _startingIndex, _enumerableCancellationToken, - enumeratorCancellationToken, - e => - { - lock (_collector._records) - { - _ = _collector._indexUpdates.Remove(e.UpdateIndexByRemoved); - } - }); + enumeratorCancellationToken); - _collector._indexUpdates.Add(enumerator.UpdateIndexByRemoved); return enumerator; } } @@ -71,8 +53,6 @@ private sealed class StreamEnumerator : IAsyncEnumerator { private readonly FakeLogCollector _collector; private readonly CancellationTokenSource _masterCts; - private readonly CancellationTokenSource? _timeoutCts; - private readonly Action? _onDispose; private FakeLogRecord? _current; private int _index; @@ -83,24 +63,14 @@ private sealed class StreamEnumerator : IAsyncEnumerator public StreamEnumerator( FakeLogCollector collector, - int startingIndex, CancellationToken enumerableCancellationToken, - CancellationToken enumeratorCancellationToken, - Action? onDispose) + CancellationToken enumeratorCancellationToken) { _collector = collector; - _index = startingIndex; - _onDispose = onDispose; _masterCts = CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]); } - public void UpdateIndexByRemoved(int removedItems) - { - // performed under lock by the calling mechanism during Clear() - _index = Math.Max(0, _index - removedItems); - } - public FakeLogRecord Current => _current ?? throw new InvalidOperationException("Enumeration not started."); public async ValueTask MoveNextAsync() @@ -205,11 +175,8 @@ public ValueTask DisposeAsync() _disposed = true; - _onDispose?.Invoke(this); - _masterCts.Cancel(); _masterCts.Dispose(); - _timeoutCts?.Dispose(); return default; } diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index c6177282107..1451efaa20c 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -54,22 +54,14 @@ public void Clear(int? count = null) { lock (_records) { - int removedCount; if (!count.HasValue || count.Value >= _records.Count) { - removedCount = _records.Count; _records.Clear(); } else { - removedCount = count.Value; _records.RemoveRange(0, count.Value); } - - foreach(var indexUpdate in _indexUpdates) - { - indexUpdate(removedCount); - } } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index 0c16eb184fd..bfb327d3e97 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -106,12 +106,17 @@ public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCan using var cts = timeout.HasValue ? new CancellationTokenSource(timeout.Value) : new CancellationTokenSource(); try { - int index = fromIndex - 1; - var enumeration = collector.GetLogsAsync(startingIndex: fromIndex, cancellationToken: cts.Token); + int index = -1; + var enumeration = collector.GetLogsAsync(cancellationToken: cts.Token); await foreach (var log in enumeration) { index++; + if (index < fromIndex) + { + continue; + } + var msg = log.Message; var currentExpectation = sequence.Peek(); From 77d69939de63214b90e9a28135da70a3cd155983 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Tue, 26 Aug 2025 17:59:55 +0200 Subject: [PATCH 28/32] discarding the Clear(count) functionality --- .../FakeLogCollector.LogEnumeration.cs | 22 ++++--------------- .../Logging/FakeLogCollector.cs | 11 ++-------- .../Logging/FakeLogCollectorTests.Waiting.cs | 20 +++++------------ 3 files changed, 12 insertions(+), 41 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 67c6d88d42f..19c4ff536c8 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -5,7 +5,6 @@ using System.Collections.Generic; using System.Threading; using System.Threading.Tasks; -using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; @@ -17,9 +16,7 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; public IAsyncEnumerable GetLogsAsync(CancellationToken cancellationToken = default) - { - return new LogAsyncEnumerable(this, cancellationToken); - } + => new LogAsyncEnumerable(this, cancellationToken); private class LogAsyncEnumerable : IAsyncEnumerable { @@ -34,19 +31,9 @@ internal LogAsyncEnumerable( _enumerableCancellationToken = enumerableCancellationToken; } - public IAsyncEnumerator GetAsyncEnumerator(CancellationToken enumeratorCancellationToken = default) - { - // Locking to protect against race between the enumerator creation and callback registration - lock (_collector._records) - { - var enumerator = new StreamEnumerator( - _collector, - _enumerableCancellationToken, - enumeratorCancellationToken); - - return enumerator; - } - } + public IAsyncEnumerator GetAsyncEnumerator( + CancellationToken enumeratorCancellationToken = default) + => new StreamEnumerator(_collector, _enumerableCancellationToken, enumeratorCancellationToken); } private sealed class StreamEnumerator : IAsyncEnumerator @@ -67,7 +54,6 @@ public StreamEnumerator( CancellationToken enumeratorCancellationToken) { _collector = collector; - _masterCts = CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]); } diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index 1451efaa20c..b4c4526b50b 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -50,18 +50,11 @@ public static FakeLogCollector Create(FakeLogCollectorOptions options) /// /// Removes all accumulated log records from the collector. /// - public void Clear(int? count = null) + public void Clear() { lock (_records) { - if (!count.HasValue || count.Value >= _records.Count) - { - _records.Clear(); - } - else - { - _records.RemoveRange(0, count.Value); - } + _records.Clear(); } } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index bfb327d3e97..f7e09783220 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -22,10 +22,9 @@ public FakeLogCollectorTests(ITestOutputHelper outputHelper) } [Theory] - [InlineData(true, false, false)] - [InlineData(true, false, true)] - [InlineData(false, true, false)] - public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCancel, bool useClear) + [InlineData(true, false)] + [InlineData(false, true)] + public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCancel) { var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); var eventTracker = new ConcurrentQueue(); @@ -49,29 +48,22 @@ public async Task LogAwaitingDemo(bool arrivesInAwaitedOrder, bool expectedToCan Assert.False(res.wasCancelled); Assert.Equal(6, res.index); - if (useClear) - { - var countToClear = res.index + 1; - eventTracker.Enqueue($"Clearing collector by {countToClear} items at {DateTime.Now}"); - collector.Clear(countToClear); - } - // This gap simulates an action on the tested running code expected to trigger event C followed by Sync await Task.Delay(2_000); res = await AwaitSequence( new Queue(["Log C", "Sync"]), // Wait for Log C followed by Sync - fromIndex: useClear ? 0 : res.index + 1, + fromIndex: res.index + 1, collector, eventTracker, timeout: waitingTimeout); Assert.Equal(expectedToCancel, res.wasCancelled); - Assert.Equal(expectedToCancel ? -1 : (useClear ? 2 : 9), res.index); + Assert.Equal(expectedToCancel ? -1 : 9, res.index); await logEmittingTask; - if (!useClear && !expectedToCancel) + if (!expectedToCancel) { // The user may want to await partial states to perform actions, but then perform a sanity check on the whole history var snapshot = collector.GetSnapshot(); From fd74ce66c39b6ad7a3fa0b2a096c3299343b4d43 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 28 Aug 2025 13:55:17 +0200 Subject: [PATCH 29/32] count param --- .../FakeLogCollector.LogEnumeration.cs | 20 +++++++++++--- .../Logging/FakeLogCollectorTests.Waiting.cs | 27 +++++++++++++++++++ 2 files changed, 44 insertions(+), 3 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 19c4ff536c8..fdc0fd99431 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -15,30 +15,36 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; - public IAsyncEnumerable GetLogsAsync(CancellationToken cancellationToken = default) - => new LogAsyncEnumerable(this, cancellationToken); + public IAsyncEnumerable GetLogsAsync( + int count = int.MaxValue, + CancellationToken cancellationToken = default) + => new LogAsyncEnumerable(this, count, cancellationToken); private class LogAsyncEnumerable : IAsyncEnumerable { private readonly FakeLogCollector _collector; + private readonly int _count; private readonly CancellationToken _enumerableCancellationToken; internal LogAsyncEnumerable( FakeLogCollector collector, + int count, CancellationToken enumerableCancellationToken) { _collector = collector; + _count = count; _enumerableCancellationToken = enumerableCancellationToken; } public IAsyncEnumerator GetAsyncEnumerator( CancellationToken enumeratorCancellationToken = default) - => new StreamEnumerator(_collector, _enumerableCancellationToken, enumeratorCancellationToken); + => new StreamEnumerator(_collector, _count, _enumerableCancellationToken, enumeratorCancellationToken); } private sealed class StreamEnumerator : IAsyncEnumerator { private readonly FakeLogCollector _collector; + private readonly int _logCount; private readonly CancellationTokenSource _masterCts; private FakeLogRecord? _current; @@ -50,10 +56,12 @@ private sealed class StreamEnumerator : IAsyncEnumerator public StreamEnumerator( FakeLogCollector collector, + int logCount, CancellationToken enumerableCancellationToken, CancellationToken enumeratorCancellationToken) { _collector = collector; + _logCount = logCount; _masterCts = CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]); } @@ -78,6 +86,12 @@ public async ValueTask MoveNextAsync() { TaskCompletionSource? waiter = null; + if (_index >= _logCount) + { + _current = null; + return false; + } + try { masterCancellationToken.ThrowIfCancellationRequested(); diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index f7e09783220..f9d99d1856f 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -21,6 +21,33 @@ public FakeLogCollectorTests(ITestOutputHelper outputHelper) _outputHelper = outputHelper; } + [Fact] + public async Task AwaitLogCount() + { + var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var eventTracker = new ConcurrentQueue(); + + string[] logsToEmit = ["1", "2", "3", "4"]; + + var logEmittingTask = EmitLogs(collector, logsToEmit, eventTracker); + + var retrievedLogs = new List(); + + var enumeration = collector.GetLogsAsync(count: 2, cancellationToken: CancellationToken.None); + await foreach (var log in enumeration) + { + var msg = log.Message; + eventTracker.Enqueue($"Received log: \"{msg}\"."); + retrievedLogs.Add(msg); + } + + await logEmittingTask; + + Assert.Equivalent(new[] { "1", "2" }, retrievedLogs); + + OutputEventTracker(_outputHelper, eventTracker); + } + [Theory] [InlineData(true, false)] [InlineData(false, true)] From 92869304738320a0c43a90dad2e4a5ff44396dcb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Thu, 28 Aug 2025 13:55:35 +0200 Subject: [PATCH 30/32] issue with concurrent Clear call and maxItems --- .../FakeLogCollector.LogEnumeration.cs | 59 +++++++++++++------ .../Logging/FakeLogCollector.cs | 7 ++- .../Logging/FakeLogCollectorTests.Waiting.cs | 2 +- 3 files changed, 46 insertions(+), 22 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index fdc0fd99431..a988014e579 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -2,67 +2,83 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Collections.Concurrent; using System.Collections.Generic; using System.Threading; using System.Threading.Tasks; +using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; public partial class FakeLogCollector { - private TaskCompletionSource _logEnumerationSharedWaiter = + private int _recordCollectionVersion = 0; + + private TaskCompletionSource _logEnumerationSharedWaiter = new(TaskCreationOptions.RunContinuationsAsynchronously); private int _waitingEnumeratorCount; public IAsyncEnumerable GetLogsAsync( - int count = int.MaxValue, + int? maxItems = null, CancellationToken cancellationToken = default) - => new LogAsyncEnumerable(this, count, cancellationToken); + { + if (maxItems < 0) + { + Throw.ArgumentOutOfRangeException(nameof(maxItems), maxItems, "Must be null (unlimited) or non-negative integer value."); + } + + return new LogAsyncEnumerable(this, maxItems, cancellationToken); + } private class LogAsyncEnumerable : IAsyncEnumerable { private readonly FakeLogCollector _collector; - private readonly int _count; + private readonly int? _maxItems; private readonly CancellationToken _enumerableCancellationToken; internal LogAsyncEnumerable( FakeLogCollector collector, - int count, + int? maxItems, CancellationToken enumerableCancellationToken) { _collector = collector; - _count = count; + _maxItems = maxItems; _enumerableCancellationToken = enumerableCancellationToken; } public IAsyncEnumerator GetAsyncEnumerator( CancellationToken enumeratorCancellationToken = default) - => new StreamEnumerator(_collector, _count, _enumerableCancellationToken, enumeratorCancellationToken); + => new StreamEnumerator(_collector, _maxItems, _enumerableCancellationToken, enumeratorCancellationToken); } private sealed class StreamEnumerator : IAsyncEnumerator { private readonly FakeLogCollector _collector; - private readonly int _logCount; + private readonly int? _maxItems; private readonly CancellationTokenSource _masterCts; private FakeLogRecord? _current; private int _index; private bool _disposed; + private int _observedRecordCollectionVersion; + private int _returnedItemCount; // Concurrent MoveNextAsync guard private int _moveNextActive; // 0 = inactive, 1 = active (for net462 compatibility) public StreamEnumerator( FakeLogCollector collector, - int logCount, + int? maxItems, CancellationToken enumerableCancellationToken, CancellationToken enumeratorCancellationToken) { _collector = collector; - _logCount = logCount; - _masterCts = CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]); + _maxItems = maxItems; + _masterCts = enumerableCancellationToken.CanBeCanceled || enumeratorCancellationToken.CanBeCanceled + ? CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]) + : new CancellationTokenSource(); + _observedRecordCollectionVersion = collector._recordCollectionVersion; } public FakeLogRecord Current => _current ?? throw new InvalidOperationException("Enumeration not started."); @@ -84,13 +100,7 @@ public async ValueTask MoveNextAsync() while (true) { - TaskCompletionSource? waiter = null; - - if (_index >= _logCount) - { - _current = null; - return false; - } + TaskCompletionSource? waiter = null; try { @@ -98,9 +108,22 @@ public async ValueTask MoveNextAsync() lock (_collector._records) { + if (_observedRecordCollectionVersion != _collector._recordCollectionVersion) + { + _index = 0; // based on assumption that version changed on full collection clear + _observedRecordCollectionVersion = _collector._recordCollectionVersion; + } + + if (_maxItems.HasValue && _returnedItemCount >= _maxItems) + { + _current = null; + return false; + } + if (_index < _collector._records.Count) { _current = _collector._records[_index++]; + _returnedItemCount++; return true; } diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs index b4c4526b50b..75366ee940f 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -55,6 +55,7 @@ public void Clear() lock (_records) { _records.Clear(); + _recordCollectionVersion++; } } @@ -137,7 +138,7 @@ internal void AddRecord(FakeLogRecord record) return; } - TaskCompletionSource? logEnumerationSharedWaiterToWake = null; + TaskCompletionSource? logEnumerationSharedWaiterToWake = null; lock (_records) { @@ -146,13 +147,13 @@ internal void AddRecord(FakeLogRecord record) if (_waitingEnumeratorCount > 0) { logEnumerationSharedWaiterToWake = _logEnumerationSharedWaiter; - _logEnumerationSharedWaiter = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + _logEnumerationSharedWaiter = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); _waitingEnumeratorCount = 0; } } // it is possible the task was already completed, but it does not matter and we can avoid locking - _ = logEnumerationSharedWaiterToWake?.TrySetResult(true); + _ = logEnumerationSharedWaiterToWake?.TrySetResult(null); _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index f9d99d1856f..a2bb26cb1a2 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -33,7 +33,7 @@ public async Task AwaitLogCount() var retrievedLogs = new List(); - var enumeration = collector.GetLogsAsync(count: 2, cancellationToken: CancellationToken.None); + var enumeration = collector.GetLogsAsync(maxItems: 2, cancellationToken: CancellationToken.None); await foreach (var log in enumeration) { var msg = log.Message; From c1baae9118c67e375287d811ab374e2addd2e688 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 8 Sep 2025 09:44:39 +0200 Subject: [PATCH 31/32] count removed --- .../FakeLogCollector.LogEnumeration.cs | 27 +++---------------- .../Logging/FakeLogCollectorTests.Waiting.cs | 27 ------------------- 2 files changed, 3 insertions(+), 51 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index a988014e579..48fc10b5e9f 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -19,62 +19,48 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; - public IAsyncEnumerable GetLogsAsync( - int? maxItems = null, - CancellationToken cancellationToken = default) + public IAsyncEnumerable GetLogsAsync(CancellationToken cancellationToken = default) { - if (maxItems < 0) - { - Throw.ArgumentOutOfRangeException(nameof(maxItems), maxItems, "Must be null (unlimited) or non-negative integer value."); - } - - return new LogAsyncEnumerable(this, maxItems, cancellationToken); + return new LogAsyncEnumerable(this, cancellationToken); } private class LogAsyncEnumerable : IAsyncEnumerable { private readonly FakeLogCollector _collector; - private readonly int? _maxItems; private readonly CancellationToken _enumerableCancellationToken; internal LogAsyncEnumerable( FakeLogCollector collector, - int? maxItems, CancellationToken enumerableCancellationToken) { _collector = collector; - _maxItems = maxItems; _enumerableCancellationToken = enumerableCancellationToken; } public IAsyncEnumerator GetAsyncEnumerator( CancellationToken enumeratorCancellationToken = default) - => new StreamEnumerator(_collector, _maxItems, _enumerableCancellationToken, enumeratorCancellationToken); + => new StreamEnumerator(_collector, _enumerableCancellationToken, enumeratorCancellationToken); } private sealed class StreamEnumerator : IAsyncEnumerator { private readonly FakeLogCollector _collector; - private readonly int? _maxItems; private readonly CancellationTokenSource _masterCts; private FakeLogRecord? _current; private int _index; private bool _disposed; private int _observedRecordCollectionVersion; - private int _returnedItemCount; // Concurrent MoveNextAsync guard private int _moveNextActive; // 0 = inactive, 1 = active (for net462 compatibility) public StreamEnumerator( FakeLogCollector collector, - int? maxItems, CancellationToken enumerableCancellationToken, CancellationToken enumeratorCancellationToken) { _collector = collector; - _maxItems = maxItems; _masterCts = enumerableCancellationToken.CanBeCanceled || enumeratorCancellationToken.CanBeCanceled ? CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]) : new CancellationTokenSource(); @@ -114,16 +100,9 @@ public async ValueTask MoveNextAsync() _observedRecordCollectionVersion = _collector._recordCollectionVersion; } - if (_maxItems.HasValue && _returnedItemCount >= _maxItems) - { - _current = null; - return false; - } - if (_index < _collector._records.Count) { _current = _collector._records[_index++]; - _returnedItemCount++; return true; } diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs index a2bb26cb1a2..f7e09783220 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.Waiting.cs @@ -21,33 +21,6 @@ public FakeLogCollectorTests(ITestOutputHelper outputHelper) _outputHelper = outputHelper; } - [Fact] - public async Task AwaitLogCount() - { - var collector = FakeLogCollector.Create(new FakeLogCollectorOptions()); - var eventTracker = new ConcurrentQueue(); - - string[] logsToEmit = ["1", "2", "3", "4"]; - - var logEmittingTask = EmitLogs(collector, logsToEmit, eventTracker); - - var retrievedLogs = new List(); - - var enumeration = collector.GetLogsAsync(maxItems: 2, cancellationToken: CancellationToken.None); - await foreach (var log in enumeration) - { - var msg = log.Message; - eventTracker.Enqueue($"Received log: \"{msg}\"."); - retrievedLogs.Add(msg); - } - - await logEmittingTask; - - Assert.Equivalent(new[] { "1", "2" }, retrievedLogs); - - OutputEventTracker(_outputHelper, eventTracker); - } - [Theory] [InlineData(true, false)] [InlineData(false, true)] From 9a358ce7e267ac0e7124ec9c1a7a5fffb72a1954 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Wiesner?= Date: Mon, 8 Sep 2025 10:14:26 +0200 Subject: [PATCH 32/32] minor changes --- .../FakeLogCollector.LogEnumeration.cs | 47 +++++++++---------- 1 file changed, 21 insertions(+), 26 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs index 48fc10b5e9f..76a8b604b03 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -2,17 +2,15 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; -using System.Collections.Concurrent; using System.Collections.Generic; using System.Threading; using System.Threading.Tasks; -using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; public partial class FakeLogCollector { - private int _recordCollectionVersion = 0; + private int _recordCollectionVersion; private TaskCompletionSource _logEnumerationSharedWaiter = new(TaskCreationOptions.RunContinuationsAsynchronously); @@ -20,9 +18,7 @@ public partial class FakeLogCollector private int _waitingEnumeratorCount; public IAsyncEnumerable GetLogsAsync(CancellationToken cancellationToken = default) - { - return new LogAsyncEnumerable(this, cancellationToken); - } + => new LogAsyncEnumerable(this, cancellationToken); private class LogAsyncEnumerable : IAsyncEnumerable { @@ -45,7 +41,7 @@ public IAsyncEnumerator GetAsyncEnumerator( private sealed class StreamEnumerator : IAsyncEnumerator { private readonly FakeLogCollector _collector; - private readonly CancellationTokenSource _masterCts; + private readonly CancellationTokenSource _mainCts; private FakeLogRecord? _current; private int _index; @@ -53,7 +49,7 @@ private sealed class StreamEnumerator : IAsyncEnumerator private int _observedRecordCollectionVersion; // Concurrent MoveNextAsync guard - private int _moveNextActive; // 0 = inactive, 1 = active (for net462 compatibility) + private int _moveNextActive; // 0 = inactive, 1 = active (int type used for net462 compatibility) public StreamEnumerator( FakeLogCollector collector, @@ -61,7 +57,7 @@ public StreamEnumerator( CancellationToken enumeratorCancellationToken) { _collector = collector; - _masterCts = enumerableCancellationToken.CanBeCanceled || enumeratorCancellationToken.CanBeCanceled + _mainCts = enumerableCancellationToken.CanBeCanceled || enumeratorCancellationToken.CanBeCanceled ? CancellationTokenSource.CreateLinkedTokenSource([enumerableCancellationToken, enumeratorCancellationToken]) : new CancellationTokenSource(); _observedRecordCollectionVersion = collector._recordCollectionVersion; @@ -80,7 +76,7 @@ public async ValueTask MoveNextAsync() { ThrowIfDisposed(); - var masterCancellationToken = _masterCts.Token; + var masterCancellationToken = _mainCts.Token; masterCancellationToken.ThrowIfCancellationRequested(); @@ -143,6 +139,21 @@ public async ValueTask MoveNextAsync() } } + public ValueTask DisposeAsync() + { + if (_disposed) + { + return default; + } + + _disposed = true; + + _mainCts.Cancel(); + _mainCts.Dispose(); + + return default; + } + private static async Task AwaitWithCancellationAsync(Task task, CancellationToken cancellationToken) { if (!cancellationToken.CanBeCanceled || task.IsCompleted) @@ -167,22 +178,6 @@ private static async Task AwaitWithCancellationAsync(Task task, CancellationToke } } - // TODO TW: consider pending wait and exception handling - public ValueTask DisposeAsync() - { - if (_disposed) - { - return default; - } - - _disposed = true; - - _masterCts.Cancel(); - _masterCts.Dispose(); - - return default; - } - private void ThrowIfDisposed() { if (_disposed)