Requests are not logged via Arcus.Observability in isolated Azure Functions with Http trigger

[fgheysels]

Describe the bug

When you create an Azure HTTP triggered function using the Arcus templates (v1.1.0), with Serilog logging configured to log to an Application Insights sinks, we can see that requests are being logged in AppInsights. However, it seems that those requests are not being logged via the Arcus middleware, but this are rather logged via the Microsoft middleware.

This means that the requests that are being logged, are not as expected. (f.i. the request body or response is not available although it has been configured, etc...)

The requests that are being logged, are logged because of the APPLICATIONINSIGHTS_CONNECTION_STRING configuration setting that is present in our config setting. If I remove or rename this setting , no requests are being logged anymore. This can be logical, as Azure Functions is actually looking for this setting to setup AppInsights logging.

I can see however that the warning traces that represent our 'request logging', are being written to Application Insights. However, they're not converted to the 'request' format, they're rather written as a regular trace (with severity level warning):

Because of this, additional logs / traces that we write inside the Function are also not present when looking at the 'end-to-end' transaction details of a request.

Consider this sample code:

When looking in Application Insights at the 'performance' blade, we can see this:

You can see that we see invocations for operation-name 'order' (which is the Function Name specified in the Function attribute). However, the requests that are logged here, are the requests that have been logged via the MSFT middleware (picked up because of the configured APPLICATIONINSIGHTS_CONNECTION_STRING setting). When drilling into one of those invocations, we notice that the custom log-traces and dependencies are not present:

We can find those specific traces though by using the 'Transaction Search' functionality in Application Insights:

Going into the details of these traces, we also notice that these traces do not have a parentId:

To Reproduce

Create a new Http Triggered (isolated) Function project using the Arcus template. Configure the Application Insights connection-string, run the project and perform some http calls.

dotnet new arcus-az-func-http -fw isolated --name sometestfunction

To be able to run this locally, make sure to correctly specify the AzureWebJobsStorage config setting in host.json:

{
    "IsEncrypted": false,
  "Values": {
    "FUNCTIONS_WORKER_RUNTIME": "dotnet-isolated",
    "APPLICATIONINSIGHTS_CONNECTION_STRING": "<your-connectionstring>",
    "AzureWebJobsStorage": "UseDevelopmentStorage=true"
  }
}

kudos to @Pauwelz for bringing this up.

[fgheysels]

I believe there are 3 things that we need to do:

• no longer use the APPLICATIONINSIGHTS_CONNECTION_STRING setting when using our AppInsights middleware
• making sure that Arcus middleware correctly logs requests in Application Insights
• making sure that additional traces, requests, etc... are correlated to the request that is logged by Arcus.

[stijnmoreels]

Ah, I remember. This is because of the tedious way that Azure Functions is set up. Because several internal workings are hidden and not available for customization, we had to be creative. Because we support W3C, we want the default Application Insights functionality combined with our easy-to-use logger infrastructure. To do that in Azure Functions, you need to provide the APPLICATIONINSIGHTS_CONNECTION_STRING. This will make sure that any additional stuff people want to write with the TelemetryClient will also be correlated like when they solely use Application Insights services. The problem though, is that we can't disable request tracking when we use this way of configuring Application Insights, so, the way it is set up is that Arcus fully uses the default Application Insights request tracking in those cases. The fact that there is a middleware component for isolated Azure Functions is probably a mistake that we overlooked.

So, in a way, this is not a bug, but expected behavior. As commented in the referenced issue about unwanted traces, here's the things we should consider doing:

• Add logging:logLevel:Host.Function=None to host.json
• Deprecated AzureFunctionsRequestTrackingMiddleware

[fgheysels]

But what about correlating your own custom traces to the correct request, because they're currently not correlated. Also, requests that are logged via the default Azure Functions middleware do not respect the role-name / app-name that we configure.

[stijnmoreels]

But what about correlating your own custom traces to the correct request, because they're currently not correlated.

This should work already. Are you sure you selected the 'correct' traces? And not the unwanted traces from the host logger? Bc, if you select the correct ones, you see that they are correlated to the request and other stuff.

Also, requests that are logged via the default Azure Functions middleware do not respect the role-name / app-name that we configure.

This is indeed something wrong with Azure Functions as they do not pick up ITelemetryInitializer instances, as they do not allow such customization. I imagine there may be some way, but haven't founded yet; sole focus was W3C service-to-service correlation; which finally works on all platforms.

[fgheysels]

But what about correlating your own custom traces to the correct request, because they're currently not correlated.

This should work already. Are you sure you selected the 'correct' traces? And not the unwanted traces from the host logger? Bc, if you select the correct ones, you see that they are correlated to the request and other stuff.

Yes. Consider an Azure Function project, created via the Arcus template. The only thing I've customized up until now, is just adding some additional logging.
For example:

When opening Application Insights after a few minutes, I can see only one request in the last 24 hours (logical, since I haven't run the function since today):

Drilling down in that request shows this:

So, the additional traces and custom dependency are not correlated to this request. However, they're logged as I can find them via the 'transaction search' in app insights:

@pauwelz can you confirm that you see the same behavior ?

[stijnmoreels]

That's different from my experience, and I also used a fresh template with only configuring Application Insights via the provided variable. 🤔 Since your dependency is logged as a trace and not a dependency, I imagine that Arcus Serilog is not configured correctly.

[fgheysels]

It's just the code that is provided by the Arcus Http Function template.

 public static async Task Main(string[] args)
        {
            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Debug()
                .WriteTo.Console()
                .CreateBootstrapLogger();

            try
            {
                IHost host = CreateHostBuilder(args).Build();

                await ConfigureSerilogAsync(host);
                await host.RunAsync();
            }
            catch (Exception exception)
            {
                Log.Fatal(exception, "Host terminated unexpectedly");
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }

private static async Task ConfigureSerilogAsync(IHost app)
    {
        var secretProvider = app.Services.GetRequiredService<ISecretProvider>();
        string connectionString = await secretProvider.GetRawSecretAsync("APPLICATIONINSIGHTS_CONNECTION_STRING");

        var reloadLogger = (ReloadableLogger)Log.Logger;
        reloadLogger.Reload(config =>
        {

            config.MinimumLevel.Information()
                      .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
                      .Enrich.FromLogContext()
                      .Enrich.WithComponentName(app.Services)
                      .Enrich.WithVersion(app.Services)
                      .WriteTo.Console();

            if (!string.IsNullOrWhiteSpace(connectionString))
            {
                config.WriteTo.AzureApplicationInsightsWithConnectionString(app.Services, connectionString);
            }

            return config;
        });
    }