Silent failure in TargetingTelemetryInitializer about featuremanagement-dotnet HOT 10 OPEN

It sounds like logging a warning would be appropriate.

from featuremanagement-dotnet.

How does AppInsights component normally bubble up warnings/errors?

It's happy to log issues when it's not in an initializer or processor- as initializers and processors are hooked into outgoing logs. There's a thread on their github about it microsoft/ApplicationInsights-dotnet#1536 and it appears to still be an issue with no fix eta.

from featuremanagement-dotnet.

So @zhiyuanliang-ms and I looked into this a bit, and were happy to add some logging- however...

Adding a logger here becomes a circular dependency, since AppInsights is built on top of logging:

InvalidOperationException: A circular dependency was detected for the service of type 
'Microsoft.Extensions.Logging.ILoggerFactory'.
Microsoft.Extensions.Hosting.IHostApplicationLifetime(Microsoft.Extensions.Hosting.Internal.ApplicationLifetime) 
-> Microsoft.Extensions.Logging.ILogger<Microsoft.Extensions.Hosting.Internal.ApplicationLifetime>(Microsoft.Extensions.Logging.Logger<Microsoft.Extensions.Hosting.Internal.ApplicationLifetime>) 
-> Microsoft.Extensions.Logging.ILoggerFactory(Microsoft.Extensions.Logging.LoggerFactory) 
-> System.Collections.Generic.IEnumerable<Microsoft.Extensions.Logging.ILoggerProvider> 
-> Microsoft.Extensions.Logging.ILoggerProvider(Microsoft.Extensions.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider) 
-> Microsoft.Extensions.Options.IOptions<Microsoft.ApplicationInsights.Extensibility.TelemetryConfiguration>(Microsoft.Extensions.DependencyInjection.TelemetryConfigurationOptions) 
-> System.Collections.Generic.IEnumerable<Microsoft.Extensions.Options.IConfigureOptions<Microsoft.ApplicationInsights.Extensibility.TelemetryConfiguration>> 
-> Microsoft.Extensions.Options.IConfigureOptions<Microsoft.ApplicationInsights.Extensibility.TelemetryConfiguration>(Microsoft.Extensions.DependencyInjection.TelemetryConfigurationOptionsSetup) 
-> System.Collections.Generic.IEnumerable<Microsoft.ApplicationInsights.Extensibility.ITelemetryInitializer> 
-> Microsoft.ApplicationInsights.Extensibility.ITelemetryInitializer(Microsoft.FeatureManagement.Telemetry.ApplicationInsights.AspNetCore.TargetingTelemetryInitializer) 
-> Microsoft.Extensions.Logging.ILogger<Microsoft.FeatureManagement.Telemetry.ApplicationInsights.AspNetCore.TargetingTelemetryInitializer>(Microsoft.Extensions.Logging.Logger<Microsoft.FeatureManagement.Telemetry.ApplicationInsights.AspNetCore.TargetingTelemetryInitializer>) 
-> Microsoft.Extensions.Logging.ILoggerFactory

from featuremanagement-dotnet.

Thanks for looking into it. How does AppInsights component normally bubble up warnings/errors?

from featuremanagement-dotnet.

@rossgrambo

Did you try httpContext.RequestServices.GetService<ILogger>(); ?

from featuremanagement-dotnet.

httpContext.RequestServices.GetService();

@jimmyca15 This returns null.

from featuremanagement-dotnet.

@zhiyuanliang-ms

Sorry, should be httpContext.RequestServices.GetService<ILoggerFactory>();

from featuremanagement-dotnet.

httpContext.RequestServices.GetService()

This works.

protected override void OnInitializeTelemetry(HttpContext httpContext, RequestTelemetry requestTelemetry, ITelemetry telemetry)
{
    if (telemetry == null)
    {
        throw new ArgumentNullException(nameof(telemetry));
    }

    if (httpContext == null)
    {
        throw new ArgumentNullException(nameof(httpContext));
    }

    EnsureInit(httpContext);

    // Extract the targeting id from the http context
    string targetingId = null;

    if (httpContext.Items.TryGetValue(TargetingIdKey, out object value))
    {
        targetingId = value?.ToString();
    }

    if (!string.IsNullOrEmpty(targetingId))
    {
        // Telemetry.Properties is deprecated in favor of ISupportProperties
        if (telemetry is ISupportProperties telemetryWithSupportProperties)
        {
            telemetryWithSupportProperties.Properties["TargetingId"] = targetingId;
        }
    }
    else
    {
        //
        // This line will cause StackOverFlowException, if I changed the log level to debug, then no exception will be thrown
        _logger.LogWarning("No Targeting Id");
    }
}

private void EnsureInit(HttpContext httpContext)
{
    if (_initialized == 0)
    {
        lock (_lock)
        {
            if (Interlocked.Read(ref _initialized) == 0)
            {
                _logger = httpContext.RequestServices.GetRequiredService<ILoggerFactory>().CreateLogger<TargetingTelemetryInitializer>();

                Interlocked.Exchange(ref _initialized, 1);
            }
        }
    }
}

I tried this pattern. The logger can be initialized. But another issue occurred. There will be tons of _logger.LogWarning("No Targeting Id"); calls and it will eventually throw stackoverflow exception.
It seems like the Application Insights will send telemetry if there is any warning level log. This will cause infinite recursive call of OnInitializeTelemetry and all of them are without TargetingId.

https://learn.microsoft.com/en-us/azure/azure-monitor/app/ilogger?tabs=dotnet6

But I found that if we change the log level to debug, everything works fine (which is interesting)

Here is the screenshot of what the additional telemetry of the logwarning call looks like:

It is technically possible to filter such telemetry. A very naive example will be like:

if (!string.IsNullOrEmpty(targetingId))
{
    // Telemetry.Properties is deprecated in favor of ISupportProperties
    if (telemetry is ISupportProperties telemetryWithSupportProperties)
    {
        telemetryWithSupportProperties.Properties["TargetingId"] = targetingId;
    }
}
else
{
    if (telemetry is TraceTelemetry traceTelemetry)
    {
        if (traceTelemetry.Message.Equals("No Targeting Id"))
        {
            return;
        }
    }

    _logger.LogWarning("No Targeting Id");
}

What do you think? @jimmyca15 @rossgrambo @zhenlan

from featuremanagement-dotnet.

Thank you for looking into it @zhiyuanliang-ms,

I don't like logging here. While we could get around it in this way- but I think it's a pattern we shouldn't try to break. The short version of this logic is "Initializers will run on all logs", and I don't like trying to get around this idea.

If the log level of debug was reliable, that would be great. However App Insights lets you choose your log level (by default it's Information). This means customers who change it would crash / still be subject to this.

I think the best two options are either throw or silently fail. With the library in it's current state, I think silently failing makes more sense. We're working on adjusting the TargetingContext cache logic and if we end up with a Scoped service, I don't think this is a concern anymore, since the Targeting Context will always exist.

from featuremanagement-dotnet.

The short version of this logic is "Initializers will run on all logs", and I don't like trying to get around this idea.

Agreed

from featuremanagement-dotnet.