Keeps capturing traces after parent scope is closed?

[dziedrius]

Describe the bug
I've added custom traces for our application startup and noticed strange behavior:

As long as I'm trying to instrument application startup, where logging is bootstrapped, background jobs are scheduled, etc., it seems that tracing agent captures active scope during that bootstrap and keeps using it even after scope is disposed, that makes it confusing and problematic (not sure are what side effects are - does this mean some leaking in the app?).

I've intentionally hovered on one of the scopes outside my custom scope - it is datadog pushing logs to web, (we're using serilog as logging framework) - so that is happening periodically without me controlling it, I don't wish to disable HttpClient integration - so I am out of ideas how to fix it.

I'm using default finishOnClose value - true.

To Reproduce
I don't have an isolated app to demonstrate this, but I've reproduced it like this:

using (Tracer.Instance.StartActive("testing-scope", serviceName: "datadogscopes"))
{
    Task.Run(async () =>
    {
        for (int i = 0; i < 20; i++)
        {
            using (Tracer.Instance.StartActive("inner-testing-scope", serviceName: "datadogscopes"))
            {
                Thread.Sleep(300);
            }
        }
    });              
}

It looks in datadog like this:

And here I probably can control behavior as for inner scope I can say "don't attach to parent", problem is with scopes that I can't control (integrations - sql, redis, httpclient).

Expected behavior
I would expect that after disposing scope nothing would be added to it anymore or at least I could control that (like it might be that for some multithreaded cases it makes sense to add something to the scope after disposing it, so it might be useful).

Runtime environment (please complete the following information):

• Instrumentation mode: mixed (side car container + manual custom scopes)
• Tracer version: 1.24.0
• OS: App's container is running on official asp.net 3.1-alpine image
• CLR: .NET Core 3.1

[andrewlock]

Thanks for providing the detailed examples, it makes things a lot easier to follow! 🙂

The behaviour you’re describing is a combination of a couple of issues:

1. The Serilog Sink currently traces requests to the Datadog logs intake
2. Scopes are nested, so if you create a new span when a trace has already begun, all subsequent spans will be added to that trace, even after the “root” span has been closed

With regard to 1, that’s an issue we’re aware of, which we are aiming to fix in an upcoming release.

With regard to 2, this behaviour is actually by design. In your example, the inner-testing-scope has a testing-scope parent in your case. When the inner scope closes, it will automatically restore the parent scope as the currently active scope, regardless of whether that parent has already closed (as in your example).

This behaviour is necessary to avoid disconnected spans in some cases. For example, consider if the parent testing-scope was created by an incoming request. The request may end (if the connection was closed for example), while the tasks are still running. If we didn't restore the parent (request) scope when each inner scope closed, then those subsequent spans would be disconnected from the trace and from the initial request entirely, leaving orphaned spans with no idea where they came from!

As you mention, using ignoreActiveScope:true is the correct approach for manual instrumentation, though won't apply to automatic instrumentation. One way to work around that could be to use an ignoreActiveScope span around those areas that use the automatic instrumentation. Hopefully there aren't too many of them in Startup.cs! 😉

Hope that makes sense 🙂

[dziedrius]

@andrewlock - thanks for explanation, it makes a lot of sense.
May be you have link to serilog issue, so that I could track that?

And regarding

When the inner scope closes, it will automatically restore the parent scope as the currently active scope, regardless of whether that parent has already closed (as in your example)

I agree that this as default behavior is reasonable, but if I could say "don't reopen parent scope", "don't attach automatic integrations within this scope" - would give me more control.

In any case, at least now I'm sure that this is by design and I have not overlooked something.