ILogger structured logging with Application Insights not working in .Net 5 Azure Function

[Done3319]

.Net 5 Azure Function: Custom properties of ILogger generated messages are not showing up in Application Insights

Example: logger.LogInformation("Example {ExampleValue}", 1001);

Expected in Application Insights log: customDimensions.propExampleValue == 1001 customDimensions.prop{OriginalFormat} == "Example {ExampleValue}"

However, the only thing that is logged is the message as string: message == "Example 1001"

This makes structured logging impossible and logging to Application Insights useless, as no proper filtering can be applied.

Other non-working examples:

using (_logger.BeginScope("ScopeTest"))
{
     _logger.LogInformation("Scope logging test"); //Logs only the string, scope missing
}

Dictionary<string, string> properties = new Dictionary<string, string>()
{
     { "Prop1", "abc" },
     { "Prop2", "def" },
};
 _logger.LogInformation("CustomProperties", properties); //Logs only the string, dictionary content missing completely

[rikbosch]

+1 logging with ILogger currently sends the traces over grpc to the functions worker host.

I believe this somewhat relates to #410 . When activity popagation is handled correctly, it should be able to just use regular application insights logging (and dependency tracking etc) in the dotnet worker. That way, all the application insights telemetry is correctly visible in the azure portal in one operation.

[fabiocav]

• @brettsam for awareness

[brettsam]

I've opened https://github.com/Azure/azure-functions-host/issues/7452 to support this in host. Once supported, we'll work through this on the worker side.

[Matthewsre]

This has been a pretty big pain point for my team after migrating to dotnet-isolated so we could use .net 5. None of our expected customDimensions have been showing up so we have switched to including the dictionary values passing into the message instead so we can at least see what is going on. This breaks all of our aggregations in application insights for alerts and reporting.

Any suggestions or alternatives for working around this issue?

[tovich37]

This has been a pretty big pain point for my team after migrating to dotnet-isolated so we could use .net 5. None of our expected customDimensions have been showing up so we have switched to including the dictionary values passing into the message instead so we can at least see what is going on. This breaks all of our aggregations in application insights for alerts and reporting.

Any suggestions or alternatives for working around this issue?

Any news about workaround? (.NET 5 or .NET 6)

[kelps]

As a workaround, I thought of adding a custom logger factory to DI that would create an ILogger that doesn't flow through the host GRPC channel and would connect directly to Insights. In theory it should work, but we would loose all console and stream logs in Azure and local dev and would be forced to rely on Insights for ANY diagnostics. If we try to keep the connection to GRPC, to also show in the stream logs, Insights would get duplicated entries with and without the structured information.

It should work, but I didn't have the time to try and test it yet.

This NEEDS to be FIXED soon. It is a very serious bug. From the looks of it, I'm worried that it might only happen for .NET 7, but that would be a serious case of not giving enough importance to very important community feedback. This specific issue is already 7 months old, and it was not the first on this problem.

If the intention really is to have only isolated process in .NET 7, as the roadmap suggests, EVERYTHING that work in process will need to work in isolated, including structured logs.

Please make it available as a fix in 6, not only in 7!

[tovich37]

As a workaround, I thought of adding a custom logger factory to DI that would create an ILogger that doesn't flow through the host GRPC channel and would connect directly to Insights. In theory it should work, but we would loose all console and stream logs in Azure and local dev and would be forced to rely on Insights for ANY diagnostics. If we try to keep the connection to GRPC, to also show in the stream logs, Insights would get duplicated entries with and without the structured information.

It should work, but I didn't have the time to try and test it yet.

This NEEDS to be FIXED soon. It is a very serious bug. From the looks of it, I'm worried that it might only happen for .NET 7, but that would be a serious case of not giving enough importance to very important community feedback. This specific issue is already 7 months old, and it was not the first on this problem.

If the intention really is to have only isolated process in .NET 7, as the roadmap suggests, EVERYTHING that work in process will need to work in isolated, including structured logs.

Please make it available as a fix in 6, not only in 7!

Good idea, but what about the "End-to-end" functionality? Because I tested with Serilog (directly in Application Insight) and I lost this functionality.

I also agree with @kelps, this bug is very serious.

[bricenocar]

