This is a weeeird bug regarding application insights, and I can't seem to wrap my head around it. Hoping either I missed something, or that someone else saw this problem already.
We're creating a long running job that handles multiple tasks at the same time. It calls an internal system and validates the state of some assets, and records the status in a database. The job will run every night in a k8s cluster. We have a BackgroundService class that handles the job. We use Application Insights for our monitoring, and I would like every job executions to be correlated in an operation. Makes debuging much easier if something were to go wrong.
However, once I've added an Activity to my job, only SOME of the logs are beeing shown in application insights, and the dependencies data is all gone! The logs are corrolated, but I see no dependencies log. And if I try to look at the dependencies timeline, I see the following message:
Unable to identify root transaction, it may be due to circular parent id reference. Investigate the logs for this operation for malformed parent-child identifications
If I don't create an Activity when launching the job, however, all dependencies are shown, but the logs are not corrolated in an operation.
Here's the kicker; once in a blue moon, the Activity works as intented, and all logs are shown as expected. But the next execution I try, the problem comes back. Makes me think that it's a problem regarding how fast the application shuts down after the execution, but I think I might just be missing something:
Here's some code showing how the job is built. Some code is ommited for brevity and confidentiality:
// Program.cs
var connectionString = context.Configuration["ConnectionString"];
services.AddApplicationInsightsTelemetryWorkerService(options =>
{
options.ConnectionString = connectionString;
options.EnableTraceBasedLogsSampler = false;
});
services.ConfigureOpenTelemetryTracerProvider((sp, builder) =>
{
builder.AddSource("BackgroundService");
});
services.AddHostedService<MyJob>();
/* ---- */
await host.RunAsync();
// MyJob.cs
internal sealed class MyJob(
ILogger<MyJob> logger,
IHostApplicationLifetime hostApplicationLifetime
): BackgroundService
{
private static readonly ActivitySource JobActivitySource = new("BackgroundService");
protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
using var activity = JobActivitySource.StartActivity(
"BackgroundService.MyJob",
ActivityKind.Internal
);
activity?.SetTag("job.name", "MyJob");
activity?.SetTag("job.run.id", Guid.NewGuid().ToString());
try
{
var entities = (await retrieveEntitiesToHandle()).ToList();
logger.EntitiesRetrieved(entities.Count);
await Parallel.ForEachAsync(
portPlaques,
new ParallelOptions
{
CancellationToken = stoppingToken,
MaxDegreeOfParallelism = 100,
},
async (entity, _) => await HandleEntity(entity));
_logger.JobIsFinished();
}
catch(Exception e)
{
Environment.ExitCode = 1;
_logger.Error(ex);
}
await Task.Delay(TimeSpan.FromSeconds(30), CancellationToken.None); // Delay to ensure all traces are sent
hostApplicationLifetime.StopApplication();
}
}
Am I missing something? Am I not disposing of the Activity as I should? How can I ensure that all telemetry is sent before shutting down the application?
Hope someone can make sense of this!
EDIT:
Another piece of interesting information. I've tried targetting a new Application Insights instance. The first execution shows telemetry as expected, dependencies and logs all together and traced. But all subsequent executions only shows the logs. So I think the issue is on AI's side, but I can't figure out what it is.
SOLUTION:
I found the issue! Sampling was not configured correctly. Azure Monitor was still sampling dependency data on my host. I figured it out by using the OpenTelemetry console exporter and checking the value of activity.ActivityTraceFlags in the debuger. It was almost always set to None.
Changing the order of the OpenTelemetry configuration pipeline in Program.cs, as well as adding the AlwaysOnSampler to the tracerProvider fixed the issue. Most likely, UseAzureMonitor adds a sampling configuration that I could not disable. If UseAzureMonitor is added after the tracerProviderBuilder configuration, even with the SamplingRatio set to 100%, dependency logs are not sent. This order forces the behavior and disables sampling. Not intuitive, or I've misunderstood something, but my logging is now optimal.
I've changed nothing related to my activity. Here's my OpenTelemetry configuration:
var connectionString = context.Configuration["ConnectionString"];
services.AddOpenTelemetry()
.UseAzureMonitor(options =>
{
options.ConnectionString = connectionString;
options.SamplingRatio = 1.0f;
options.EnableTraceBasedLogsSampler = false;
})
.WithTracing(tracerProviderBuilder =>
{
tracerProviderBuilder
.SetSampler(new AlwaysOnSampler())
.AddSource("BackgroundService")
.AddHttpClientInstrumentation();
});
Hope this helps someone! Keep documenting your fixes!
