Traces, logs, correlation are lost when using Arcus.Observability in Azure Functions

[fgheysels]

Describe the bug

I have a Timer Triggered Azure Function, in where I use Arcus.Observability (and thus also Serilog) to log to Azure Application Insights.

Although there are traces being logged to Application Insights, they're not correlated. With that , I mean that I cannot get an overview of traces (dependencies, etc... ) that were logged during one Function Invocation.

When I do not use Arcus.Observability and Serilog, everything is nicely linked AND there are things logged that are not logged out-of-the box when using Arcus.

To Reproduce

This is how I setup logging using Arcus:

internal class Startup : FunctionsStartup
{
        public override void Configure(IFunctionsHostBuilder builder)
        {
            var configuration = builder.GetContext().Configuration;

            builder.ConfigureSecretStore(secretStoreBuilder => AddSecretProviders(secretStoreBuilder, configuration));

            builder.Services.AddLogging(loggingBuilder => ConfigureLogging(loggingBuilder, configuration));
        }

        private static void ConfigureLogging(ILoggingBuilder builder, IConfiguration configuration)
        {
            var functionDependencyContext = DependencyContext.Load(typeof(Startup).Assembly);
            
            var logConfiguration = new LoggerConfiguration()
                                        .MinimumLevel.Is(LogEventLevel.Information)
                                        .Enrich.FromLogContext()                                           
                                        .Enrich.WithComponentName("curated-dsbuilder-plc")
                                        .WriteTo.Console();

            var telemetryKey = configuration.GetValue<string>("APPINSIGHTS_INSTRUMENTATIONKEY");

            if (!String.IsNullOrWhiteSpace(telemetryKey))
            {                
                logConfiguration.WriteTo.AzureApplicationInsights(telemetryKey);
            }

            builder.ClearProvidersExceptFunctionProviders();
            builder.AddSerilog(logConfiguration.CreateLogger());
        }
}

When the Function runs, I can find all sort of things in App Insights, but correlation info is missing. The traces do not contain any Operation Id , Parent Id header

If I change the function, so that Arcus.Observability and the AppInsights extension is not used for logging, traces are correlated AND I see things being logged that are not logged when using Arcus.Observability:

In the screenshot above, you can see that there are traces being logged for getting a token; a (SQL) dependency is logged out of the box to Azure Synapse, .... These things are not logged out-of-the-box when I use Arcus.Observability (when using Arcus, I make use of an Arcus extension method to log the dependency myself, but when I do not use Arcus, it is done out-of-the box).
It looks like some traces / dependencies / .... are lost when using Arcus.Observability. Could this have something to do with configured loglevels ? (As you can see, the default loglevel that I've configured is Information).

The screenshot above shows what and how is being logged when we setup logging like this:

internal class Startup : FunctionsStartup
{
        public override void Configure(IFunctionsHostBuilder builder)
        {
            var configuration = builder.GetContext().Configuration;

            builder.ConfigureSecretStore(secretStoreBuilder => AddSecretProviders(secretStoreBuilder, configuration));
            
            builder.Services.AddLogging();
        }
 }

(In my settings I have an APPINSIGHTS_INSTRUMENTATIONKEY setting that contains the instrumentation-key of App Insights).

Expected behavior
All logs are nicely correlated.
All information that is collected out of the box, must be available in App Insights.

[stijnmoreels]

Ok, so to recap: using Arcus/Serilog gives diff results than using Microsoft logging solely.
First off, the ConfigureLogging method in the sample is not being used, but that is maybe bc the sample was incomplete. 😅
I think we need to have a conversation on what where is missing and whether this is a Arcus or Serilog problem, with or without a log level relationship. The HTTP correlation is for example not yet supported in Arcus for Azure Functions, this can maybe also be a reason for this behavior.

[carolinasantos0]

I am also having this problem.

var logger = new LoggerConfiguration()
                .MinimumLevel.Debug()
                .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
                .Enrich.FromLogContext()
                .Enrich.WithComponentName(Constants.ComponentName)
                .Enrich.WithVersion()
                .Enrich.WithHttpCorrelationInfo(builder.Services.BuildServiceProvider())
                .WriteTo.Console()
                .WriteTo.AzureApplicationInsights(instrumentationKey)
                .CreateLogger();

when I run without the "WithHttpCorrelationInfo", it shows correctly.

[fgheysels]

Ok, so to recap: using Arcus/Serilog gives diff results than using Microsoft logging solely. First off, the ConfigureLogging method in the sample is not being used, but that is maybe bc the sample was incomplete. 😅 I think we need to have a conversation on what where is missing and whether this is a Arcus or Serilog problem, with or without a log level relationship. The HTTP correlation is for example not yet supported in Arcus for Azure Functions, this can maybe also be a reason for this behavior.

't Was indeed a mistake in the sample. I corrected it.

[fgheysels]

@carolinasantos0 What version of Arcus.Observability are you using ?

I am using 2.3.0 and with the sample code that I posted here, no requests are logged in App Insights. I can find some traces via 'Transaction Search' in App Insights, but nothing is linked to each other, so it is impossible to display a 'timeline'.

As you can see, I'm not even using ´WithHttpCorrelationInfo`.

Edit: this is specific for Azure Functions. I do not have these problems with web API's.

[carolinasantos0]

@fgheysels also 2.3.0.
Yes, same here. I'm using azure functions too

[stijnmoreels]

@fgheysels : As you can see, I'm not even using ´WithHttpCorrelationInfo`.

I'm wondering, if this is a problem of linking/correlation, and we don't use Arcus. Again, HTTP correlation in logging is not yet supported with Arcus. Then, I'm wondering if this is something to do with Arcus, and rather Serilog and/or log levels. Maybe a dedicated meeting should be planned for this.

[stijnmoreels]

@carolinasantos0 , the way you're using the IServiceProvider and the Serilog HTTP correlation, is not correct. Building a dedicated IServiceProvider with .BuildServiceProvider is not the solution to make Arcus support HTTP correlation in a Serilog environment. We don't support HTTP correlation in an Azure Functions environment.

[fgheysels]

I think this will indeed call for a dedicated meeting / more investigation.

I can already say that:

• I'm experiencing this in an Azure Function that is timer-triggered, running .NET 6 on Functions Runtime ~4
• I'm also seeing the same behavior in multiple .NET Core 3.1 Azure Functions (Azure Functions runtime ~3). Some of them are timer-triggered, others are eventhub, servicebus or blob triggered

It is hard to say whether this is Serilog or Arcus related.

Nothing is being logged in the 'request' table in AppInsights. So when you go to the 'performance' blade in AppInsights f.i., , it is just empty. As soon as I remove the Serilog logger usage, it works as expected (as in, requests are logged, and I all related telemetry is linked)

[fgheysels]

It looks like it's more working as expected if I do not call the ClearProvidersExceptFunctionProviders() method on the ILoggingBuilder.

[fgheysels]

When looking at the ClearProvidersExceptionFunctionProviders, the code looks a bit dangerous. This method was introduced because of custom dimensions that would dissapear, but we'll investigate this further.
See also discussion #189

[fgheysels]

I've done some further investigation:

• It seems that the ClearProvidersExceptFunctionProviders method doesn't remove anything. The only ILoggerProvider instances that are registered, are the 2 that should not be removed (in a default setup).
• It looks like this method would also not function correctly: Should there be additional ILoggerProvider instances registered, there will only be one instance removed (the first one encountered), hence the break statement that forces exitting the loop
• Not using ClearProvidersExceptFunctionProviders makes sure that logging to App Insights for your Function App is now done correctly. Which is actually weird, as the ClearProviders... method does actually nothing except looping over the Services collection. (Maybe that causes some side-effect ? )
• Custom dimensions are still correctly registered in App Insights when we're not calling this method when setting up logging

Therefore, I've decided to mark this method as obsolete. It can be removed in a later phase. (Note that this also has an effect on the Arcus.Observability.Telemetry.AzureFunctions package, as this extension method is the only thing that exists in this package.

[fgheysels]

I have now noticed that traces are written twice to application insights from within my FunctionApp. Needs to be investigated further.

[stijnmoreels]

I have now noticed that traces are written twice to application insights from within my FunctionApp. Needs to be investigated further.

Hehe, that's strange. 😅 Maybe something with sinks that are registered twice and/or Serilog+Microsoft logging and/or methods that are called twice?

[fgheysels]

To be honest, I don't see any duplicated registered sinks, nor do I see duplicatd logging calls.

This is how the logger is setup in the FunctionsStartup:

public override void Configure(IFunctionsHostBuilder builder)
{
    var configuration = builder.GetContext().Configuration;

    builder.ConfigureSecretStore(secretStoreBuilder => AddSecretProviders(secretStoreBuilder, configuration));
            
    builder.Services.AddLogging(loggingBuilder => ConfigureLogging(loggingBuilder, configuration));            
}

private static void ConfigureLogging(ILoggingBuilder builder, IConfiguration configuration)
{
   var logConfiguration = new LoggerConfiguration()
                                   .MinimumLevel.Information()   
                                   .Enrich.FromLogContext()
                                   .Enrich.WithComponentName("myname")
                                   .WriteTo.Console();

    var telemetryKey = configuration.GetValue<string>("APPINSIGHTS_INSTRUMENTATIONKEY");

    if (!String.IsNullOrWhiteSpace(telemetryKey))
    {
        logConfiguration.WriteTo.AzureApplicationInsights(telemetryKey);
    }

    builder.AddSerilog(logConfiguration.CreateLogger());
}

Also, not everything is logged twice. Some Traces are logged twice, but dependencies are not. (Dependencies that are tracked by the Azure Storage SDK for instance, are appearing only once in AppInsights).

There is a slight difference in the trace-text though; look at the quotes.

[fgheysels]

I'm wondering if this issue (duplicated entries that are not entirely identical) is because of using the APPINSIGHTS_INSTRUMENTATIONKEY config-setting. See also this document.

So, as a test, I renamed the APPINSIGHTS_INSTRUMENTATIONKEY setting and although my function is still running, no information is written anymore in the 'request' table in Application Insights.

[stijnmoreels]

Ok, wauw, that's kinda strange 🤔 . It's a good thing you found it!

[fgheysels]

I'll close this issue, as I've created another issue for the duplicated traces (and other strange things).
#359