Is there any plan to fix this bug soon? We recently upgraded to .NET 5 and this caused an issue now with our structured logs in app insights.

[kelps]

Is there any plan to fix this bug soon? We recently upgraded to .NET 5 and this caused an issue now with our structured logs in app insights.

@bricenocar the problem only happens when running in dotnet isolated mode. If you migrated to .net5, you probably can make your functions using "int process" mode, and there structured logs work. (Unless you changed to isolated in .net5 to take advantage of some of the new features. In that case, no luck yet, except if you try something similar to what I suggested above...)

[bricenocar]

Thanks for the answer @kelps. I will try to fix it with your workaround :). Will let you know if it works.

[WestDiscGolf]

After spending a lot of time trying to get it working with .NET 6 / isolated process Azure Functions I stumbled across this issue 😢

Any updates on when this will be looked at? Thanks

[kelps]

Over the weekend I tried playing with a workaround for this a little. My original idea was "bad" as I intended to replace the logger factory with one that would create the ILogger for insights without flowing through the GRPC channel.

I realized that this is not necessary. What I need to do is add an Insights log provider in the worker process and disable my log sources from going to Insights in the host process. This way, the logs will keep flowing and showing in the Log Stream.

I didn't go far with that idea for lack of time, but I plan on continuing those tests soon. I believe this workaround has a real chance of working and be quite simple to implement, once I find the proper way to register the Insights logger provider in the worker process. The configuration to disable my logs from going to Insights in the host already worked.

This will also have the extra benefit that I'll be able to set my custom logs as debug or trace when needed, since as it is now the filters in the host seem to prevent me from logging or even seeing my custom logs on any levels lower than Information, no matter what I configure.

I'll post updates here about the workaround, as soon as I try again, working or not.

[juanbriceno]

Well, looks like it is working for us now. We have implemented net6 and function v4 (We were using net5 - v3). We have also added the following code in Program.cs

.ConfigureLogging((context, builder) => { builder.AddApplicationInsights(context.Configuration["APPINSIGHTS_INSTRUMENTATIONKEY"]); }).Build();

BE SURE to use "Instrumentation key" and not the connectionstring. I have tested with connectionstring and it is not working.

When writing structured logs, we are using the ILogger from the function context:

var logger = context.GetLogger("YourClassName");

And then a BeginScope...

In application insights we see the properties now, and the pretty cool thing is that it is showing the actual property name without the prop prefix it used to show previously. Cool stuff!

Maybe Microsoft just fixed this? not sure but it is working now like a charm!

Let me know if you need more info ;)

Cheers!

[WestDiscGolf]

@juanbriceno thanks for the update, will give it a go. What extra nuget packages need to be referenced to use the AddApplicationInsights extension method? Thanks

[juanbriceno]

Oh! @WestDiscGolf that is a good one. I forgot about the packages :) We have updated all the packages to the very latest versions. This is the one for adding appinsights: -Microsoft.Extensions.Logging.ApplicationInsights (2.19.0)

Let me know how it goes ;)

[WestDiscGolf]

Thanks @juanbriceno! Will give it a go 😄

[WestDiscGolf]

If anyone is struggling to get this working, make sure you're on a windows host and not a Linux one. I feel I've lost too many hours because I chose "linux consumption" 😞

[kelps]

Well, looks like it is working for us now. We have implemented net6 and function v4 (We were using net5 - v3). We have also added the following code in Program.cs

.ConfigureLogging((context, builder) => { builder.AddApplicationInsights(context.Configuration["APPINSIGHTS_INSTRUMENTATIONKEY"]); }).Build();

BE SURE to use "Instrumentation key" and not the connectionstring. I have tested with connectionstring and it is not working.

When writing structured logs, we are using the ILogger from the function context:

var logger = context.GetLogger("YourClassName");

And then a BeginScope...

In application insights we see the properties now, and the pretty cool thing is that it is showing the actual property name without the prop prefix it used to show previously. Cool stuff!

Maybe Microsoft just fixed this? not sure but it is working now like a charm!

Let me know if you need more info ;)

Cheers!

Excellent! I'll try that tomorrow. But just fyi, this is in line with the fix I was planning, I just didn't get to the correct way to register it.

