Troubleshooting Intermittent Telemetry Logging in .NET 6 with OpenTelemetry: An In-depth Analysis and Temporary Solution

[SSPAGNAMN76]

Bug Report

Symptom

Describe the bug
After deployment, telemetry logging in our .NET 6 projects using OpenTelemetry only functions for a limited time span. The logging ceases without error warnings, and a memory dump reveals that instances of OpenTelemetry vanish until a connection pool refresh.

Expected behavior
Continuous and uninterrupted telemetry logging with OpenTelemetry instances remaining persistent without requiring a pool refresh.

Runtime environment:

• OpenTelemetry version: 1.6.0
• OS: Windows
• .NET version: .NET Framework 6.0 + Language C#

Additional context
Potential issue with the Garbage Collector prematurely deallocating the MeterProvider instance, interrupting the telemetry logging. Deployed applications utilizing .NET 6 with slightly varied OpenTelemetry initiation codes are being impacted.
Notably, within our suite of applications, the ones experiencing this issue are the only two hosted on IIS, presenting a possible correlation that may warrant further exploration.

Reproduce

Steps to reproduce the behavior:

1. Deploy a .NET 6 application utilizing OpenTelemetry for telemetry logging.
2. After a short time span, observe ceasing of telemetry logging without error messages.
3. Perform a memory dump and note the absence of OpenTelemetry instances.
4. Refresh the connection pool, note the reappearance of OpenTelemetry instances, and resume of telemetry logging.

Additional Steps Taken:

Enabled logging with the command:

setx OTEL_LOG_LEVEL "debug" /M

Yet, no logs are recorded in %ProgramData%\OpenTelemetry .NET AutoInstrumentation\logs.

Implemented a static field, Provider, to retain the MeterProvider instance and utilized GC.KeepAlive to prevent early collection by the GC:

private static MeterProvider Provider;

// Configuration logic...
Provider = Sdk.CreateMeterProviderBuilder()
    // Additional configuration logic...
   .Build();

I added GC KeepAlive

// Further configuration logic...
GC.KeepAlive(Provider);

that replaces the previous logic:

services.AddSingleton(meterProvider);

This temporary solution seems to initially work, but further validation in the production environment is necessary and better or alternative strategies are sought to avoid potential memory issues in the long-running applications.
Any insights, alternatives, or optimizations that might offer a more stable solution to this issue would be highly appreciated. Also, any additional steps or locations to explore for troubleshooting, considering the missing logs, would be beneficial.

Configuration class code

Here I provide you the code of the configuration class before applying changes described above :

using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using OpenTelemetry;
using OpenTelemetry.Exporter;
using OpenTelemetry.Metrics;
using OpenTelemetry.Resources;
using System;
using System.Collections.Generic;
using System.Diagnostics.Metrics;
using System.Reflection;
using System.Threading;

namespace MyProject.Metrics;

public static class MetricsConfigurator
{
    private static readonly AsyncLocal<MetricStreamConfiguration> CurrentCallConfiguration = new();

    public static MeterProvider Configure(IConfiguration configuration, Assembly mainAssembly)
    {
        var appName = mainAssembly.GetName();
        var resource = ResourceBuilder.CreateDefault()
            .AddService(serviceName: appName.Name, serviceVersion: appName.Version!.ToString())
            .AddAttributes(new KeyValuePair<string, object>[]
            {
                new("server.name", Environment.MachineName),
                new("process.id", Environment.ProcessId)
            });

        var exportInterval = TimeSpan.FromMilliseconds(configuration.GetValue("OpenTelemetry:ExportIntervalMilliseconds", 60000));

        return Sdk.CreateMeterProviderBuilder()
            .AddMeter("*")
            .SetResourceBuilder(resource)
            .AddView(instrument =>
            {
                var config = CurrentCallConfiguration.Value;
                CurrentCallConfiguration.Value = null;
                return config;
            })
            .AddOtlpExporter((eo, mo) =>
            {
                eo.Endpoint = new Uri("http://localhost:2222");
                eo.Protocol = OtlpExportProtocol.Grpc;
                mo.PeriodicExportingMetricReaderOptions = new PeriodicExportingMetricReaderOptions
                {
                    ExportIntervalMilliseconds = (int)exportInterval.TotalMilliseconds
                };
                mo.TemporalityPreference = MetricReaderTemporalityPreference.Delta;
            }).Build();
    }

    public static void AddOpenTelemetry(this IServiceCollection services, IConfiguration configuration)
    {
        var meterProvider = Configure(configuration, Assembly.GetCallingAssembly());
        services.AddSingleton(meterProvider);
    }

    public static Meter UsingConfiguration(this Meter meter, MetricStreamConfiguration configuration)
    {
        CurrentCallConfiguration.Value = configuration;
        return meter;
    }
}

The class is referenced in *Program.cs* written using Minimal Hosting / Minimal Apis approach :

// ......
builder.Services.AddOpenTelemetry(builder.Configuration);
// ......

Log Results:

Enabling logs the following error comes out, but I'm pretty sure that we haven't network issue :

`20`23-10-05T19:27:09.5341587Z:Exporter failed send data to collector to {0} endpoint. Data will not be sent. Exception: {1}{http://localhost:5110/}{Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error starting gRPC call. HttpRequestException: An error occurred while sending the request. IOException: The request was aborted. IOException: The response ended prematurely while waiting for the next frame from the server.", DebugException="System.Net.Http.HttpRequestException: An error occurred while sending the request.")---> System.Net.Http.HttpRequestException: An error occurred while sending the request.---> System.IO.IOException: The request was aborted.---> System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync()--- End of inner exception stack trace ---at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()at System.Net.Http.Http2Connection.Http2Stream.TryEnsureHeaders()at System.Net.Http.Http2Connection.Http2Stream.ReadResponseHeadersAsync(CancellationToken cancellationToken)at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)--- End of inner exception stack trace ---at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)at Grpc.Net.Client.Internal.GrpcCall2.RunCall(HttpRequestMessage request, Nullable1 timeout)--- End of inner exception stack trace ---at Grpc.Net.Client.Internal.HttpClientCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)`
   `at Grpc.Core.Interceptors.InterceptingCallInvoker.b__3_0[TRequest,TResponse](TRequest req, ClientInterceptorContext`2 ctx)at Grpc.Core.ClientBase.ClientBaseConfiguration.ClientBaseConfigurationInterceptor.BlockingUnaryCall[TRequest,TResponse](TRequest request, ClientInterceptorContext`2 context, BlockingUnaryCallContinuation`2 continuation)at Grpc.Core.Interceptors.InterceptingCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)`
   `at OpenTelemetry.Proto.Collector.Metrics.V1.MetricsService.MetricsServiceClient.Export(ExportMetricsServiceRequest request, CallOptions options)`
   at OpenTelemetry.Proto.Collector.Metrics.V1.MetricsService.MetricsServiceClient.Export(ExportMetricsServiceRequest request, Metadata headers, Nullable`1 deadline, CancellationToken cancellationToken)at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.ExportClient.OtlpGrpcMetricsExportClient.SendExportRequest(ExportMetricsServiceRequest request, CancellationToken cancellationToken)}`

[SSPAGNAMN76]

Clear Indication Towards an IIS Context Issue

Thank you all for your diligent observations and comments thus far. After traversing through the data and instances provided, we've descended into a scenario that requires our utmost attention and collaborative resolution. I’ve dissected the situation and here is a clear, deductive path that leans towards the conclusions reached in point 3.

1. Persistent Memory Instances:

After manually invoking the Garbage Collector during the memory dump, both instances - the metrics-producing application and the collector - remain discernible in the memory. This consistency between active instances and memory representation points towards an undeviating relation of instances with our issue at hand, rather than an irregularity in memory allocation or deallocation.

2. Network Error Elimination:

The co-existence of the metrics producer and collector on the identical machine effectively nullifies the hypothesis of network errors contributing to the traced issue. This brings to the forefront a stark revelation that the surface-level error we are perceiving is perhaps a symptom of an underlying, concealed issue.

3. The IIS Context Culprit:

When immersing into a .NET 6 console application context, the metrics are dispatched seamlessly, devoid of discrepancies. Conversely, introducing an application into the IIS context, by launching it as a process (in-process), resurrects the aforestated issue. This correlation between the manifestation of the problem and the IIS context is undeniable.

Conclusion

Considering these aspects, it's evident that our issue is intricately tied to the IIS context in which the application is running. It's imperative that we dive deep into this particular area, exploring potential incongruities or conflicts that might be surfacing only within this specific context.

Your expertise and insights into how applications behave diversely when executed within an IIS context, or any anomalies witnessed previously, would be immensely valuable. Urgency binds us due to the criticality of the situation, and your swift response will be greatly appreciated. Let's unravel this together and sculpt a resolution at the earliest. Thank you in advance for your cooperation and looking forward to fruitful discussions ahead.

[SSPAGNAMN76]

Open a bug for developers. Thanks to all for the attention.
#4936