ApplicationInsights-dotnet icon indicating copy to clipboard operation
ApplicationInsights-dotnet copied to clipboard

How to find the source of "TelemetryChannel found a telemetry item without an InstrumentationKey"

Open rnarayana opened this issue 3 years ago • 58 comments

Microsoft.ApplicationInsights Version="2.15.0"
Microsoft.ApplicationInsights.AspNetCore Version="2.15.0"
Microsoft.ApplicationInsights.Kubernetes Version="1.1.2"
Microsoft.ApplicationInsights.NLogTarget Version="2.15.0"
  • Runtime version (e.g. net461, net48, netcoreapp2.1, netcoreapp3.1, etc. You can find this information from the *.csproj file): .Net Core 3.1.7
  • Hosting environment (e.g. Azure Web App, App Service on Linux, Windows, Ubuntu, etc.): Kubernetes (Rancher) and also on AKS on Alpine Linux

What are you trying to achieve? Almost all the telemetry comes through properly, but I still get the trace "AI: TelemetryChannel found a telemetry item without an InstrumentationKey. This is a required field and must be set in either your config file or at application startup." at regular intervals The key is set as the first step in ConfigureServices() itself in Startup.cs:

        public void ConfigureServices(IServiceCollection services)
        {
            var appInsightsKey = this.appConfig.GetConfig("App:ApplicationInsightsKey"); // Get my key
            services.AddAppInsights("LISTENER", appInsightsKey); // See extension method below
            services.AddControllers();
            ....
        }

        public static void AddAppInsights(this IServiceCollection services, string cloudRoleName,
            string instrumentationKey)
        {
            services.AddSingleton<ITelemetryInitializer>(new CloudRoleNameInitializer(cloudRoleName));
            services.AddApplicationInsightsTelemetry(o =>
            {
                o.InstrumentationKey = instrumentationKey;
                o.EnableAdaptiveSampling = false;
            });
            services.ConfigureTelemetryModule<DependencyTrackingTelemetryModule>((module, o) =>
            {
                module.EnableSqlCommandTextInstrumentation = true;
            });
            services.AddApplicationInsightsTelemetryProcessor<HealthCheckExclusionFilter>();
            services.AddApplicationInsightsTelemetryProcessor<CustomPropertyFilter>();
            services.AddApplicationInsightsKubernetesEnricher();
        }

What have you tried so far? I tried adding a TelemetryProcessor to try and inspect each item and figure out this, but did not get any leads.

rnarayana avatar Sep 25 '20 06:09 rnarayana

Can you share the full code showing how you enabled ApplicationInsights? Its not clear which nuget package you are using, and which code snippet is being used. Without seeing them, its not possible to give any useful response.

cijothomas avatar Sep 25 '20 21:09 cijothomas

My bad, I've updated the question with details. I thought adding the appinsights telemetry at the very beginning would make the key available everywhere, and am unable to track the intermittent error about not finding the key.

rnarayana avatar Sep 28 '20 06:09 rnarayana

@rnarayana I have updated to v2.15.0 last night and I've started to see this problem happening. It is really hard to find the source, but I did not have the problem with v2.14.0, so I'll just revert to get back my telemetry

poveilleux avatar Oct 08 '20 13:10 poveilleux

@poveilleux Are you also on kubernetes?

rnarayana avatar Oct 08 '20 15:10 rnarayana

@rnarayana I am, but I don't see how this would be related.

poveilleux avatar Oct 08 '20 15:10 poveilleux

@rnarayana Are you facing this issue only when deploying to AKS ? Are you able to seeing telemetry flowing correctly without issues when running locally?

cijothomas avatar Oct 08 '20 21:10 cijothomas

@cijothomas I see this issue when deploying to kuberentes (AKS and non-AKS). Note that I have all my other telemetry flowing in correctly, but this one particular message keeps coming in at exactly 15 minutes apart. I've checked multiple services, and in every service, this entry is there, every 15 minutes. I have run locally in Debug mode for more than 15 mins, but did not see this issue.

image

rnarayana avatar Oct 10 '20 18:10 rnarayana

@rnarayana The 15 min interval hints that this may have something to do with Heartbeat module..Can you check if you have heartbeats flowing for the app in aks/local? Heartbeats would be a "customMetric" with the name "heartbeat".

Also, if possible, can isolate the issue to particular version. Specifically - please confirm if you have repro with 2.15 only, or its repro in 2.14 as well? (There were changes in heartbeat modules in 2.15, so we want to narrow the scope down further to quickly reach the root cause). Appreciate your patience!

cijothomas avatar Oct 12 '20 17:10 cijothomas

I can confirm that the following two methods get rid of this issue:

  1. Use version 2.14 and set key via AddApplicationInsightsTelemetry().
  2. Use version 2.15, but set APPINSIGHTS_INSTRUMENTATIONKEY env. var instead of setting the key via AddApplicationInsightsTelemetry()

rnarayana avatar Oct 13 '20 06:10 rnarayana

We encountered the described issue in a SF stateless ASP.NET Core service that is using the Microsoft.ApplicationInsights.AspNetCore v2.15.0 package. We have a lot of logs of this type.