In other words, there was nothing fixed on Microsoft side yet. What you did was make your logs be registered on Insights directly from the worker process, instead of the host process as is the default.

I only suggest you disable Function logs to Insights in the host process, to prevent duplicated logs. I'm on my phone now, so I can't post an example of this setting, but I'll do it tomorrow when I get at the office.

I might even adopt this as my default for logging, even if this gets "fixed" in the functions sdk, just for the benefits of better control of the log levels, better naming of the custom dimension properties (without the Prop_ prefix)

[juanbriceno]

Yeah, i think this way should work. I tried by clearing all logging providers first and then adding AddAppInsight line but it removed the console logger. If you check the providers within the builder property, you will see the console provider but i did not see any other. In my head, the built-in appinsight one is not being inyected in this version so it has to be done manually, which i'm fine with it cause we have kind of full control over the whole logging configuration/functionality.

Maybe Microsoft will go this way or maybe they are inyecting it in a new update.

Good work everyone and have a nice weekend!

[kelps]

As promissed, here is the host.json in my test project. The loglevel block inside applicationInsights is what disables the Function logs from being recorded to Insights from the host process. Since the configuration you showed above will already be sending those logs to Insights from the worker process, in theory we don't loose anything and we actually gain more control. Ignore the extensions part (it is related to service bus triggers)

  "version": "2.0",
  "logging": {
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request,Trace"
      },
      "logLevel": {
        "Function": "None"
      }
    },
    "logLevel": {
      "default": "Information",
      "Function": "Information"
    }
  },
  "extensions": {
    "serviceBus": {
      "messageHandlerOptions": {
        "maxConcurrentCalls": 1
      }
    }
  }
}

[WestDiscGolf]

@kelps Thanks for posting your hosts.json example. I am still struggling to get it to work 😢 I have the latest packages registered and setup yet still experiencing double entry in the AppInsights.

I've set the log level in my hosts.json as you specify above and it complains at me that it's not valid in the schema.

I've tried shuffling the order of the host builder setup so that logging is configured first before the worker defaults and other dependencies but no luck.

            var host = new HostBuilder()
                .ConfigureLogging((context, builder) =>
                {
                    var key = context.Configuration["APPINSIGHTS_INSTRUMENTATIONKEY"];
                    builder.AddApplicationInsights(key);
                })
                .ConfigureFunctionsWorkerDefaults()
                .ConfigureServices(services =>
                {

                })
                .Build();

Still new to Functions with AppInsights and I'm stuck :persevere:

You don't happen to have a repo with a demo example somewhere do you? If not, no worries 😃 Really appreciate the help, thanks in advance 👍

[kelps]

I don't have a public repo with this yet. Sorry. I'll see if I can create a small repo on github with this setup when I get some time. As of this moment, my test code has other dependencies that I can't put in a public repo.

[WestDiscGolf]

@kelps No worries, totally understand, just thought I would ask 😄

Hope you have a Happy Christmas 🎄

[juanbriceno]

Hi @WestDiscGolf , maybe a dumb comment but i think is good to double check all configurations. It will be net6 and v4 in the azure function project and check also the azure function app configuration:

FUNCTIONS_EXTENSION_VERSION --> ~4 FUNCTIONS_WORKER_RUNTIME --> dotnet-isolated

Also make sure you are passing the APPINSIGHTS_INSTRUMENTATIONKEY instead of connectionstring (double check the value in the Azure function configuration value).

My host.json file looks like this now...

{ "version": "2.0", "logging": { "applicationInsights": { "samplingSettings": { "isEnabled": true, "excludedTypes": "Request" } } }, "functionTimeout": "00:05:00" }

[WestDiscGolf]

Hi @juanbriceno, no worries about validating 😄

My csproj file is:

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <TargetFramework>net6.0</TargetFramework>
    <AzureFunctionsVersion>v4</AzureFunctionsVersion>
    <OutputType>Exe</OutputType>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="Microsoft.ApplicationInsights.WorkerService" Version="2.20.0" />
    <PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.Http" Version="3.0.13" />
    <PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.3.0" OutputItemType="Analyzer" />
    <PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.6.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.ApplicationInsights" Version="2.20.0" />
  </ItemGroup>
  <ItemGroup>
    <None Update="host.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
    <None Update="local.settings.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
      <CopyToPublishDirectory>Never</CopyToPublishDirectory>
    </None>
  </ItemGroup>
