diff --git a/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestCallbacks.cs b/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestCallbacks.cs index de609f793c8a77..4ee8cae1c6ee02 100644 --- a/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestCallbacks.cs +++ b/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestCallbacks.cs @@ -7,7 +7,10 @@ using System.Linq; using System.Reflection; using System.Text; +using System.Threading; using System.Threading.Tasks; +using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.DotNet.RemoteExecutor; using Xunit; namespace BasicEventSourceTests @@ -82,5 +85,275 @@ protected override void OnEventCommand(EventCommandEventArgs command) _isDisabledInCallback = !IsEnabled(); } } + + /// + /// Validates disposing the current or another EventSource from within OnEventCommand. + /// + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false)] + [InlineData(true)] + [SkipOnPlatform(TestPlatforms.Browser, "DiagnosticsClient IPC is not available on browser")] + public void Test_EventSource_DisposeInOnEventCommand(bool disposeOtherSource) + { + RemoteExecutor.Invoke( + RunDisposeInOnEventCommand, + disposeOtherSource.ToString(), + new RemoteInvokeOptions { TimeOut = 45_000 }).Dispose(); + } + + private static void RunDisposeInOnEventCommand(string disposeOtherSourceString) + { + bool disposeOtherSource = bool.Parse(disposeOtherSourceString); + using var callbackCompleted = new ManualResetEventSlim(false); + using var source = new DisposeInCallbackEventSource(callbackCompleted); + using var otherSource = disposeOtherSource ? new PassiveEventSource() : null; + source._sourceToDispose = otherSource; + + var providers = disposeOtherSource + ? new[] + { + new EventPipeProvider(source.Name, System.Diagnostics.Tracing.EventLevel.Verbose, long.MaxValue), + new EventPipeProvider(otherSource!.Name, System.Diagnostics.Tracing.EventLevel.Verbose, long.MaxValue) + } + : new[] { new EventPipeProvider(source.Name, System.Diagnostics.Tracing.EventLevel.Verbose, long.MaxValue) }; + var client = new DiagnosticsClient(Environment.ProcessId); + using var session = client.StartEventPipeSession(providers, requestRundown: false); + + // Drain the event stream in a background thread so the runtime's buffer doesn't fill up + // and so session.Stop() can complete. + Task readerTask = Task.Run(() => + { + try + { + using var eventPipeSource = new Microsoft.Diagnostics.Tracing.EventPipeEventSource(session.EventStream); + eventPipeSource.Process(); + } + catch (Exception) { } // Stream is closed when session stops. The exact exception type + // varies by TraceEvent version/platform, so catch broadly here. + }); + + bool completed = callbackCompleted.Wait(TimeSpan.FromSeconds(30)); + + session.Stop(); + readerTask.Wait(TimeSpan.FromSeconds(5)); + + Assert.True(completed, "The EventSource callback did not complete."); + if (disposeOtherSource) + { + Assert.Null(source._disposeException); + Assert.True(source._disposeCompleted); + Assert.False(source._targetCallbackObservedBeforeDispose); + } + else + { + Assert.IsType(source._disposeException); + Assert.False(source._disposeCompleted); + } + } + + [EventSource(Name = "TestsEventSourceCallbacks.DisposeInCallbackEventSource")] + private class DisposeInCallbackEventSource : EventSource + { + private readonly ManualResetEventSlim _callbackCompleted; + internal EventSource? _sourceToDispose; + internal bool _disposeCompleted; + internal InvalidOperationException? _disposeException; + internal bool _targetCallbackObservedBeforeDispose; + + internal DisposeInCallbackEventSource(ManualResetEventSlim callbackCompleted) + { + _callbackCompleted = callbackCompleted; + } + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + try + { + _targetCallbackObservedBeforeDispose = + _sourceToDispose is PassiveEventSource passiveSource && passiveSource._callbackObserved; + (_sourceToDispose ?? this).Dispose(); + _disposeCompleted = true; + } + catch (InvalidOperationException ex) + { + _disposeException = ex; + } + finally + { + _callbackCompleted.Set(); + } + } + } + } + + [EventSource(Name = "TestsEventSourceCallbacks.PassiveEventSource")] + private sealed class PassiveEventSource : EventSource + { + internal bool _callbackObserved; + + protected override void OnEventCommand(EventCommandEventArgs command) + { + _callbackObserved = true; + } + } + + [Fact] + public void Test_EventSource_ConcurrentDisposeWaitsForCallback() + { + using var callbackEntered = new ManualResetEventSlim(false); + using var callbackRelease = new ManualResetEventSlim(false); + using var disposeStarted = new ManualResetEventSlim(false); + using var source = new BlockingCallbackEventSource(callbackEntered, callbackRelease); + using var listener = new PassiveListener(); + + Task enableTask = Task.Run(() => listener.EnableEvents(source, EventLevel.Verbose)); + Task? disposeTask = null; + try + { + Assert.True(callbackEntered.Wait(TimeSpan.FromSeconds(30))); + + disposeTask = Task.Run(() => + { + disposeStarted.Set(); + source.Dispose(); + }); + Assert.True(disposeStarted.Wait(TimeSpan.FromSeconds(30))); + Assert.False(disposeTask.Wait(TimeSpan.FromMilliseconds(100))); + } + finally + { + callbackRelease.Set(); + Assert.True(disposeTask is null + ? enableTask.Wait(TimeSpan.FromSeconds(30)) + : Task.WaitAll(new[] { enableTask, disposeTask }, TimeSpan.FromSeconds(30))); + } + } + + private sealed class PassiveListener : EventListener + { + } + + [EventSource(Name = "TestsEventSourceCallbacks.BlockingCallbackEventSource")] + private sealed class BlockingCallbackEventSource : EventSource + { + private readonly ManualResetEventSlim _callbackEntered; + private readonly ManualResetEventSlim _callbackRelease; + + internal BlockingCallbackEventSource( + ManualResetEventSlim callbackEntered, + ManualResetEventSlim callbackRelease) + { + _callbackEntered = callbackEntered; + _callbackRelease = callbackRelease; + } + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + _callbackEntered.Set(); + _callbackRelease.Wait(); + } + } + } + + [Fact] + public void Test_EventSource_DisposeInDeferredOnEventCommand_Throws() + { + DeferredCommandEventSource.s_disposeException = null; + + using var listener = new DeferredCommandListener(); + using var source = new DeferredCommandEventSource(); + + Assert.IsType(DeferredCommandEventSource.s_disposeException); + } + + private sealed class DeferredCommandListener : EventListener + { + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == "TestsEventSourceCallbacks.DeferredCommandEventSource") + { + EnableEvents(eventSource, EventLevel.Verbose); + } + } + } + + [EventSource(Name = "TestsEventSourceCallbacks.DeferredCommandEventSource")] + private sealed class DeferredCommandEventSource : EventSource + { + internal static InvalidOperationException? s_disposeException; + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + try + { + Dispose(); + } + catch (InvalidOperationException ex) + { + s_disposeException = ex; + } + } + } + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public void Test_EventSource_DisposeInOnEventSourceCreated_Throws(bool sourceBeforeListener) + { + DisposeOnCreatedEventSource? source = null; + DisposeOnCreatedListener? listener = null; + try + { + if (sourceBeforeListener) + { + source = new DisposeOnCreatedEventSource(); + listener = new DisposeOnCreatedListener(); + } + else + { + listener = new DisposeOnCreatedListener(); + source = new DisposeOnCreatedEventSource(); + } + + Assert.IsType(listener._disposeException); + } + finally + { + source?.Dispose(); + listener?.Dispose(); + } + } + + private sealed class DisposeOnCreatedListener : EventListener + { + internal InvalidOperationException? _disposeException; + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == "TestsEventSourceCallbacks.DisposeOnCreatedEventSource") + { + try + { + eventSource.Dispose(); + } + catch (InvalidOperationException ex) + { + _disposeException = ex; + } + } + } + } + + [EventSource(Name = "TestsEventSourceCallbacks.DisposeOnCreatedEventSource")] + private sealed class DisposeOnCreatedEventSource : EventSource + { + } } } diff --git a/src/libraries/System.Diagnostics.Tracing/tests/System.Diagnostics.Tracing.Tests.csproj b/src/libraries/System.Diagnostics.Tracing/tests/System.Diagnostics.Tracing.Tests.csproj index 1789b2304a360f..dad8ed6764daf9 100644 --- a/src/libraries/System.Diagnostics.Tracing/tests/System.Diagnostics.Tracing.Tests.csproj +++ b/src/libraries/System.Diagnostics.Tracing/tests/System.Diagnostics.Tracing.Tests.csproj @@ -37,6 +37,7 @@ + diff --git a/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx b/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx index 23635bf8653aab..705dfb526bc71b 100644 --- a/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx +++ b/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx @@ -2141,6 +2141,9 @@ Data descriptors are out of range. + + EventSource cannot be disposed from an EventSource callback while one of its callbacks is in progress. + Multiple definitions for string "{0}". diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventListener.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventListener.cs index 5d1ab4b30becf5..02832a85863aab 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventListener.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventListener.cs @@ -578,9 +578,29 @@ private void CallBackForExistingEventSources(bool addToListenersList, EventHandl WeakReference eventSourceRef = eventSourcesSnapshot[i]; if (eventSourceRef.TryGetTarget(out EventSource? eventSource)) { - EventSourceCreatedEventArgs args = new EventSourceCreatedEventArgs(); - args.EventSource = eventSource; - callback(this, args); + bool callbackEntered = eventSource.TryEnterCallback(); + if (!callbackEntered) + { + EventSource.EnterCallbackScope(); + } + + try + { + EventSourceCreatedEventArgs args = new EventSourceCreatedEventArgs(); + args.EventSource = eventSource; + callback(this, args); + } + finally + { + if (callbackEntered) + { + eventSource.ExitCallback(); + } + else + { + EventSource.ExitCallbackScope(); + } + } } } #if DEBUG diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventProvider.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventProvider.cs index 8efbecc896bfdb..f1674e4144b484 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventProvider.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventProvider.cs @@ -50,6 +50,10 @@ internal enum ControllerCommand /// internal class EventProvider : IDisposable { + private const int UnregisterPending = 0; + private const int UnregisterInProgress = 1; + private const int UnregisterComplete = 2; + // This is the windows EVENT_DATA_DESCRIPTOR structure. We expose it because this is what // subclasses of EventProvider use when creating efficient (but unsafe) version of // EventWrite. We do make it a nested type because we really don't expect anyone to use @@ -65,7 +69,8 @@ public struct EventData internal EventProviderImpl _eventProvider; // The implementation of the specific logging mechanism functions. private string? _providerName; // Control name private Guid _providerId; // Control Guid - internal bool _disposed; // when true provider has unregistered + internal bool _disposed; // when true provider disposal has started + private int _unregisterState; [ThreadStatic] private static WriteEventErrorCode s_returnCode; // The last return code @@ -124,7 +129,10 @@ internal void Register(Guid id, string name) public void Dispose() { Dispose(true); - GC.SuppressFinalize(this); + if (Volatile.Read(ref _unregisterState) == UnregisterComplete) + { + GC.SuppressFinalize(this); + } } protected virtual void Dispose(bool disposing) @@ -140,7 +148,14 @@ protected virtual void Dispose(bool disposing) // check if the object has been already disposed // if (_disposed) + { + if (!disposing) + { + _ = TryCompleteUnregister(throwOnFailure: false); + } + return; + } // Disable the provider. _eventProvider.Disable(); @@ -156,16 +171,51 @@ protected virtual void Dispose(bool disposing) _disposed = true; } - // We do the Unregistration outside the EventListenerLock because there is a lock - // inside the ETW routines. This lock is taken before ETW issues commands - // Thus the ETW lock gets taken first and then our EventListenersLock gets taken - // in SendCommand(), and also here. If we called EventUnregister after taking - // the EventListenersLock then the take-lock order is reversed and we can have - // deadlocks in race conditions (dispose racing with an ETW command). - // - // We solve by Unregistering after releasing the EventListenerLock. - Debug.Assert(!Monitor.IsEntered(EventListener.EventListenersLock)); - _eventProvider.Unregister(); + if (EventSource.IsExecutingCallback) + { + // Native unregistration may wait for callbacks queued behind the current callback. + ThreadPool.UnsafeQueueUserWorkItem( + static eventProvider => + { + if (eventProvider.TryCompleteUnregister(throwOnFailure: false)) + { + GC.SuppressFinalize(eventProvider); + } + }, + this, + preferLocal: false); + } + else + { + Debug.Assert(!Monitor.IsEntered(EventListener.EventListenersLock)); + _ = TryCompleteUnregister(throwOnFailure: disposing); + } + } + + private bool TryCompleteUnregister(bool throwOnFailure) + { + if (Interlocked.CompareExchange(ref _unregisterState, UnregisterInProgress, UnregisterPending) == UnregisterPending) + { + try + { + _eventProvider.Unregister(); + } + catch + { + Volatile.Write(ref _unregisterState, UnregisterPending); + if (throwOnFailure) + { + throw; + } + + return false; + } + + Volatile.Write(ref _unregisterState, UnregisterComplete); + return true; + } + + return Volatile.Read(ref _unregisterState) == UnregisterComplete; } /// diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs index 98f73cecd4345d..90bc7dae5dc0be 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @@ -228,7 +228,16 @@ public partial class EventSource : IDisposable private readonly EventSourceSettings m_config; // configuration information + // Callback state encoding: + // [0, int.MaxValue] - number of admitted callbacks + // (int.MinValue, 0) - disposal claimed, with the remaining callback count added to int.MinValue + // int.MinValue - disposal claimed and all admitted callbacks have exited + // Once disposal makes the state negative, no new callbacks are admitted. Existing callbacks decrement + // the state until it reaches CallbackDisposing, allowing the disposing thread to continue. + private const int CallbackDisposing = int.MinValue; + private bool m_eventSourceDisposed; // has Dispose been called. + private int m_eventSourceCallbackState; // callback count, or a negative disposing state // Enabling bits private bool m_eventSourceEnabled; // am I enabled (any of my events are enabled for any dispatcher) @@ -253,6 +262,22 @@ public partial class EventSource : IDisposable [ThreadStatic] private static byte m_EventSourceExceptionRecurenceCount; // current recursion count inside ThrowEventSourceException + [ThreadStatic] + private static int t_callbackDepth; + + internal static bool IsExecutingCallback => t_callbackDepth > 0; + + internal static void EnterCallbackScope() + { + t_callbackDepth++; + } + + internal static void ExitCallbackScope() + { + Debug.Assert(t_callbackDepth > 0); + t_callbackDepth--; + } + internal volatile ulong[]? m_channelData; // We use a single instance of ActivityTracker for all EventSources instances to allow correlation between multiple event providers. @@ -1501,6 +1526,10 @@ protected unsafe void WriteEventWithRelatedActivityId(int eventId, Guid relatedA /// /// Disposes of an EventSource. /// + /// + /// The method was called from an callback while a callback for this + /// was already in progress. + /// public void Dispose() { this.Dispose(true); @@ -1525,9 +1554,64 @@ protected virtual void Dispose(bool disposing) return; } - // Do not invoke Dispose under the lock as this can lead to a deadlock. - // See https://github.com/dotnet/runtime/issues/48342 for details. - Debug.Assert(!Monitor.IsEntered(EventListener.EventListenersLock)); + int callbackState = Volatile.Read(ref m_eventSourceCallbackState); + while (callbackState >= 0) + { + if (callbackState == 0) + { + // Claim disposal only if no callback entered after the state was read. + int zeroObservedState = Interlocked.CompareExchange( + ref m_eventSourceCallbackState, + CallbackDisposing, + 0); + if (zeroObservedState == 0) + { + break; + } + + callbackState = zeroObservedState; + continue; + } + + if (!disposing) + { + // A callback keeps the source alive, so this should not occur during finalization. + Debug.Fail("An EventSource command callback should keep the EventSource alive."); + return; + } + + if (IsExecutingCallback) + { + // Waiting here would deadlock if this thread is responsible for completing a callback. + throw new InvalidOperationException(SR.EventSource_DisposeInsideCallback); + } + + // Make the state negative to close callback admission while preserving the number to drain. + int observedState = Interlocked.CompareExchange( + ref m_eventSourceCallbackState, + CallbackDisposing + callbackState, + callbackState); + if (observedState == callbackState) + { + // Each admitted callback decrements the state as it exits. + SpinWait spinWait = default; + while (Volatile.Read(ref m_eventSourceCallbackState) != CallbackDisposing) + { + spinWait.SpinOnce(); + } + + break; + } + + // The callback count changed, or another thread claimed disposal. Retry with its value. + callbackState = observedState; + } + + if (callbackState < 0) + { + // Another thread claimed disposal and owns the remaining cleanup. + return; + } if (disposing) { @@ -1714,17 +1798,25 @@ private unsafe void Initialize(Guid eventSourceGuid, string eventSourceName, str } #endif - // Add the eventSource to the global (weak) list. - // This also sets m_id, which is the index in the list. - EventListener.AddEventSource(this); + ObjectDisposedException.ThrowIf(!TryEnterCallback(), this); + try + { + // Add the eventSource to the global (weak) list. + // This also sets m_id, which is the index in the list. + EventListener.AddEventSource(this); - // OK if we get this far without an exception, then we can at least write out error messages. - // Set m_provider, which allows this. - m_etwProvider = etwProvider; + // OK if we get this far without an exception, then we can at least write out error messages. + // Set m_provider, which allows this. + m_etwProvider = etwProvider; #if FEATURE_PERFTRACING - m_eventPipeProvider = eventPipeProvider; + m_eventPipeProvider = eventPipeProvider; #endif + } + finally + { + ExitCallback(); + } Debug.Assert(!m_eventSourceEnabled); // We can't be enabled until we are completely initted. } catch (Exception e) @@ -1741,10 +1833,20 @@ private unsafe void Initialize(Guid eventSourceGuid, string eventSourceName, str // Note that we are NOT resetting m_deferredCommands to NULL here, // We are giving for EventHandler that will be attached later EventCommandEventArgs? deferredCommands = m_deferredCommands; - while (deferredCommands != null) + if (deferredCommands != null && TryEnterCallback()) { - DoCommand(deferredCommands); // This can never throw, it catches them and reports the errors. - deferredCommands = deferredCommands.nextCommand; + try + { + while (deferredCommands != null) + { + DoCommand(deferredCommands); // This can never throw, it catches them and reports the errors. + deferredCommands = deferredCommands.nextCommand; + } + } + finally + { + ExitCallback(); + } } if (m_constructionException == null) @@ -2620,38 +2722,85 @@ internal void SendCommand(EventListener? listener, EventProviderType eventProvid EventLevel level, EventKeywords matchAnyKeyword, IDictionary? commandArguments) { - if (!IsSupported) + if (!IsSupported || !TryEnterCallback()) { return; } - var commandArgs = new EventCommandEventArgs(command, commandArguments, this, listener, eventProviderType, perEventSourceSessionId, enable, level, matchAnyKeyword); - lock (EventListener.EventListenersLock) + try { - if (m_completelyInited) + var commandArgs = new EventCommandEventArgs(command, commandArguments, this, listener, eventProviderType, perEventSourceSessionId, enable, level, matchAnyKeyword); + lock (EventListener.EventListenersLock) { - // After the first command arrive after construction, we are ready to get rid of the deferred commands - this.m_deferredCommands = null; - // We are fully initialized, do the command - DoCommand(commandArgs); - } - else - { - // We can't do the command, simply remember it and we do it when we are fully constructed. - if (m_deferredCommands == null) + if (m_completelyInited) { - m_deferredCommands = commandArgs; // create the first entry + // After the first command arrive after construction, we are ready to get rid of the deferred commands + this.m_deferredCommands = null; + // We are fully initialized, do the command + DoCommand(commandArgs); } else { - // We have one or more entries, find the last one and add it to that. - EventCommandEventArgs lastCommand = m_deferredCommands; - while (lastCommand.nextCommand != null) - lastCommand = lastCommand.nextCommand; - lastCommand.nextCommand = commandArgs; + // We can't do the command, simply remember it and we do it when we are fully constructed. + if (m_deferredCommands == null) + { + m_deferredCommands = commandArgs; // create the first entry + } + else + { + // We have one or more entries, find the last one and add it to that. + EventCommandEventArgs lastCommand = m_deferredCommands; + while (lastCommand.nextCommand != null) + lastCommand = lastCommand.nextCommand; + lastCommand.nextCommand = commandArgs; + } } } } + finally + { + ExitCallback(); + } + } + + // Atomically admits a callback unless disposal has started and marks the current thread + // as executing callback code. SendCommand admits before taking EventListenersLock so + // disposal can observe callbacks waiting for that lock. + internal bool TryEnterCallback() + { + int callbackState = Volatile.Read(ref m_eventSourceCallbackState); + while (callbackState >= 0) + { + if (callbackState == int.MaxValue) + { + Debug.Fail("Too many concurrent EventSource command callbacks."); + return false; + } + + int observedState = Interlocked.CompareExchange( + ref m_eventSourceCallbackState, + callbackState + 1, + callbackState); + if (observedState == callbackState) + { + EnterCallbackScope(); + return true; + } + + callbackState = observedState; + } + + // A negative state means disposal has started and no new callbacks may enter. + return false; + } + + // Releases the per-source admission and thread callback scope acquired by TryEnterCallback. + // This must run on the admitting thread in a finally block. + internal void ExitCallback() + { + int callbackState = Interlocked.Decrement(ref m_eventSourceCallbackState); + Debug.Assert(callbackState != int.MaxValue, "Callback state underflowed."); + ExitCallbackScope(); } ///