Application Insights for Kubernetes 3.0: telemetry initializer is used but the content has not ready yet in Console Applications

Question

Application Insights for Kubernetes 3.0: telemetry initializer is used but the content has not ready yet in Console Applications

qbdev-kr opened this issue 2 years ago · 16 comments

qbdev-kr commented 2 years ago

Goal

I want to be able to see Enriched Kubernetes Info coming into App Insights

Issue Summary

I consistently am seeing the trace,

Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.

What I have done

I have used #187 to help me out by adding delay etc. But that has not helped me and i am also deploying to AKS.

AKS

AKS is used to host a docker image from this code. The console app is calling an await method to run some ETL process and the total job completes in 2 minutes.

Usage

The code snipper example below is identical to the BasicConsoleAppILoggerApplication in .NET 6 console application with all needed packages installed.

const string ApplicationInsightsInstrumentationKey = "InstrumentationKey=<redacted keyValue from App Insights>";



IServiceCollection services = new ServiceCollection();
services.AddSingleton<Microsoft.Extensions.Configuration.IConfiguration>(p => new ConfigurationBuilder().Build());
var observer = new ApplicationInsightsKubernetesDiagnosticObserver(DiagnosticLogLevel.Trace);
ApplicationInsightsKubernetesDiagnosticSource.Instance.Observable.SubscribeWithAdapter(observer);

services.AddApplicationInsightsKubernetesEnricher(diagnosticLogLevel: LogLevel.Information);

var channel = new InMemoryChannel();
services.AddOptions<TelemetryConfiguration>().Configure<IServiceProvider>((config, p) =>
{
    // Appending registered telemetry initializers.
    foreach (ITelemetryInitializer registeredInitializer in p.GetServices<ITelemetryInitializer>())
    {
        config.TelemetryInitializers.Add(registeredInitializer);
    }

    // Setup up telemetry channels.
    config.TelemetryChannel = channel;
});

services.AddLogging(builder =>
{
    builder.AddFilter<ApplicationInsightsLoggerProvider>("", LogLevel.Trace);
    
    // Below is a different way to set Key to use the non-obselete extension method for AddApplicationInsights.
    
    builder.AddApplicationInsights(
    telemetryConfiguration => { telemetryConfiguration.ConnectionString = ApplicationInsightsInstrumentationKey; },
    applicationInsightsLoggerOptions => { });

    builder.AddSimpleConsole(opt =>
    {
        opt.SingleLine = true;
        opt.ColorBehavior = LoggerColorBehavior.Disabled;
    });
});

IServiceProvider serviceProvider = services.BuildServiceProvider();
ILogger<Program> logger = serviceProvider.GetRequiredService<ILogger<Program>>();

// Redacted Code
try {

logger.LogInformation("Config variable set ...");
await process.RunSomeProcess(); // Simple HTTP Get Calls here.
}
catch (Exception ex)
{
    logger.LogError(ex, "Job failed");
}

finally
{
    logger.LogInformation("Job end.");
    channel.Flush();
    Thread.Sleep(10000);
}

Answer 1 · 2022-10-20T16:24:57.000Z

@xiaomi7732 . Tagging you as I saw you made a recent PR to another example in this repo.

Answer 2 · 2022-10-20T17:32:27.000Z

Hey, @qbdev-kr I'll help troubleshoot. I have several questions after reading the code, could you please help me understand them:

Which version of the package are you using?
Are you building a console application to serve HTTP calls? Does it use any kind of hosting technology like ASP.NET Core/Minimal API or Worker, or is it just a plain console application?

Could you please run it with more detailed logs like this:

services.AddApplicationInsightsKubernetesEnricher(diagnosticLogLevel: LogLevel.Trace); // Use trace level than information level.

⚠️ You might have access tokens displayed in your logs, please redact before posting.

BTW, due to a recent change, you do NOT need the observer to turn on diagnostic traces any more, so you could remove these lines if you are using 3.0+ (or even later version in 2.x)

// These are deprecated in the later versions
var observer = new ApplicationInsightsKubernetesDiagnosticObserver(DiagnosticLogLevel.Trace);
ApplicationInsightsKubernetesDiagnosticSource.Instance.Observable.SubscribeWithAdapter(observer);

// Set the log level in `AddApplicationInsightsKubernetesEnricher` instead, which you already did.

Answer 3 · 2022-10-20T17:58:02.000Z

Hi @xiaomi7732 Thank you for your fast response. I have included some info below.

