Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Activity.Current does not reset to null if entry span stops/disposes before child spans causing all subsequent activities to share the same trace id #91265

Open
Mpdreamz opened this issue Aug 29, 2023 · 7 comments

Comments

@Mpdreamz
Copy link
Contributor

Description

Stopping an entry span (one that starts a trace) before its children 'leaks' as Activity.Current never gets cleared out to null again.

This can erroneously cause all subsequent activities to reuse the 'leaked' trace id.

Reproduction Steps

Using the following minimal bootstrap:

using System.Diagnostics;

var listener = new ActivityListener
{
    ShouldListenTo = _ => true,
    Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData
};
ActivitySource.AddActivityListener(listener);

Starting 3 traces but disposing the entry span before its children:

// Activity.Current == null here (correctly)
for (var i = 0; i < 3; i++)
{
    Console.WriteLine($"=> Trace {i}");
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    //using var child = source.StartActivity();
    using var span = new Activity("child").Start();
    entry.Stop();
    Console.WriteLine($"=> Active after entry stop : {Activity.Current?.Id}");
    child.Stop();
    Console.WriteLine($"=> Active after child stop : {Activity.Current?.Id}");
    Console.WriteLine();
}
if (Activity.Current != null)
    Console.WriteLine("Still an active trace after all activities are disposed");

Will yield:

=> Trace 0
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00
=> Active after entry stop : 
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00

=> Trace 1
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00
=> Active after entry stop : 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00

=> Trace 2
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-f618bcf43a2b475f-00
=> Active after entry stop : 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-f618bcf43a2b475f-00

Still an active trace after all activities are disposed

We can clearly see the child.Stop() on the first trace will reinstate entry as the Activity.Current even though entry was already stopped.

On any subsequent iteration the will reuse the traceid of the first trace and continue it rather than creating a new one.

Expected behavior

for (var i = 0; i < 3; i++)
{
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    using var child = new Activity("child").Start();
}
if (Activity.Current == null)
    Console.WriteLine("Correctly reset `Activity.Current` to null as there are no active traces anymore");

or even more explicitly

for (var i = 0; i < 3; i++)
{
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    using var child = new Activity("child").Start();
    child.Stop();
    entry.Stop();
}

if (Activity.Current == null)
    Console.WriteLine("Correctly reset `Activity.Current` to null as there are no active traces anymore");

Will yield something similar to:

=> Active after entry start: 00-7144ae3329e4a2b40fac87c0283b8c97-f7846dc870c902aa-00
=> Active after entry start: 00-7c13f4ccf62fa622fe2caf8e5483945e-a7a9e6820e08a0cc-00
=> Active after entry start: 00-6c5a1ddde105a9bcbcdc3d9e6661e08b-dbb803f80eb53244-00
Correctly reset `Activity.Current` to null as there are no active traces anymore

Ensuring each iteration correctly starts a new trace and after the for loop Activity.Current is correctly reset to null.

The only way to clear this state is to manually set Activity.Current to null.

Actual behavior

Stopping activities out of order may cause Activity.Current to stick to a certain traceid.

Regression?

No response

Known Workarounds

No response

Configuration

.NET <= 7.0

Other information

No response

@ghost ghost added the untriaged New issue has not been triaged by the area owner label Aug 29, 2023
@ghost
Copy link

ghost commented Aug 29, 2023

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

Description

Stopping an entry span (one that starts a trace) before its children 'leaks' as Activity.Current never gets cleared out to null again.

This can erroneously cause all subsequent activities to reuse the 'leaked' trace id.

Reproduction Steps

Using the following minimal bootstrap:

using System.Diagnostics;

var listener = new ActivityListener
{
    ShouldListenTo = _ => true,
    Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData
};
ActivitySource.AddActivityListener(listener);

Starting 3 traces but disposing the entry span before its children:

// Activity.Current == null here (correctly)
for (var i = 0; i < 3; i++)
{
    Console.WriteLine($"=> Trace {i}");
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    //using var child = source.StartActivity();
    using var span = new Activity("child").Start();
    entry.Stop();
    Console.WriteLine($"=> Active after entry stop : {Activity.Current?.Id}");
    child.Stop();
    Console.WriteLine($"=> Active after child stop : {Activity.Current?.Id}");
    Console.WriteLine();
}
if (Activity.Current != null)
    Console.WriteLine("Still an active trace after all activities are disposed");

Will yield:

=> Trace 0
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00
=> Active after entry stop : 
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00

=> Trace 1
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00
=> Active after entry stop : 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00

=> Trace 2
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-f618bcf43a2b475f-00
=> Active after entry stop : 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-f618bcf43a2b475f-00

Still an active trace after all activities are disposed

We can clearly see the child.Stop() on the first trace will reinstate entry as the Activity.Current even though entry was already stopped.

On any subsequent iteration the will reuse the traceid of the first trace and continue it rather than creating a new one.

Expected behavior

for (var i = 0; i < 3; i++)
{
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    using var child = new Activity("child").Start();
}
if (Activity.Current == null)
    Console.WriteLine("Correctly reset `Activity.Current` to null as there are no active traces anymore");

or even more explicitly

for (var i = 0; i < 3; i++)
{
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    using var child = new Activity("child").Start();
    child.Stop();
    entry.Stop();
}

if (Activity.Current == null)
    Console.WriteLine("Correctly reset `Activity.Current` to null as there are no active traces anymore");

Will yield something similar to:

=> Active after entry start: 00-7144ae3329e4a2b40fac87c0283b8c97-f7846dc870c902aa-00
=> Active after entry start: 00-7c13f4ccf62fa622fe2caf8e5483945e-a7a9e6820e08a0cc-00
=> Active after entry start: 00-6c5a1ddde105a9bcbcdc3d9e6661e08b-dbb803f80eb53244-00
Correctly reset `Activity.Current` to null as there are no active traces anymore

Ensuring each iteration correctly starts a new trace and after the for loop Activity.Current is correctly reset to null.

The only way to clear this state is to manually set Activity.Current to null.

Actual behavior

Stopping activities out of order may cause Activity.Current to stick to a certain traceid.

Regression?

No response

Known Workarounds

No response

Configuration

.NET <= 7.0

Other information

No response

Author: Mpdreamz
Assignees: -
Labels:

area-System.Diagnostics.Tracing

Milestone: -

@tommcdon
Copy link
Member

@noahfalk

@tommcdon tommcdon added this to the 9.0.0 milestone Aug 29, 2023
@tommcdon tommcdon removed the untriaged New issue has not been triaged by the area owner label Aug 29, 2023
@tarekgh
Copy link
Member

tarekgh commented Aug 29, 2023

@Mpdreamz did you run into this issue in a real scenario?

@ghost
Copy link

ghost commented Aug 29, 2023

Tagging subscribers to this area: @dotnet/area-system-diagnostics-activity
See info in area-owners.md if you want to be subscribed.

Issue Details

Description

Stopping an entry span (one that starts a trace) before its children 'leaks' as Activity.Current never gets cleared out to null again.

This can erroneously cause all subsequent activities to reuse the 'leaked' trace id.

Reproduction Steps

Using the following minimal bootstrap:

using System.Diagnostics;

var listener = new ActivityListener
{
    ShouldListenTo = _ => true,
    Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData
};
ActivitySource.AddActivityListener(listener);

Starting 3 traces but disposing the entry span before its children:

// Activity.Current == null here (correctly)
for (var i = 0; i < 3; i++)
{
    Console.WriteLine($"=> Trace {i}");
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    //using var child = source.StartActivity();
    using var span = new Activity("child").Start();
    entry.Stop();
    Console.WriteLine($"=> Active after entry stop : {Activity.Current?.Id}");
    child.Stop();
    Console.WriteLine($"=> Active after child stop : {Activity.Current?.Id}");
    Console.WriteLine();
}
if (Activity.Current != null)
    Console.WriteLine("Still an active trace after all activities are disposed");

