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..13e47913919 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.LogEnumeration.cs @@ -0,0 +1,214 @@ +// 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.Diagnostics.CodeAnalysis; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Logging.Testing; + +public partial class FakeLogCollector +{ + private volatile int _recordCollectionVersion; + + private TaskCompletionSource _logEnumerationSharedWaiter = + new(TaskCreationOptions.RunContinuationsAsynchronously); + + private int _waitingEnumeratorCount; + + /// + /// Asynchronously enumerates the instances collected by this . + /// + /// + /// A token that can be used to cancel the asynchronous enumeration. This token is observed while creating + /// and iterating the asynchronous sequence. + /// + /// + /// An that yields instances as they are written. + /// The sequence does not have a completion state defined and awaits subsequent elements indefinitely, + /// or stops when cancellation is requested. + /// + /// + /// The returned sequence is hot: it streams log records as they become available and may block between + /// elements while waiting for additional logs to be written. Multiple independent enumerations can be created + /// by calling this method multiple times. + /// + /// + /// Thrown when the provided or the enumerator's own cancellation token + /// is canceled while waiting for the next log record. + /// + /// + /// The following example shows how to consume logs asynchronously: + /// + /// + [Experimental(DiagnosticIds.Experiments.Telemetry)] + public IAsyncEnumerable GetLogsAsync(CancellationToken cancellationToken = default) + => new LogAsyncEnumerable(this, cancellationToken); + + private sealed class LogAsyncEnumerable : IAsyncEnumerable + { + private readonly FakeLogCollector _collector; + private readonly CancellationToken _enumerableCancellationToken; + + internal LogAsyncEnumerable( + FakeLogCollector collector, + CancellationToken enumerableCancellationToken) + { + _collector = collector; + _enumerableCancellationToken = enumerableCancellationToken; + } + + public IAsyncEnumerator GetAsyncEnumerator( + CancellationToken enumeratorCancellationToken = default) + => new StreamEnumerator(_collector, _enumerableCancellationToken, enumeratorCancellationToken); + } + + private sealed class StreamEnumerator : IAsyncEnumerator + { + private readonly FakeLogCollector _collector; + private readonly CancellationTokenSource _mainCts; + private int _index; + private int _disposed; // 0 = false, 1 = true (int type used for net462 compatibility) + private int _observedRecordCollectionVersion; + + // Concurrent MoveNextAsync guard + private int _moveNextActive; // 0 = inactive, 1 = active (int type used for net462 compatibility) + + public StreamEnumerator( + FakeLogCollector collector, + CancellationToken enumerableCancellationToken, + CancellationToken enumeratorCancellationToken) + { + _collector = collector; + _mainCts = enumerableCancellationToken.CanBeCanceled || enumeratorCancellationToken.CanBeCanceled + ? CancellationTokenSource.CreateLinkedTokenSource(enumerableCancellationToken, enumeratorCancellationToken) + : new CancellationTokenSource(); + _observedRecordCollectionVersion = collector._recordCollectionVersion; + } + + public FakeLogRecord Current + { + get => field ?? throw new InvalidOperationException("Enumeration not started."); + private set; + } + + public async ValueTask MoveNextAsync() + { + if (Interlocked.CompareExchange(ref _moveNextActive, 1, 0) == 1) + { + throw new InvalidOperationException("MoveNextAsync is already in progress. Concurrent calls are not allowed."); + } + + try + { + ThrowIfDisposed(); + + var mainCancellationToken = _mainCts.Token; + + mainCancellationToken.ThrowIfCancellationRequested(); + + while (true) + { + TaskCompletionSource? waiter = null; + + try + { + mainCancellationToken.ThrowIfCancellationRequested(); + + lock (_collector._records) + { + int currentVersion = _collector._recordCollectionVersion; + if (_observedRecordCollectionVersion != currentVersion) + { + _index = 0; // based on assumption that version changed on full collection clear + _observedRecordCollectionVersion = currentVersion; + } + + 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++; + } + + // After the wait is complete in normal flow, no need to decrement because the shared waiter will be swapped and counter reset. + _ = await waiter.Task.WaitAsync(mainCancellationToken).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + if (waiter is not null) + { + lock (_collector._records) + { + 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--; + } + } + } + + throw; + } + } + + } + finally + { + Volatile.Write(ref _moveNextActive, 0); + } + } + +#if !NETCOREAPP + public ValueTask DisposeAsync() + { + if (Interlocked.Exchange(ref _disposed, 1) == 1) + { + return default; + } + + _mainCts.Cancel(); + _mainCts.Dispose(); + + return default; + } +#else + public async ValueTask DisposeAsync() + { + if (Interlocked.Exchange(ref _disposed, 1) == 1) + { + return; + } + + await _mainCts.CancelAsync().ConfigureAwait(false); + _mainCts.Dispose(); + } +#endif + + private void ThrowIfDisposed() + { + if (Volatile.Read(ref _disposed) == 1) + { + 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 24b9f933b9c..f2297bcc094 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogCollector.cs @@ -4,6 +4,8 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; using Microsoft.Extensions.Options; using Microsoft.Shared.Diagnostics; @@ -14,7 +16,7 @@ namespace Microsoft.Extensions.Logging.Testing; /// [DebuggerDisplay("Count = {Count}, LatestRecord = {LatestRecord}")] [DebuggerTypeProxy(typeof(FakeLogCollectorDebugView))] -public class FakeLogCollector +public partial class FakeLogCollector { private readonly List _records = []; private readonly FakeLogCollectorOptions _options; @@ -53,10 +55,16 @@ public void Clear() { lock (_records) { - _records.Clear(); + ClearRecordsCore(); } } + private void ClearRecordsCore() + { + _records.Clear(); + _ = Interlocked.Increment(ref _recordCollectionVersion); + } + /// /// Gets the records that are held by the collector. /// @@ -71,7 +79,7 @@ public IReadOnlyList GetSnapshot(bool clear = false) var records = _records.ToArray(); if (clear) { - _records.Clear(); + ClearRecordsCore(); } return records; @@ -136,11 +144,23 @@ internal void AddRecord(FakeLogRecord record) return; } + TaskCompletionSource? logEnumerationSharedWaiterToWake = null; + lock (_records) { _records.Add(record); + + if (_waitingEnumeratorCount > 0) + { + logEnumerationSharedWaiterToWake = _logEnumerationSharedWaiter; + _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(null); + _options.OutputSink?.Invoke(_options.OutputFormatter(record)); } diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj index c38dcdea395..3b127da2b50 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj @@ -12,6 +12,7 @@ true true true + true $(NoWarn);SYSLIB1100;SYSLIB1101 diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.LogEnumeration.cs b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.LogEnumeration.cs new file mode 100644 index 00000000000..a54dafb3411 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.LogEnumeration.cs @@ -0,0 +1,222 @@ +// 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 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; + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task GetLogsAsync_EnumeratesNewLogsAsynchronouslyWithCancellationSupport(bool isWaitCancelled) + { + var fakeLogCollector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var logger = new FakeLogger(fakeLogCollector); + var eventTracker = new ConcurrentQueue(); + + using var cts = new CancellationTokenSource(); + var cancellationToken = cts.Token; + + var awaitSequenceTask = AwaitSequence( + new Queue(["Log A", "Log B", "Sync"]), // Wait for event A and B followed by Sync + fromIndex: 0, + fakeLogCollector, + eventTracker, + cancellationToken: cancellationToken); + + EmitLogs(logger, ["Sync", "Log A", "Log C", "Sync", "Sync", "Log B", "Sync", "Sync"], eventTracker); + + await AssertAwaitingTaskCompleted(awaitSequenceTask); + + var res = await awaitSequenceTask; + + Assert.False(res.wasCancelled); + Assert.Equal(6, res.index); + + awaitSequenceTask = AwaitSequence( + new Queue(["Log C", "Sync"]), // Wait for another Log C followed by Sync + fromIndex: res.index + 1, // Starting from previously asserted state + fakeLogCollector, + eventTracker, + cancellationToken: cancellationToken); + + if (isWaitCancelled) + { + cts.Cancel(); + } + else + { + EmitLogs(logger, ["Log C", "Sync"], eventTracker); + } + + await AssertAwaitingTaskCompleted(awaitSequenceTask); + + res = await awaitSequenceTask; + Assert.Equal(isWaitCancelled, res.wasCancelled); + Assert.Equal(isWaitCancelled ? -1 : 9, res.index); + + if (!isWaitCancelled) + { + // The user may want to await partial states, but then perform a sanity check on the whole expected history + var snapshot = fakeLogCollector.GetSnapshot().Select(x => x.Message); + var containsSequence = ContainsNonContinuousSequence(snapshot, new Queue(["Log A", "Log B", "Sync", "Log C", "Sync"])); + Assert.True(containsSequence); + } + + OutputEventTracker(_outputHelper, eventTracker); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task GetLogsAsync_RegardlessOfClearDuringWait_SuppliesNextLogWhenRecorded(bool clearIsCalledDuringWait) + { + var fakeLogCollector = FakeLogCollector.Create(new FakeLogCollectorOptions()); + var logger = new FakeLogger(fakeLogCollector); + int moveNextCounter = 0; + + var abSequenceTask = AwaitSequence( + new Queue(["A", "B"]), + fromIndex: 0, + fakeLogCollector, + null, + cancellationToken: CancellationToken.None); + + var abcSequenceTask = AwaitSequence( + new Queue(["A", "B", "C"]), + fromIndex: 0, + fakeLogCollector, + null, + cancellationToken: CancellationToken.None, + () => Interlocked.Increment(ref moveNextCounter)); + + EmitLogs(logger, ["A", "B"], null); + await AssertAwaitingTaskCompleted(abSequenceTask); // checkpoint to not clear, before A, B is processed + + if (clearIsCalledDuringWait) + { + fakeLogCollector.Clear(); + } + + EmitLogs(logger, ["C"], null); + await AssertAwaitingTaskCompleted(abcSequenceTask); + Assert.Equal(3, moveNextCounter); + } + + private static async Task AssertAwaitingTaskCompleted(Task task) + { + var timeout = Task.Delay(TimeSpan.FromSeconds(5)); +#pragma warning disable VSTHRD003 + var finishedTask = await Task.WhenAny(task, timeout); +#pragma warning restore VSTHRD003 + + // Assert our tested task finished before the timeout + Assert.Equal(finishedTask, task); + } + + private static bool ContainsNonContinuousSequence(IEnumerable orderedEnumeration, Queue sequence) + { + foreach (var item in orderedEnumeration) + { + if (sequence.Count == 0) + { + break; + } + + if (item == sequence.Peek()) + { + sequence.Dequeue(); + } + } + + return sequence.Count == 0; + } + + private static async Task<(bool wasCancelled, int index)> AwaitSequence( + Queue sequence, + int fromIndex, + FakeLogCollector collector, + ConcurrentQueue? eventTracker, + CancellationToken cancellationToken, + Action? onMoveNextCalled = null) + { + eventTracker?.Enqueue("New sequence awaiter started at " + DateTime.Now + $", waiting for items: {string.Join(", ", sequence)} from index {fromIndex}."); + + try + { + int index = -1; + var enumeration = collector.GetLogsAsync(cancellationToken: cancellationToken); + await foreach (var log in enumeration) + { + onMoveNextCalled?.Invoke(); + index++; + + if (index < fromIndex) + { + continue; + } + + var msg = log.Message; + var currentExpectation = sequence.Peek(); + + eventTracker?.Enqueue($"Sequence awaiter checks log: \"{msg}\"."); + + if (msg == currentExpectation) + { + sequence.Dequeue(); + + if (sequence.Count != 0) + { + continue; + } + + eventTracker?.Enqueue($"Sequence awaiter satisfied at {DateTime.Now}"); + return (false, index); + } + } + } + catch (OperationCanceledException) + { + eventTracker?.Enqueue($"Sequence awaiter cancelled at {DateTime.Now}"); + return (true, -1); + } + + throw new InvalidOperationException("Enumeration was supposed to be unbound."); + } + + private static void OutputEventTracker(ITestOutputHelper testOutputHelper, ConcurrentQueue eventTracker) + { + while (eventTracker.TryDequeue(out var item)) + { + testOutputHelper.WriteLine(item); + } + } + + private static void EmitLogs( + FakeLogger logger, + IEnumerable logsToEmit, + ConcurrentQueue? eventTracker) + { + foreach (var log in logsToEmit) + { + eventTracker?.Enqueue($"Emitting log: \"{log}\" at {DateTime.Now}, current log count: {logger.Collector.Count}"); + logger.Log(LogLevel.Debug, log); + } + } +} 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..63ce2a7e718 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLogCollectorTests.cs @@ -9,7 +9,7 @@ namespace Microsoft.Extensions.Logging.Testing.Test.Logging; -public class FakeLogCollectorTests +public partial class FakeLogCollectorTests { private class Output : ITestOutputHelper {