We have noticed 1 more thing that might be a different issue but might be related to this one. Some of the Trace logs have provider name <undefined>. These logs are duplicated with logs that have the correct provider name set but this is still cluttering our logs.

vladislav-karamfilov avatar Oct 14 '20 06:10 vladislav-karamfilov

We encountered the described issue in a SF stateless ASP.NET Core service that is using the Microsoft.ApplicationInsights.AspNetCore v2.15.0 package. We have a lot of logs of this type.

We have noticed 1 more thing that might be a different issue but might be related to this one. Some of the Trace logs have provider name <undefined>. These logs are duplicated with logs that have the correct provider name set but this is still cluttering our logs.

Reverting back to v2.14.0 as @poveilleux suggested in 1 of the above comments fixes the AI: TelemetryChannel found a telemetry item without an InstrumentationKey. This is a required field and must be set in either your config file or at application startup. issue for us too. The issue with <undefined> provider name still persists.

vladislav-karamfilov avatar Oct 15 '20 18:10 vladislav-karamfilov

Thanks everyone for reporting the issue. This would be a regression from 2.14, most likelyt in the heartbeat area. Wil investigate and provide fix.

cijothomas avatar Oct 15 '20 18:10 cijothomas

im getting the same problem, reverted to 2.14.0 and everything worked

yehiasalam avatar Oct 17 '20 09:10 yehiasalam

@rnarayana, I started investigating this issue, but could not recreate in my environment. Adding the code as in issue description did not recreate an issue. I see a note stating issue does not get recreated in debug environment. Is it reproducible only in AKS? Could you please provide the steps the recreate an issue, this will help us investigate this issue faster.

Also it could help if you can provide below data.

  • Do you see the heart beat information logged in the failure case. If so, could you please provide the heart beat data. Heartbeat information gets logged into CustomMetrics table with the name - HeartbeatState

rajkumar-rangaraj avatar Nov 06 '20 04:11 rajkumar-rangaraj

We haven't fixed this yet, which means this won't be part of 2.16.