Will yield:

=> Trace 0
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00
=> Active after entry stop : 
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00

=> Trace 1
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00
=> Active after entry stop : 00-1ad1700f46edcdcadbb6c81f20ae206b-f57b7b80644b96ab-00
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00

=> Trace 2
=> Active after entry start: 00-1ad1700f46edcdcadbb6c81f20ae206b-f618bcf43a2b475f-00
=> Active after entry stop : 00-1ad1700f46edcdcadbb6c81f20ae206b-a134bcc4a3b21a5d-00
=> Active after span stop  : 00-1ad1700f46edcdcadbb6c81f20ae206b-f618bcf43a2b475f-00

Still an active trace after all activities are disposed

We can clearly see the child.Stop() on the first trace will reinstate entry as the Activity.Current even though entry was already stopped.

On any subsequent iteration the will reuse the traceid of the first trace and continue it rather than creating a new one.

Expected behavior

for (var i = 0; i < 3; i++)
{
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    using var child = new Activity("child").Start();
}
if (Activity.Current == null)
    Console.WriteLine("Correctly reset `Activity.Current` to null as there are no active traces anymore");

or even more explicitly

for (var i = 0; i < 3; i++)
{
    using var entry = source.StartActivity()!;
    Console.WriteLine($"=> Active after entry start: {Activity.Current?.Id}");
    using var child = new Activity("child").Start();
    child.Stop();
    entry.Stop();
}

if (Activity.Current == null)
    Console.WriteLine("Correctly reset `Activity.Current` to null as there are no active traces anymore");

Will yield something similar to:

=> Active after entry start: 00-7144ae3329e4a2b40fac87c0283b8c97-f7846dc870c902aa-00
=> Active after entry start: 00-7c13f4ccf62fa622fe2caf8e5483945e-a7a9e6820e08a0cc-00
=> Active after entry start: 00-6c5a1ddde105a9bcbcdc3d9e6661e08b-dbb803f80eb53244-00
Correctly reset `Activity.Current` to null as there are no active traces anymore

Ensuring each iteration correctly starts a new trace and after the for loop Activity.Current is correctly reset to null.

The only way to clear this state is to manually set Activity.Current to null.

Actual behavior

Stopping activities out of order may cause Activity.Current to stick to a certain traceid.

Regression?

No response

Known Workarounds

No response

Configuration

.NET <= 7.0

Other information

No response

Author: Mpdreamz
Assignees: -
Labels:

area-System.Diagnostics.Activity

Milestone: 9.0.0

@tarekgh tarekgh added the needs-author-action An issue or pull request that requires more info or actions from the author. label Nov 21, 2023
@ghost
Copy link

ghost commented Nov 21, 2023

This issue has been marked needs-author-action and may be missing some important information.

@tarekgh tarekgh modified the milestones: 9.0.0, Future Nov 21, 2023
@ghost ghost added the no-recent-activity label Dec 6, 2023
@ghost
Copy link

ghost commented Dec 6, 2023

This issue has been automatically marked no-recent-activity because it has not had any activity for 14 days. It will be closed if no further activity occurs within 14 more days. Any new comment (by anyone, not necessarily the author) will remove no-recent-activity.

@Mpdreamz
Copy link
Contributor Author

@Mpdreamz did you run into this issue in a real scenario?

@tarekgh if meaning in one the existing opentelemetry integrations, no.

However I do believe this to be a general API problem. It would be quite common for someone to want to start a trace over various asynchronous work without being able to ensure the entry/starting span is not disposed before all this asynchronous work is completed.

@ghost ghost added needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration and removed needs-author-action An issue or pull request that requires more info or actions from the author. no-recent-activity labels Dec 13, 2023
@tarekgh tarekgh removed the needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration label Dec 19, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants