DiagnosticListener: Cyclical IsEnabled reference and Activity action disappearance #125306
Description
Description
I was looking through the source code for DiagnosticListener to try and understand its inner workings and I believe I have come across two problems.
Problem 1
When subscribing to a DiagnosticListener using one of the follwing Subscribe overloads
Subscribe(IObserver<KeyValuePair<string, object?>> observer, Func<string, object?, object?, bool>? isEnabled)Subscribe(IObserver<KeyValuePair<string, object?>> observer, Func<string, object?, object?, bool>? isEnabled, Action<Activity, object?>? onActivityImport = null, Action<Activity, object?>? onActivityExport = null)
with a non null isEnabled argument, the DiagnosticListener.SubscribeInternal method gets invoked with its second argument (isEnabled1Arg) referencing the DiagnosticListener.IsEnabled(string, object?, object?) method instead of directly referencing the provided isEnabled delegate.
public virtual IDisposable Subscribe(IObserver<KeyValuePair<string, object?>> observer, Func<string, object?, object?, bool>? isEnabled)
{
return isEnabled == null ?
SubscribeInternal(observer, null, null, null, null) :
SubscribeInternal(observer, name => IsEnabled(name, null, null), isEnabled, null, null);
}
public virtual IDisposable Subscribe(IObserver<KeyValuePair<string, object?>> observer, Func<string, object?, object?, bool>? isEnabled,
Action<Activity, object?>? onActivityImport = null, Action<Activity, object?>? onActivityExport = null)
{
return isEnabled == null ?
SubscribeInternal(observer, null, null, onActivityImport, onActivityExport) :
SubscribeInternal(observer, name => IsEnabled(name, null, null), isEnabled, onActivityImport, onActivityExport);
}In this case, if a caller later uses the DiagnosticListener.IsEnabled(string) overload, a weird chain of invocations occur:
DiagnosticListener.IsEnabled(string)
DiagnosticSubscription.IsEnabled1Arg(string)
DiagnosticListener.IsEnabled(string, object?, object?)
DiagnosticSubscription.IsEnabled3Arg(string, object?, object?)
isEnabled(string, object?, object?) // the delegate provided on subscription.
Event though the isEnabled delegate gets invoked in the end, a better alternative should be:
public virtual IDisposable Subscribe(IObserver<KeyValuePair<string, object?>> observer, Func<string, object?, object?, bool>? isEnabled)
{
IDisposable subscription;
if (isEnabled == null)
{
subscription = SubscribeInternal(observer, null, null, null, null);
}
else
{
Func<string, object?, object?, bool> localIsEnabled = isEnabled;
subscription = SubscribeInternal(observer, name => localIsEnabled(name, null, null), isEnabled, null, null);
}
return subscription;
}
public virtual IDisposable Subscribe(IObserver<KeyValuePair<string, object?>> observer, Func<string, object?, object?, bool>? isEnabled,
Action<Activity, object?>? onActivityImport = null, Action<Activity, object?>? onActivityExport = null)
{
IDisposable subscription;
if (isEnabled == null)
{
subscription = SubscribeInternal(observer, null, null, onActivityImport, onActivityExport);
}
else
{
Func<string, object?, object?, bool> localIsEnabled = isEnabled;
subscription = SubscribeInternal(observer, name => localIsEnabled(name, null, null), isEnabled, onActivityImport, onActivityExport);
}
return subscription;
}Problem 2
When disposing of a DiagnosticSubscription, the DiagnosticSubscription.Remove method does not copy over the OnActivityImport and OnActivityExport properties when copying the linked list. These properties are also ignored when checking for subscription equality:
private static DiagnosticSubscription? Remove(DiagnosticSubscription? subscriptions, DiagnosticSubscription subscription)
{
if (subscriptions == null)
{
// May happen if the IDisposable returned from Subscribe is Dispose'd again
return null;
}
/*
* !! OnActivitImport & OnActivityExport are ignored !!
*/
if (subscriptions.Observer == subscription.Observer &&
subscriptions.IsEnabled1Arg == subscription.IsEnabled1Arg &&
subscriptions.IsEnabled3Arg == subscription.IsEnabled3Arg)
return subscriptions.Next;
#if DEBUG
// Delay a bit. This makes it more likely that races will happen.
for (int i = 0; i < 100; i++)
GC.KeepAlive("");
#endif
/*
* !!!! OnActivityImport & OnActivityExport are not copied to the new DiagnosticSubscription !!!!
*/
return new DiagnosticSubscription() { Observer = subscriptions.Observer, Owner = subscriptions.Owner, IsEnabled1Arg = subscriptions.IsEnabled1Arg, IsEnabled3Arg = subscriptions.IsEnabled3Arg, Next = Remove(subscriptions.Next, subscription) };
}Reproduction Steps
A simple small test can highlight both problems.
using System;
using System.Collections.Generic;
using System.Diagnostics;
namespace TestDiagnosticListener
{
public static class Program
{
public static void Main(string[] args)
{
TestDiagnosticListener listener = new TestDiagnosticListener("Test");
// Order of subscriptions is important so that the disposal of s1 will trigger a copy of the linked list of subscriptions to highlight Problem 2
Observer o1 = new Observer("O1");
IDisposable s1 = listener.Subscribe(o1);
Observer o2 = new Observer("O2");
IDisposable s2 = listener.Subscribe(
observer: o2,
isEnabled: (name, arg1, arg2) =>
{
Console.WriteLine($"isEnabled delegate invoked with name = {name}, arg1 = {arg1}, arg2 = {arg2}");
return true;
},
onActivityImport: (activity, args) =>
{
Console.WriteLine($"OnActivityImport: {activity.OperationName} => {args}");
},
onActivityExport: (activity, args) =>
{
Console.WriteLine($"OnActivityExport: {activity.OperationName} => {args}");
}
);
Console.WriteLine("Testing Activity A1");
using (Activity a1 = new Activity("A1"))
{
listener.StartActivity(a1, "Start A1 payload");
listener.OnActivityImport(a1, "Import A1 payload");
if (listener.IsEnabled("ExampleEvent.A1.1"))
{
listener.Write("ExampleEvent.A1.1", "A1.1");
}
listener.OnActivityExport(a1, "Export A1 payload");
if (listener.IsEnabled("ExampleEvent.A1.2", "this is arg1", "this is arg2"))
{
listener.Write("ExampleEvent.A1.2", "A1.2");
}
listener.StopActivity(a1, "Stop A1 payload");
}
Console.WriteLine();
s1.Dispose(); // This will trigger a copy of the linked list of subscriptions. Delegates provided for activities on subscription s2 will disappear
Console.WriteLine("Testing Activity A2");
using (Activity a2 = new Activity("A2"))
{
listener.StartActivity(a2, "Start A2 payload");
listener.OnActivityImport(a2, "Import A2 payload");
if (listener.IsEnabled("ExampleEvent.A2.1"))
{
listener.Write("ExampleEvent.A2.1", "A2.1");
}
listener.OnActivityExport(a2, "Export A2 payload");
if (listener.IsEnabled("ExampleEvent.A2.2", "this is arg1", "this is arg2"))
{
listener.Write("ExampleEvent.A2.2", "A2.2");
}
listener.StopActivity(a2, "Stop A2 payload");
}
s2.Dispose();
Console.WriteLine();
listener.Dispose();
}
private class Observer : IObserver<KeyValuePair<string, object?>>
{
public string Name { get; }
public Observer(string name)
{
Name = name;
}
public void OnCompleted()
{
}
public void OnError(Exception error)
{
}
public void OnNext(KeyValuePair<string, object?> value)
{
Console.WriteLine($"Observer {Name}: {value.Key} => {value.Value}");
}
}
private class TestDiagnosticListener : DiagnosticListener
{
public TestDiagnosticListener(string name) : base(name)
{
}
public override bool IsEnabled(string name)
{
Console.WriteLine($"TestDiagnosticListener.IsEnabled1 invoked with name = {name}");
return base.IsEnabled(name);
}
public override bool IsEnabled(string name, object? arg1, object? arg2 = null)
{
Console.WriteLine($"TestDiagnosticListener.IsEnabled3 invoked with name = {name}, arg1 = {arg1}, arg2 = {arg2}");
return base.IsEnabled(name, arg1, arg2);
}
}
}
}Expected behavior
The expected output of the simple test program should be:
Testing Activity A1
Observer O2: A1.Start => Start A1 payload
Observer O1: A1.Start => Start A1 payload
OnActivityImport: A1 => Import A1 payload
TestDiagnosticListener.IsEnabled1 invoked with name = ExampleEvent.A1.1
isEnabled delegate invoked with name = ExampleEvent.A1.1, arg1 = , arg2 =
Observer O2: ExampleEvent.A1.1 => A1.1
Observer O1: ExampleEvent.A1.1 => A1.1
OnActivityExport: A1 => Export A1 payload
TestDiagnosticListener.IsEnabled3 invoked with name = ExampleEvent.A1.2, arg1 = this is arg1, arg2 = this is arg2
isEnabled delegate invoked with name = ExampleEvent.A1.2, arg1 = this is arg1, arg2 = this is arg2
Observer O2: ExampleEvent.A1.2 => A1.2
Observer O1: ExampleEvent.A1.2 => A1.2
Observer O2: A1.Stop => Stop A1 payload
Observer O1: A1.Stop => Stop A1 payloadTesting Activity A2
Observer O2: A2.Start => Start A2 payload
OnActivityImport: A2 => Import A2 payload
TestDiagnosticListener.IsEnabled1 invoked with name = ExampleEvent.A2.1
isEnabled delegate invoked with name = ExampleEvent.A2.1, arg1 = , arg2 =
Observer O2: ExampleEvent.A2.1 => A2.1
OnActivityExport: A2 => Export A2 payload
TestDiagnosticListener.IsEnabled3 invoked with name = ExampleEvent.A2.2, arg1 = this is arg1, arg2 = this is arg2
isEnabled delegate invoked with name = ExampleEvent.A2.2, arg1 = this is arg1, arg2 = this is arg2
Observer O2: ExampleEvent.A2.2 => A2.2
Observer O2: A2.Stop => Stop A2 payload
Actual behavior
The actual output of the simple testing program is:
Testing Activity A1
Observer O2: A1.Start => Start A1 payload
Observer O1: A1.Start => Start A1 payload
OnActivityImport: A1 => Import A1 payload <-- PROBLEM 2 (Missing on output of A2)
TestDiagnosticListener.IsEnabled1 invoked with name = ExampleEvent.A1.1
TestDiagnosticListener.IsEnabled3 invoked with name = ExampleEvent.A1.1, arg1 = , arg2 = <-- PROBLEM 1
isEnabled delegate invoked with name = ExampleEvent.A1.1, arg1 = , arg2 =
Observer O2: ExampleEvent.A1.1 => A1.1
Observer O1: ExampleEvent.A1.1 => A1.1
OnActivityExport: A1 => Export A1 payload <-- PROBLEM 2 (Missing on output of A2)
TestDiagnosticListener.IsEnabled3 invoked with name = ExampleEvent.A1.2, arg1 = this is arg1, arg2 = this is arg2
isEnabled delegate invoked with name = ExampleEvent.A1.2, arg1 = this is arg1, arg2 = this is arg2
Observer O2: ExampleEvent.A1.2 => A1.2
Observer O1: ExampleEvent.A1.2 => A1.2
Observer O2: A1.Stop => Stop A1 payload
Observer O1: A1.Stop => Stop A1 payloadTesting Activity A2
Observer O2: A2.Start => Start A2 payload
TestDiagnosticListener.IsEnabled1 invoked with name = ExampleEvent.A2.1
TestDiagnosticListener.IsEnabled3 invoked with name = ExampleEvent.A2.1, arg1 = , arg2 =
isEnabled delegate invoked with name = ExampleEvent.A2.1, arg1 = , arg2 =
Observer O2: ExampleEvent.A2.1 => A2.1
TestDiagnosticListener.IsEnabled3 invoked with name = ExampleEvent.A2.2, arg1 = this is arg1, arg2 = this is arg2
isEnabled delegate invoked with name = ExampleEvent.A2.2, arg1 = this is arg1, arg2 = this is arg2
Observer O2: ExampleEvent.A2.2 => A2.2
Observer O2: A2.Stop => Stop A2 payload
Regression?
As far as I can see in the commit history of DiagnosticListener, both of these problems were introduced when the overloads were added and have not been changed since then.
Known Workarounds
No response
Configuration
No response
Other information
No response