Packages Info:

	<PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="6.0.1" />
        <PackageReference Include="Microsoft.Extensions.Logging.ApplicationInsights" Version="2.21.0" />
       <PackageReference Include="Microsoft.ApplicationInsights.Kubernetes" Version="3.0.0" />
       <PackageReference Include="Microsoft.Extensions.Logging" Version="6.0.0" />	
	<PackageReference Include="Microsoft.ApplicationInsights" Version="2.21.0" />

Building a simple console application to consume data from cosmosDB client and loading data back into CosmosDB with some changes. Using Microsoft.Azure.Cosmos for this. Does not use a hosting technology like ASP.NET core or Worker service - No. This console application is kicked off like a cron job in AKS but it shouldn't matter.
Setting Diagnostic level to trace and redacting some internal logs and i will share here shortly.

I have removed the DiagnosticObserver code lines as the ApplicationInsights.Kubernetes package is 3.0

Answer 4 · 2022-10-20T18:08:53.000Z

Still waiting for the log to confirm, but here's my I hunch: there's a design hole in 3.x that we are relying on the HostedService to bootstrap the fetch of K8s info.

And the console application by default doesn't have a host to start the backend services - thus nothing triggers the fetch of the k8s info.

I'll do some quick checks while waiting for the logs to confirm. Thank you @qbdev-kr for the report.

Answer 5 · 2022-10-20T19:08:25.000Z

@xiaomi7732 - Logs From the Pod the job is running in. The console app is executed like a cron job on demand.

Is there something specific I can look into? Will it help if I call a http end point and we see some logs that way?

