[BUG] Extension suddenly logging unwanted information messages into log stream of Functions app

[jsquire]

Issue Transfer

This issue has been transferred from the Azure SDK for .NET repository, #33008.

Please be aware that @TheCakeMonster is the author of the original issue and include them for any questions or replies.

Details

The last deployment we did was 27 days ago. These log entries were not present at that time; they only started appearing in the last 10-14 days.

Describe the bug

We have an Azure functions app (.NET 6, running in the original in-process deployment model on functions V4) that has been in production for about 18 months. Suddenly, in the last 10 days, we have started getting an overload of unwanted logging of messages at level Information, which appear to be from Azure.Storage.Blobs and/or Azure.Storage.Queues.

The default log level specified in host.json is Warning. host.json has not changed for about 6 weeks.

These new log entries appear to have been triggered by a change in Azure - a change to the platform. We haven't changed anything in our app for over a month, but suddenly these logs have started appearing in the log stream. These could dramatically increase our App Insights telemetry costs - but I haven't found time to check yet. There is a lot of information in the logs, and we don't want any of it, so my hope is that we are not suddenly having to pay for it because of a change to the behaviour of Azure's runtime.

Whether it is hitting App Insights or not, the effect on the log stream is fairly dramatic - in a bad way. It is now very difficult - almost impossible - to find the useful log entries from our app (which we record at level Information) in the log stream because of all of the noise from the infrastructure.

I think there might be a bug in the way entries are being filtered, or a change in behaviour in the way the log stream works, so that it no longer uses host.json settings to filter the log stream before display.

What follows is a small example of the logs we are seeing. I have redacted the details of a number of the log entry values, as I don't want to expose anything sensitive. My redactions are probably excessive, but better I redact too much than too little. Hopefully, the format of the message rather than the content will help you understand what these are, and help you find why they have started appearing in our carefully filtered log stream in the last 10 days.

2022-12-12T15:35:23Z   [Information]   Request <redacted> HEAD https://storageaccount<redacted>.blob.core.windows.net/azure-webjobs-hosts/locks/<redacted>/host
x-ms-version:2021-08-06
Accept:application/xml
x-ms-client-request-id:<redacted>
x-ms-return-client-request-id:true
User-Agent:azsdk-net-Storage.Blobs/12.13.0,(.NET 6.0.11; Microsoft Windows 10.0.14393)
x-ms-date:Mon, 12 Dec 2022 15:35:22 GMT
Authorization:REDACTED
client assembly: Azure.Storage.Blobs
2022-12-12T15:35:23Z   [Information]   Response <redacted> 200 OK (00.0s)
Accept-Ranges:bytes
ETag:<redacted>
Server:Windows-Azure-Blob/1.0,Microsoft-HTTPAPI/2.0
x-ms-request-id:<redacted>
x-ms-client-request-id:<redacted>
x-ms-version:2021-08-06
x-ms-meta-FunctionInstance:REDACTED
x-ms-creation-time:Fri, 22 Oct 2021 13:03:11 GMT
x-ms-lease-status:locked
x-ms-lease-state:leased
x-ms-lease-duration:fixed
x-ms-blob-type:BlockBlob
x-ms-server-encrypted:true
Date:Mon, 12 Dec 2022 15:35:22 GMT
Content-Length:0
Content-Type:application/octet-stream
Content-MD5:<redacted>
Last-Modified:Mon, 12 Dec 2022 02:57:45 GMT

I think this is in a related area to Azure/azure-functions-dotnet-worker#796 and Azure/azure-sdk-for-net#31967, which are about whether these are really Informational. I don't think these log entries are information - this is debugging data from underlying infrastructure in which we are not interested, and it is not really appropriate to put them at a level of Information. However, that's a separate issue. I have chosen to report this as there has been a change in behaviour in the last 10 days or so.

Expected behavior

Logging should not increase significantly because of deployments to the underlying cloud platform.

These log entries did not appear a few weeks ago, so they should not be there now - but suddenly they are.

Actual behavior

A significant increase in the number of entries in the log stream, making it very hard to find what we want in amongst the noise generated by the underlying runtime/platform.

Reproduction Steps

I am guessing this affects many Functions apps. I haven't got time to create a new one at the moment, but my guess is that these log entries will appear for any .NET functions app targeting .NET 6 using the in-proc model and using blob storage in any way. It may also affect lots of other deployment models, I'm not sure.

Environment

.NET 6.0, Azure Functions V4, older in proc deployment model.

3 of our functions have Http triggers, one has an Azure Storage Queue trigger. The functions using Http triggers seem to have been affected, but the one with storage queues might have as well. I can't quite decipher the logs to work that out at the moment because they are so noisy.

[jorge-datactika]

It just started to happen to me... Haven't made any releases in months! Please help!

It looks like these logs are just showing in the LogStream but not in Application Insights

[RetiredDotaPlayer]

Same here... Have tried making these log settings in host.json, which is not working. The information level flood still exists, making the log stream unreadable.

      "Host.Results": "Warning",
      "Azure.Core": "Warning",
      "Azure.Storage.Blobs": "Warning",

[DomPurnell]

yes - this is causing me pain too .net 6 v4.

[d4046949]

Yep - causing issues here too! Making the logs so noisy that we can't actually work with it. Any work around? I tried changing the log settings like @RetiredDotaPlayer mentions and again, no luck either!

[mincheHuang]

I occurred the same issue with blob service when I included "Microsoft.Azure.WebJobs.Extensions.Storage" or Microsoft.Azure.WebJobs.Extensions.Storage.Blobs version "5.0.0" / "5.0.1" , but I found when I used and downgraded "Microsoft.Azure.WebJobs.Extensions.Storage" to version "4.0.4", it won't occur those annoying logs repeatedly again.

[bw-adriangould]

Hi - We have the same issue. Very noisy logging to the Log Stream in Azure portal for all of our Azure function V4 apps.
The log stream is so chatty and noisy, it's almost impossible to monitor anything useful, and yet nothing has changed our end.
Please advise.

[SomaAmbati]

yes, we too have same issue.

[sdean3842]

I came across this issue in the last few days whilst trying to lock down Azure Function v4 (isolated mode) chattiness ahead of a new client project, prompted by having previously witnessed AI cost horror. While it doesn't affect us directly at present, others might appreciate a response from Microsoft Billing on any plan to compensate for excess AI telemetry ingestion.

[thomasf1234]

This has significantly impacted our team's ability to diagnose issues. Is there any workaround available? After trying to use it for several weeks, so many lines are written that we can't correlate what we're seeing in real time, making this too difficult to use. We have gotten used to this feature being simple and available as this feature has been priceless to us over the last year (for instant feedback on functions), but we are struggling with demand now in this vital part of monitoring.

[danielvaneck]

We are also facing this issue with .net 7 and Azure Fuctions v4. I can see the AI logging has increased substantially and this is contributing to a much higher bill for ingestion.

I have tried the suggested log level fixes in the host.json file, however these are not being respected by the logging for blob storage and I can still see the flood of logs. Is there any ETA on a fix for this?

[joachimdalen]

We experienced the same issue. In addition to logging to Application Insights our functions are configured with Serilog to send to different sources. By setting the following configuration we were able to filter these out

Log.Logger = new LoggerConfiguration()
.MinimumLevel.Information()
.MinimumLevel.Override("Azure", LogEventLevel.Warning)
.CreateLogger();

[d4046949]

Does the above work with Azure Functions? I don't use Serilog and hoped for a solution that would involve configuration changes in the Host.json