</Project>

Yes, the output of those variables are when published to a windows consumption plan are:

Version: ~4

Runtime: dotnet-isolated

And yes, I'm using the APPINSIGHTS_INSTRUMENTATIONKEY. Interestingly when I output the values of those environment variables when running the functions app in Visual Studio the version value is not present but the core tools output in the console window confirm v4.

[juanbriceno]

Looks good. Now when it comes to the code (structured logs) i am doing it this way...

` [Function("PostFile")] public async Task Run([HttpTrigger(AuthorizationLevel.Anonymous, "post", Route = null)] HttpRequestData req, FunctionContext context) { var logger = context.GetLogger("PostFile");

using (logger.BeginScope("Operation {MCOMOperationTrace} processed request for {MCOMLogSource}.", "PostFile", "Archiving")) { // Here your logs..... `

[WestDiscGolf]

It's coming through fine but still getting double entries from both the function and the logger (if that makes sense) which @kelps's solution tries to get rid of but unfortunately I can't get to work. I also can't get it to log anything other than Critical, Error, Information or Warning locally so any debug level items get missed (locally and in AppInsights). Might have to call it a day and stick with in process functions for now 😢

Thanks for all your help in trying to get this working!

[kelps]

It's coming through fine but still getting double entries from both the function and the logger (if that makes sense) which @kelps's solution tries to get rid of but unfortunately I can't get to work. I also can't get it to log anything other than Critical, Error, Information or Warning locally so any debug level items get missed (locally and in AppInsights). Might have to call it a day and stick with in process functions for now 😢

Thanks for all your help in trying to get this working!

Ok, I was just able to test this and the structured logs did get recorded, but with some "missing" information and as you mentioned, my attempt at fixing the duplicated log to insights didn't work.

Also, as far as I can tell, the minimum log level can only be set in code. If you call SetMinimumLevel(Trace) in your program.cs, it will log traces and debugs, but when you do that, it ignores the settings in configuration. That could be the reason we can't properly configure this (the host process could be setting the configurations in code, wich overrides the settings in files and the portal)

The missing information are a few fields that are set in the logs that come from the host but not in the logs that come from the worker process: logLevel, ProcessId, HostInstanceId, cloud_RoleName, operation_Name, operation_id, operation_ParentId

There is probably a way to set this values in scopes or some other way. I didn't investigate this yet.

The bad thing about switching to in-process would be:

• we loose control over the versions of some of our dependencies, when the host also has the same dependency, being limited to the version used by the host process.
• no middleware support (I'm using middleware for error handling/logging) and plan on using it for other cross concerns as well, like auth.
• .net7 is expected to support only isolated-process

The correct fix would be for the host process to properly support scopes flowing through the GRPC channel and also to respect the settings defined in the hosts files (log levels lower than Information and different log level by provider, for example). Another thing would be that the structured logs respected the key names we generate instead of attaching a "Prop_" prefix. If they do this to prevent name collision, they should add the prefix to their properties, not ours. We should have full control over how our logs are generated.

An alternative fix would be for the host to simply respect our settings. This way the settings above would've disabled the Function logs to Insights, allowing us to log the way we need without duplication. That could be the simpler way to fix this mess...

[kelps]

It's been about 2 months since my last post on this issue, and I don't see any news about it being fixed or even being addressed/planned. I am about to put code in production with my workaround, even with the logs getting duplicated in order to be able to have good logs. ANY news on this would be really appreciated!

[Done3319]

Thanks for the workaround! This at least allows structured logging, although with duplicates. Anyhow, there are still too many things not working in regards of Application Insights. The dependency map shows the Function App isolated, calls from the Function App to other web-services or Azure Storage etc. are not visible at all... And no one seems to be working on these serious bugs. This is really frustrating. Overall the solution seem not to be enterprise ready.

[cmeyertons]

Is there a plan forward with this item?

@brettsam @fabiocav it doesn’t seem to be mentioned as much as the other App Insights issues, etc. and seems to have been lost in the ether :/

[kosperera]

Does context.Features.Get<RequestTelemetry>() work in Azure Functions v4 net6 Isolated Middleware? I tried to access it but got a null reference exception. Same for Activity.Current.AddBaggage(...).

[brettsam]

I have no idea how I missed this entire conversation; I apologize for the delay here.

The approach we've taken is to have logging go directly to App Insights from the worker (as was proposed here). This uses the App Insights logger with very minimal changes (no "prop_" appended, for example).

Give the newer package a try and see if it works how you'd expect: https://github.com/Azure/azure-functions-dotnet-worker/pull/944#issue-1282987627https://github.com/Azure/azure-functions-dotnet-worker/pull/944#issue-1282987627.

[Mech0z]

I have no idea how I missed this entire conversation; I apologize for the delay here.

The approach we've taken is to have logging go directly to App Insights from the worker (as was proposed here). This uses the App Insights logger with very minimal changes (no "prop_" appended, for example).

Give the newer package a try and see if it works how you'd expect: #944 (comment).

We are using the new preview package in https://github.com/Energinet-DataHub/geh-charges/ configured here https://github.com/Energinet-DataHub/geh-charges/blob/main/source/GreenEnergyHub.Charges/source/GreenEnergyHub.Charges.FunctionHost/ChargesFunctionApp.cs with these packages https://github.com/Energinet-DataHub/geh-charges/blob/main/source/GreenEnergyHub.Charges/source/GreenEnergyHub.Charges.FunctionHost/GreenEnergyHub.Charges.FunctionHost.csproj

But when we use it we get some wierd extra logging messages and sometimes only those https://github.com/Energinet-DataHub/geh-charges/issues/1882 an information message with some prefixed text and without the custom properties we have specified

[madushans]

Looks like this is still broken.

Probably should add this to the execution mode comparison document, so people (like me) don't waste their time upgrading to .NET 7 and realize logging, custom metrics and dashboards that rely on structured logging get hopelessly broken.

if you like some pakour, see https://github.com/Azure/azure-functions-dotnet-worker/issues/1182 for some guidance on how to get some of it to work. Though probably not for production.

[ThePatrickMartin]

The following code in .NET 8 isolated worker is not adding customDimensions. Could this issue still be open after 2+ years?

            using (logger.BeginScope(new Dictionary<string, string> {
                { "Entity", entity },
                { "CorrelationId", correlationId },
                { "Function", function },
                { "EventType", eventType.ToString() }
            }))
            {
                logger.Log(Microsoft.Extensions.Logging.LogLevel.Information, dataEventTemplate, entity, correlationId, function, eventType.ToString(), message);
            }

[aressler38]

The following code in .NET 8 isolated worker is not adding customDimensions. Could this issue still be open after 2+ years?

            using (logger.BeginScope(new Dictionary<string, string> {
                { "Entity", entity },
                { "CorrelationId", correlationId },
                { "Function", function },
                { "EventType", eventType.ToString() }
            }))
            {
                logger.Log(Microsoft.Extensions.Logging.LogLevel.Information, dataEventTemplate, entity, correlationId, function, eventType.ToString(), message);
            }

Try Dictionary<string, object>.

[ThePatrickMartin]

Alas, it made no difference.

[aressler38]

Alas, it made no difference.

Well that's a bummer. I have been able to make .net8 structured logging with scopes working in prior projects, but I've always used the <string, object> dictionary type as <string, string> hasn't worked in the past for me. I'd double check the installed package versions and the dependency injection setup. Double check this issue as there was an initial workaround: https://github.com/Azure/azure-functions-dotnet-worker/issues/1182

[ThePatrickMartin]

The relevant installed packages:

• Microsoft.Azure.Functions.Worker.ApplicationInsights 1.1.0
• Microsoft.ApplicationInsights.WorkerService 2.22.0

Injection code:

        // Add console logging
        services.AddLogging(loggingBuilder =>
        {
            loggingBuilder.AddConsole();
        });
        services.AddApplicationInsightsTelemetryWorkerService();
        services.ConfigureFunctionsApplicationInsights();

If you've been able to get structured logging with custom dimensions working in .net 8 isolated azure functions, could you perhaps provide some code snippets of your injection and logging code?

[fabiocav]

Guidance and additional information about this problem is available here

Closing this as answered.