PS C:\Windows\system32> kubectl -n kube-system logs -f -n cscm
W1020 14:55:40.636665 9524 azure.go:92] WARNING: the azure auth plugin is deprecated in v1.22+, unavailable in v1.26+; use https://github.com/Azure/kubelogin instead.
To learn more, consult https://kubernetes.io/docs/reference/access-authn-authz/authentication/#client-go-credential-plugins
Defaulted container "redacted" out of: redacted, copy-azurekeyvault-env (init)
I1020 18:54:50.902870 1 version.go:31] "version info" version="" commit="11d9861" buildDate="2022-04-18T15:59:28Z" component="vaultenv"
I1020 18:54:50.902968 1 main.go:184] "azure key vault env injector initializing"
I1020 18:54:50.903355 1 main.go:253] "found original container command" cmd="/usr/bin/dotnet" args=[dotnet redacted]
I1020 18:54:50.903438 1 authentication.go:98] "checking if current auth service credentials are stale" url=""
I1020 18:54:50.986743 1 authentication.go:111] "auth service credentials ok" url=""
I1020 18:54:50.987209 1 authentication.go:147] "requesting key vault token" url=""
I1020 18:54:51.023012 1 authentication.go:167] "successfully received oauth token"
I1020 18:54:51.815153 1 main.go:355] "secret injected into env var" azurekeyvaultsecret="redacted" env="redacted"
I1020 18:54:51.815224 1 main.go:361] "starting process with secrets in env vars" cmd="/usr/bin/dotnet" args=[redacted]
[Debug] [2022-10-20T18:54:57.2219869Z] Application Insights Kubernetes injected the service successfully.
[Trace] [2022-10-20T18:54:58.0355420Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Skip Setting Config Variable ...
[Trace] [2022-10-20T18:54:58.0608190Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Forced 30 sec Delay ..
[Trace] [2022-10-20T18:55:28.1137510Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:55:44.0622409Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:55:59.0855817Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:56:14.1267500Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:56:29.1596076Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:56:44.2402969Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:56:59.3058341Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:57:14.3535779Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:57:29.3703389Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:57:44.4191937Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:57:59.4598506Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:58:14.4971953Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:58:29.5144898Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:58:44.5353609Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:58:59.5798009Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:59:14.6563085Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:59:29.6714946Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:59:44.6932452Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T18:59:59.7149494Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T19:00:14.7442307Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [DEMO] Info Logged is made by User
[Trace] [2022-10-20T19:00:29.9405965Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
fail: Program[0] [DEMO] Application failed System.Exception: [DEMO] Forced Exception by User - Testing Kubernetes of type K8s at Program.

$(String[] args) in /app/redacted/Program.cs:line 87
[Trace] [2022-10-20T19:01:05.0363596Z] Application Insights for Kubernetes telemetry initializer is used but the content has not ready yet.
info: Program[0] [Demo] Job end.

I redacted all code and put this log in a loop like this and it throws an exception when iterator limit is reached.

IServiceProvider serviceProvider = services.BuildServiceProvider();
ILogger<Program> logger = serviceProvider.GetRequiredService<ILogger<Program>>();

try
{
    logger.LogInformation("[DEMO] Skip Setting Config Variable ...");
    // redacted

    int count = 0;
    int maxCount = 20;
    await Task.Delay(TimeSpan.FromSeconds(30));

    // for loop in-place of redacted code
    for (int i =0; i<= maxCount; i++)
    {
        count++;
        if (count > maxCount)
            throw new Exception("[DEMO] Forced Exception by User - Testing Kubernetes of type K8s");

        logger.LogInformation("[DEMO] Info Logged is made by User");
        channel.Flush();
        await Task.Delay(TimeSpan.FromSeconds(15));
        
    }
}
catch (Exception ex)
{
    logger.LogError(ex, "[DEMO] Application failed");
    Thread.Sleep(35000);
}

finally
{
    logger.LogInformation("[Demo] Job end.");
    channel.Flush();
    Thread.Sleep(10000);
}

Answer 6 · 2022-10-20T19:09:40.000Z

@xiaomi7732 Would it help if I use a HostBuilder to instantiate the DI steps and run the Host Async? Is that what you meant in your earlier comment.

Answer 7 · 2022-10-20T19:25:45.000Z

@qbdev-kr I see.

It is a bug that the background service to fetch k8s info was never bootstrapped. Let me see how to support the console application.

I see several approaches for you:

Downgrade to 2.0.6 and give it a shot.
Yes, it will help to run it in a hosted environment. Use this example, if you are okay with migrating the code to Worker:
- https://github.com/microsoft/ApplicationInsights-Kubernetes/tree/develop/examples/WorkerExample
Wait for a bug fix - and I'll work on it.

I'll use this issue as the bug tracking and I'll keep it open until the issue is addressed.

Answer 8 · 2022-10-20T19:46:33.000Z

@xiaomi7732 , Thank you for giving direction and tracking this. I have some follow up questions,

Downgrade to 2.0.6 for Microsoft.ApplicationInsights.Kubernetes package?
Will using Generic Host example help get around the current situation?

https://github.com/microsoft/ApplicationInsights-Kubernetes/tree/develop/examples/GenericHost

Answer 9 · 2022-10-20T20:37:59.000Z

Yes, Microsoft.ApplicationInsights.Kubernetes.2.x doesn't require hosted service;
Yes, the generic hosted example should work too for Microsoft.ApplicationInsights.Kubernetes.3.x package.

Answer 10 · 2022-10-21T04:28:43.000Z

Hey @qbdev-kr,
The fix is available now. Please follow this updated example: Program.cs, specifically, call serviceProvider.StartApplicationInsightsKubernetesEnricher() after you call services.AddApplicationInsightsKubernetesEnricher().

I tested it locally and it worked for me. Please give it a try. At the same time, let me know if there's any feedback or any change you want.

Package:
https://www.nuget.org/packages/Microsoft.ApplicationInsights.Kubernetes/3.1.0-beta2

Answer 11 · 2022-10-21T14:09:50.000Z

@xiaomi7732 Thank you so much.

I will add this package and share the results with you.

Answer 12 · 2022-10-24T18:28:03.000Z

Hi @xiaomi7732, Thank you so much for the suggested change. I Can confirm, after including the change below and using the 3.1.0-beta2 package
serviceProvider.StartApplicationInsightsKubernetesEnricher() the Enriched Kubernetes data is populating under custom Dimension.

These are the kubectl logs =>

Thank you for your help, I wanted to ask if you know, how can I see the replicaSet and the deployment name property? I see all but these two.

Answer 13 · 2022-10-24T19:15:33.000Z

Cool. Thanks for getting back and confirming the fix. A quick thing to check is cluster role binding. See docs here: https://github.com/microsoft/ApplicationInsights-Kubernetes/blob/develop/docs/configure-rbac-permissions.md

I'll close this issue since this topic is completed. Feel free to file another issue if you would like to have another troubleshooting for replicaSet/deployment name after you confirm the proper rbac permissions are granted.

Answer 14 · 2022-10-27T15:44:02.000Z

@xiaomi7732 , I noticed the package I was using per recommendation is deprecated, are the changes now part of a different package version?

https://www.nuget.org/packages/Microsoft.ApplicationInsights.Kubernetes/3.1.0-beta2

Answer 15 · 2022-10-27T17:06:03.000Z

Yes, it is out of beta now:
https://www.nuget.org/packages/Microsoft.ApplicationInsights.Kubernetes/3.1.0.

Just in case, we go with semver. And by the rule: 3.0.0 < 3.1.0-betaN < 3.1.0.

Answer 16 · 2022-10-27T17:08:45.000Z

@xiaomi7732, Thank you for the update and your Contribution!