Sql dependency tracking broken in 2.8.0+. Dependency operation is not stopped and becomes parent of subsequent operations

[ArturDorochowicz]

This is a bug in versions 2.8.0+ (checked 2.8.0 and 2.8.1). It does not happen in 2.7.2 (also checked 2.5.1).

Repro Steps

Create a console application with code like this:

    public class Sql
    {
        public static void Run()
        {
            var connString = @"Data Source=(LocalDb)\MSSQLLocalDB; Initial Catalog=master; Integrated Security=SSPI";

            for (var i = 0; i < 5; ++i)
            {
                ExecSql(i, connString);
            }
        }

        static void ExecSql(int i, string connectionString)
        {
            using (var conn = new SqlConnection(connectionString))
            {
                conn.Open();
                conn.GetSchema("Tables");
            }

            Console.WriteLine($"Activity id after sql {i}: {Activity.Current?.Id}");
        }
    }

Full repro solution attached.
ConsoleApp1.zip

Actual Behavior

When using 2.8.0 the app prints:

Activity id after sql 0: |47da6e291f386f42b6fb519694553b3c.dc340c80_
Activity id after sql 1: |47da6e291f386f42b6fb519694553b3c.dc340c80_1.
Activity id after sql 2: |47da6e291f386f42b6fb519694553b3c.dc340c80_1.1.
Activity id after sql 3: |47da6e291f386f42b6fb519694553b3c.dc340c80_1.1.1.
Activity id after sql 4: |47da6e291f386f42b6fb519694553b3c.dc340c80_1.1.1.1.

Note that activity remains present after running a sql dependency and, due to this, the next operation (here another sql dependency) becomes its child. It continues for subsequent operations.

Expected Behavior

When using 2.7.2 the app prints:

Activity id after sql 0:
Activity id after sql 1:
Activity id after sql 2:
Activity id after sql 3:
Activity id after sql 4:

This is the expected output, i.e. there's no activity left over after running a sql dependency.

Version Info

SDK Version : 2.8.0, also 2.8.1
.NET Version : net framework 4.6.1, also 4.7.1
How Application was onboarded with SDK(VisualStudio/StatusMonitor/Azure Extension) : Visual Studio
OS : Windows 10
Hosting Info (IIS/Azure WebApps/ etc) : console app / Windows service

[lmolkova]

Thanks for reporting it and providing the repro app.

It reproduces when Activity happens out of the parent (request scope). One way to fix it may be to call it (and other related items) within a scope of operation:

using(var op = TelemteryClient.StartOperation<RequestTelemetry>())
{
  // call sql
  // call http 
  // do processing
  // etc   
}

[ArturDorochowicz]

I had tried something like what you suggest before submitting the issue. It doesn't actually help. The output is then similar to this:

Activity id after sql 0: |s+HVrDXZJ1s=.7c8ae45f_1.
Activity id after sql 1: |s+HVrDXZJ1s=.7c8ae45f_1.1.
Activity id after sql 2: |s+HVrDXZJ1s=.7c8ae45f_1.1.1.
Activity id after sql 3: |s+HVrDXZJ1s=.7c8ae45f_1.1.1.1.
Activity id after sql 4: |s+HVrDXZJ1s=.7c8ae45f_1.1.1.1.1.

The root id is now a base64-like value instead of guid-like value which shows that it comes from request telemetry instead of dependency telemetry, but it's still a wrong behaviour overall.

[lmolkova]

@ArturDorochowicz you are right, sorry for misleading info.
Another approach is to call Activity.Current.Stop() right after SQL call.

I've submitted PR #1091 to fix it, fix will be shipped in 2.9-beta1.

[ArturDorochowicz]

@lmolkova It's a bummer it won't land in a quick patch release for 2.8. After all it's quite a critical issue - one sql in the app and all the telemetry gets screwed.

[fschmied]

@lmolkova Just spent hours of debugging this before I found that a bug in Application Insights is the culprit rather than my own code. This is a critical bug, why wasn't it fixed in a 2.8 patch?

[fschmied]

Just to add: This is critical because it produces a memory leak, all the chained Activity objects are held alive in memory together with strings. This can easily amount to hundreds of megabytes after a few hours!