Will continue to get to the root cause for this, and will do 2.15.1 release for this, if this is confirmed to be a regression introduced by 2.15. (Similarly, it'll be part of 2.16.1 release as well)

2.16 cannot be delayed, as its a release done just to pick DiagnosticSource package version update to 5.0, which is releasing tomorrow.

cijothomas avatar Nov 09 '20 20:11 cijothomas

@rnarayana, I started investigating this issue, but could not recreate in my environment. Adding the code as in issue description did not recreate an issue. I see a note stating issue does not get recreated in debug environment. Is it reproducible only in AKS? Could you please provide the steps the recreate an issue, this will help us investigate this issue faster.

Also it could help if you can provide below data.

* Do you see the heart beat information logged in the failure case. If so, could you please provide the heart beat data. Heartbeat information gets logged into CustomMetrics table with the name - `HeartbeatState`

I'll send full repro by this weekend.

rnarayana avatar Nov 11 '20 07:11 rnarayana

I've uploaded the repro here Steps:

  1. Replace everything that says REPLACE_THIS
  2. Build project.
  3. Build docker
  4. Deploy helm to AKS.
  5. Wait for 30 minutes, check appinsights.

rnarayana avatar Nov 17 '20 16:11 rnarayana

My team is also seeing this on Microsoft.ApplicationInsights.AspNetCore 2.15.0 and we are trying to determine the cause as we have 1 API service exhibiting the issue and 3 that are not.

It's a very weird issue. If this is the issue, that the key isn't there, why is the iKey field filled in and correct? How are we also seeing legitimate logs next to it (for instance, in the middle of the items with the issue, we see a log telling us that one of our dependency requests was unsuccessful)?

Definitely sounds like a red herring to whatever the real issue is. At this point, we're pulling back slight configuration differences between the working and not working APIs to see if we can determine the cause.

mmulhearn avatar Nov 18 '20 15:11 mmulhearn

As we started to peel away, we found that removing this configuration from our api app in Azure fixed the issue, and re-adding it re-introduced the issue.

{
    "name": "ApplicationInsightsAgent_EXTENSION_VERSION",
    "value": "~2",
    "slotSetting": true
  }

mmulhearn avatar Nov 18 '20 16:11 mmulhearn

It would appear this configuration change causes the issue on a resource that is not currently exhibiting it:

  • Go to Application Insights on your app in Azure
  • Go to the Instrument your application section
  • Go to the .NET Core tab
  • Turn On Interop with Application Insights SDK (preview)

This caused the issue in our QA environment resource that was not previous exhibiting the issue.

mmulhearn avatar Nov 18 '20 16:11 mmulhearn

We have confirmed that Interop with Application Insights SDK (preview) is the issue, not the ApplicationInsightsAgent_EXTENSION_VERSION configuration.

mmulhearn avatar Nov 18 '20 17:11 mmulhearn

@rnarayana Thanks for the repro, it helped investigate an issue.

Workaround for this issue is to set EnableActiveTelemetryConfigurationSetup to true in ApplicationInsightsServiceOptions. For example,

services.AddApplicationInsightsTelemetry(o =>
{
     o.InstrumentationKey = instrumentationKey;
     o.EnableAdaptiveSampling = false;
     o.EnableActiveTelemetryConfigurationSetup = true;
});

Please note that still duplicate heartbeat is sent every 15 minutes and above proposed change will ensure that the duplicate heartbeat has InstrumentationKey and won't generate internal trace message.

Root Cause Microsoft.ApplicationInsights.NLogTarget package is creating an additional TelemetryConfiguration with HeartbeatProvider module registered. This causes two heartbeats to flow every 15 minutes instead of one. We will work on a fix to prevent the duplicate heartbeat. Please use the workaround to avoid internal trace message being logged in your component.

rajkumar-rangaraj avatar Nov 24 '20 20:11 rajkumar-rangaraj

We have confirmed that Interop with Application Insights SDK (preview) is the issue, not the ApplicationInsightsAgent_EXTENSION_VERSION configuration.

Hi, for any issues with the Azure Web App monitoring, please raise support ticket, as the codeless components are not opensourced. This repo is only for SDK related issues.

cijothomas avatar Nov 24 '20 20:11 cijothomas

Will you make a fix available for 2.17.x? Just noticed that the issue has not been resolved in 2.17.0

We are experiencing the same issue. It is really annoying, mainly because developers do not notice anything is off when they only updated the package with a newer minor version. Also, if you just add Application Insights to a new application now, by default you will be referencing a faulty version :-(

Might want to re-add the P1 label (assuming that is the highest prio).

AroglDarthu avatar Feb 22 '21 08:02 AroglDarthu

Confirmed - I am seeing this issue in our pre-production workload too. Do we have any updates?

iamalexmang avatar Mar 02 '21 14:03 iamalexmang

Any updates whether this will go into a minor release as a fix? (I notice that this has been removed from the 2.17 milestones and not been added to any other milestones)

heinrichgh avatar Mar 23 '21 11:03 heinrichgh

@rnarayana Thanks for the repro, it helped investigate an issue.

Workaround for this issue is to set EnableActiveTelemetryConfigurationSetup to true in ApplicationInsightsServiceOptions. For example,

services.AddApplicationInsightsTelemetry(o =>
{
     o.InstrumentationKey = instrumentationKey;
     o.EnableAdaptiveSampling = false;
     o.EnableActiveTelemetryConfigurationSetup = true;
});

Please note that still duplicate heartbeat is sent every 15 minutes and above proposed change will ensure that the duplicate heartbeat has InstrumentationKey and won't generate internal trace message.

Root Cause Microsoft.ApplicationInsights.NLogTarget package is creating an additional TelemetryConfiguration with HeartbeatProvider module registered. This causes two heartbeats to flow every 15 minutes instead of one. We will work on a fix to prevent the duplicate heartbeat. Please use the workaround to avoid internal trace message being logged in your component.

Has this workaround stopped working in 2.17 for anyone? I'm starting to see "TelemetryChannel found a telemetry item without an InstrumentationKey" again on upgrading to 2.17

rnarayana avatar Apr 13 '21 12:04 rnarayana

The workaround doesn't work for me either. This is problematic since I have many services, it spams the logs all the time.

Using .NET 5.0 and

    <PackageReference Include="Microsoft.ApplicationInsights.AspNetCore" Version="2.17.0" />
    <PackageReference Include="Microsoft.ApplicationInsights.Kubernetes" Version="1.1.4" />
    <PackageReference Include="Microsoft.ApplicationInsights.PerfCounterCollector" Version="2.17.0" />

adrien-constant avatar May 04 '21 09:05 adrien-constant

There's only a couple of places where this error is logged, tracing back through, InMemoryChannel is one of those points.

perhaps this code in TelemetrySink.cs is the culprit?

this.telemetryChannel = new InMemoryChannel { EndpointAddress = telemetryConfiguration.EndpointContainer.FormattedIngestionEndpoint, };

I don't see the key being set anywhere here, and looks like blame shows some insight into what happened.

Perhaps the key here could be passed to TelemetrySink constructor and onto the InMemoryChannel.

RobK410 avatar May 20 '21 20:05 RobK410

I have added EnableActiveTelemetryConfigurationSetup as indicated and the workaround works perfectly.

Here how I do it:

Add an ApplicationInsights section in appsettings.json

"ApplicationInsights": {
    "InstrumentationKey": "<add_instrumentation_key_here>",
    "DeveloperMode": false,
    "EnableRequestTrackingTelemetryModule": true,
    "EnableAdaptiveSampling": true,
    "EnableActiveTelemetryConfigurationSetup": true
  }

And load it with:

services.AddApplicationInsightsTelemetry(
				options => 
					_configuration
						.GetSection("ApplicationInsights")
						.Bind(options)
			);

Now I have no more "AI: TelemetryChannel found a telemetry item without an InstrumentationKey." messages in traces.

bNobo avatar May 25 '21 14:05 bNobo