High storage costs from an idle application with app insights disabled

[Krucial92]

I've started noticing huge storage costs ($100 per month) from a function apps storage account of mine which is practically dormant. I've actually been battling with this issue for the past 6 weeks, reading every related thread on the internet I could find, however I still can not find the source of what's causing such a large number of operations on the function apps storage account.

What I've learnt so far from my investigation is that function apps have their own internal processes which cause read/write operations on the storage account which is fair, however millions of transactions per week for a dormant application is unfeasible. I've also read that doing zip deployments via my deployment pipeline will perform a lot of these operations on the storage account which too is fair.

I've also found numerous threads/articles which point to application insights as the issue, as it's own internal logging and monitoring is doing a lot in the background. So after learning this I completely removed app insights from the function app (deleted the app insights key app setting, updated host.json, etc), and have implemented my own wrapper directly using the sdk with everything turned off:

appInsights
	.setup(env.APP_INSIGHTS_CONNECTION)
	.setAutoDependencyCorrelation(true)
	.setAutoCollectRequests(false)
	.setAutoCollectPerformance(false, false)
	.setAutoCollectExceptions(false)
	.setAutoCollectDependencies(false)
	.setAutoCollectConsole(false)
	.setUseDiskRetryCaching(false)
	.setSendLiveMetrics(false)
	.setAutoCollectHeartbeat(false)
	.setDistributedTracingMode(appInsights.DistributedTracingModes.AI_AND_W3C);

appInsights.defaultClient.setAutoPopulateAzureProperties(true);
appInsights.start();

Now even after all of this, with my function app only containing simple http triggers which are never invoked, I'm still seeing a high volume of transactions on the storage account around every 1 hour (seems to vary):

So I enabled diagnostic settings for this storage account to output logs into another storage account, and what I can see every time there is a spike in transactions is there is a 150mb~ or so PT1H.json file with 100k lines of logs continually making Create / Close operations, here's the first 10 lines:

{ "time": "2022-06-14T12:41:58.5069032Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Create", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 4, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1b9e-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dc63716e7af","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage","lastModifiedTime":"2022/06/14 05:24:54.9457839","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":208,"responseHeaderSize":64,"responseBodySize":144,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D05069D","smbVolatileHandleID":"0XFFFFFFFF00203E01","smbCreditsConsumed":1,"smbMessageID":"0X11BC","smbCommandMajor":5,"smbCommandMinor":"DirectoryOpen","smbFileId":"0XB5B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5122269Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Close", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 2, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1b9f-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dc63716e7af","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage","lastModifiedTime":"2022/06/14 05:24:54.9457839","metricResponseType":"Success","serverLatencyMs":2,"operationCount":0,"requestHeaderSize":64,"requestBodySize":24,"responseHeaderSize":64,"responseBodySize":112,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D05069D","smbVolatileHandleID":"0XFFFFFFFF00203E01","smbCreditsConsumed":1,"smbMessageID":"0X11BE","smbCommandMajor":6,"smbCommandMinor":"DirectoryClose","smbCommandDetail":"Detail=Client","smbFileId":"0XB5B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5186322Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Create", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 4, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba0-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dd0cb68d8ad","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\context\\context.js","lastModifiedTime":"2022/06/14 06:40:38.7528877","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":208,"responseHeaderSize":64,"responseBodySize":88,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D05069E","smbVolatileHandleID":"0XFFFFFFFF00300601","smbCreditsConsumed":1,"smbMessageID":"0X11BF","smbCommandMajor":5,"smbCommandMinor":"FileOpen","smbFileId":"0X87B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\context\\context.js", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5227806Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Close", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 3, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba1-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dd0cb68d8ad","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\context\\context.js","lastModifiedTime":"2022/06/14 06:40:38.7528877","metricResponseType":"Success","serverLatencyMs":3,"operationCount":0,"requestHeaderSize":64,"requestBodySize":24,"responseHeaderSize":64,"responseBodySize":112,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D05069E","smbVolatileHandleID":"0XFFFFFFFF00300601","smbCreditsConsumed":1,"smbMessageID":"0X11C1","smbCommandMajor":6,"smbCommandMinor":"FileClose","smbCommandDetail":"Detail=Client","smbFileId":"0X87B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\context\\context.js", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5279687Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Create", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 4, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba2-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dc636cffdf4","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\api","lastModifiedTime":"2022/06/14 05:24:54.4810484","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":200,"responseHeaderSize":64,"responseBodySize":144,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D05069F","smbVolatileHandleID":"0XFFFFFFFF00300A01","smbCreditsConsumed":1,"smbMessageID":"0X11C2","smbCommandMajor":5,"smbCommandMinor":"DirectoryOpen","smbFileId":"0XC9B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\api", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5338682Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Close", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 5, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba3-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dc636cffdf4","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\api","lastModifiedTime":"2022/06/14 05:24:54.4810484","metricResponseType":"Success","serverLatencyMs":5,"operationCount":0,"requestHeaderSize":64,"requestBodySize":24,"responseHeaderSize":64,"responseBodySize":112,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D05069F","smbVolatileHandleID":"0XFFFFFFFF00300A01","smbCreditsConsumed":1,"smbMessageID":"0X11C4","smbCommandMajor":6,"smbCommandMinor":"DirectoryClose","smbCommandDetail":"Detail=Client","smbFileId":"0XC9B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\api", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5399815Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Create", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 4, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba4-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dd0cb106556","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage\\utils.js","lastModifiedTime":"2022/06/14 06:40:38.1732182","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":200,"responseHeaderSize":64,"responseBodySize":88,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D0506A0","smbVolatileHandleID":"0XFFFFFFFF00300F01","smbCreditsConsumed":1,"smbMessageID":"0X11C5","smbCommandMajor":5,"smbCommandMinor":"FileOpen","smbFileId":"0XBDB4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage\\utils.js", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5459616Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Close", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 4, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba5-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dd0cb106556","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage\\utils.js","lastModifiedTime":"2022/06/14 06:40:38.1732182","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":24,"responseHeaderSize":64,"responseBodySize":112,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D0506A0","smbVolatileHandleID":"0XFFFFFFFF00300F01","smbCreditsConsumed":1,"smbMessageID":"0X11C7","smbCommandMajor":6,"smbCommandMinor":"FileClose","smbCommandDetail":"Detail=Client","smbFileId":"0XBDB4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src\\baggage\\utils.js", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5520900Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Create", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 4, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba6-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dc636a6d119","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src","lastModifiedTime":"2022/06/14 05:24:54.2112025","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":192,"responseHeaderSize":64,"responseBodySize":144,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D0506A1","smbVolatileHandleID":"0XFFFFFFFF00301D01","smbCreditsConsumed":1,"smbMessageID":"0X11C8","smbCommandMajor":5,"smbCommandMinor":"DirectoryOpen","smbFileId":"0XA1B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-06-14T12:41:58.5564950Z", "resourceId": "/subscriptions/b0a0006f-c9eb-4471-b40e-51b0acbead0b/resourceGroups/Kickstarter-Dev/providers/Microsoft.Storage/storageAccounts/kickstarterfnappdev/fileServices/default", "category": "StorageWrite", "operationName": "Close", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 2, "callerIpAddress": "10.30.5.239", "correlationId": "8f1e1ba7-201d-002c-00ec-7f6e14000000", "identity": {"type":"NTLMv2"}, "location": "Australia Central", "properties": {"accountName":"kickstarterfnappdev","etag":"0x8da4dc636a6d119","serviceType":"file","objectKey":"\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src","lastModifiedTime":"2022/06/14 05:24:54.2112025","metricResponseType":"Success","serverLatencyMs":2,"operationCount":0,"requestHeaderSize":64,"requestBodySize":24,"responseHeaderSize":64,"responseBodySize":112,"smbSessionId":"0X82C1F80280000881","smbTreeConnectID":"0X5","smbPersistentHandleID":"0X18D0506A1","smbVolatileHandleID":"0XFFFFFFFF00301D01","smbCreditsConsumed":1,"smbMessageID":"0X11CA","smbCommandMajor":6,"smbCommandMinor":"DirectoryClose","smbCommandDetail":"Detail=Client","smbFileId":"0XA1B4789800000000","smbStatusCode":"0"}, "uri": "\\\\kickstarterfnappdev.file.core.windows.net\\kickstarter-fnapp-dev-d16afcf4\\site\\wwwroot\\node_modules\\@opentelemetry\\api\\build\\src", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}

From inspecting these logs I see a lot to do with appinsights/opentelemetry. However I have completely disabled app insights in host.json:

"logging": {
	"fileLoggingMode": "never",
	"logLevel": {
		"default": "None"
	},
	"applicationInsights": {
		"samplingSettings": {
			"isEnabled": true,
			"maxTelemetryItemsPerSecond": 5,
			"maxSamplingPercentage": 20
		},
		"enableLiveMetrics": false,
		"enableDependencyTracking": false,
		"enablePerformanceCountersCollection": false
	}
},

I really do not know what to try from here, but I need to get to the source of what's causing such a high volume of transactions and eliminate these storage account costs. From an idle function app on the consumption plan with simple http triggers I do not expect to pay $100 per month just for the storage account, I couldn't imagine the cost going to production like this!

If you have any ideas as to what the issue may be please let me know. Happy to provide more details, or upload my diagnostic logs from this storage account.

[KelvinTegelaar]

Hey Jeremy,

I've been struggling with the same - I've enabled application insights to find what's going on and it's just random creates and closes to PowerShell module files in my case. I suspect you're suffering from the same, but the JS/Node equivalent.

It's been an issue for years, and there are a lot of unresolved issues on this repo referencing it, e.g. https://github.com/Azure/Azure-Functions/issues/1307

I'm afraid there is no incentive for MS to fix this, and don't have a solution for you except a "me too!"

[Krucial92]

Thanks for the insight @KelvinTegelaar and glad to know others are experiencing the same. MS needs to get onto this! I expect to pay for function app usage based on pricing outlined, not ridiculous and untransparent amounts of money on storage related costs due to some obscure "internal processes" which need to run.

Whatever processes that are running are creating millions of transactions, which is incredibly hard to debug and find the source of the issue. This is completely unfeasible, and such a problem that I've considered moving to Lambda functions, however the effort involved to transition is quite significant at this stage. Uhh..

[simonsabin]

Have you looked at https://docs.microsoft.com/en-us/azure/azure-monitor/essentials/resource-logs

"Each PT1H.json blob contains a JSON blob of events that occurred within the hour specified in the blob URL, for example, h=12. During the present hour, events are appended to the PT1H.json file as they occur. The minute value (m=00) is always 00 because resource log events are broken into individual blobs per hour.

Within the PT1H.json file, each event is stored in the following format. It uses a common top-level schema but is unique for each Azure service, as described in Resource logs schema."

[nzthiago]

Hi everyone - the Functions team certainly does not want unnecessary storage file transactions to be the behavior of the platform. There might be different reasons for high number of file storage transactions observed though. Merely accessing files via SMB can show up in logs as file Create operations as the SMB2 CREATE Request packet is sent by either a creation of or access to a file. This could lead us to different investigations for your scenarios like high number of access to referenced node modules, antivirus checks, etc., and subsequently a few ways for us to address these issues.

Therefore, I would please ask you:

• Open a support ticket if this is impacting a production app that needs immediate attention or
• Follow these steps to share your function app name privately here together with the region your app is deployed to for us to investigate
• Standard general purpose Azure Storage accounts are required when using the Azure Storage provider. All other storage account types are not supported. We highly recommend using legacy v1 general purpose storage accounts because the newer v2 storage accounts can be significantly more expensive for Durable Functions workloads. For more information on Azure Storage account types, see the Storage account overview documentation.

[Krucial92]

@simonsabin yes I have looked at the resource logs, as mentioned in the thread I enabled diagnostics on the storage account to output these logs into a separate storage account, and from a dormant application it's still generating 100k lines in each PT1H.json file per hour. What I'm trying to get to the bottom of is what is causing so many of these operations, there's a sample of these logs posted above which looks to have a lot to do with app insights.

Thanks for your response @nzthiago, at this stage I've disabled the function app to prevent this behaviour, and have moved to a new function app with exactly the same configuration (except that it's using v1 storage). There's random spikes, however no-where as near as bad the function app which I disabled. I'll keep my eye on this, and if it starts again I'll open a support ticket. In the mean time it would be great to monitor if others are having similar issues, and if so, recognize that this is a significant issue which needs investigation.

[Ved2806]

Hi @Krucial92 Is this issue resolved for you or you need some help from us? Please let us know.

[msftbot[bot]]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

[Krucial92]

So about a week ago I decided to turn on one of my problematic function apps and over the course of the following 3 days it decided to create about 30 million operations on the related storage account (simple http triggers in the function app and received no traffic, nor did any deployments).

This obviously shot my billing up to an unreasonable amount so I began investigating the issue again. The first thing I did was delete the AppInsights instance attached to this function app, which proved that AppInsights is not the source of this issue (at least for me).

I then raised a support ticket and received a response noting that the app accessed the node_modules files via SMB and according to the documentation an SMB2 CREATE request packet is sent by a client to request either creation of or access to a file, similarly the CLOSE (client) logs are used by the client to close an instance of a file that was opened previousy with a successful SMB2 CREATE request. This makes sense but was somewhat unhelpful in explaining the cause of such a high volume of transactions on the storage account.

So after staring at these storage account log files produced by enabling the diagnostic settings on the function apps storage account, and reading every thread I could find related to this issue, I thought about changing my deployment method in the Azure Devops pipeline from Zip Deploy to Zip Deploy with Run From Package. Boom - I think this may have been the source of the issue, at least in my case.

I've now been strictly monitoring logs across 4 function apps (all are running from zip package) over the course of the last 2-3 days and finally the number of transactions on all of these function apps storage accounts have sinked to a super low level, consistently, unless I start calling http triggers or doing deployments, then I'll see a spike in operations which is expected, however it will return to normal.

Now after inspecting the same logs via the diagnostic settings I have noticed a MASSIVE reduction in logs generated, and they have also changed from accessing a ton of node_module files, and instead all look like this:

{ "time": "2022-07-25T02:10:46.7440955Z", "resourceId": "/subscriptions/sub-id/resourceGroups/MyApp-Prod/providers/Microsoft.Storage/storageAccounts/myappfnappprod/fileServices/default", "category": "StorageWrite", "operationName": "Create", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 29, "callerIpAddress": "10.218.130.15", "correlationId": "21eda96b-401d-004f-00cb-9fce53000000", "identity": {"type":"NTLMv2"}, "location": "East US", "properties": {"accountName":"myappfnappprod","etag":"0x8da6c5dc3cef49d","serviceType":"file","objectKey":"\\\\myappfnappprod.file.core.windows.net\\myapp-fnapp-prod-39a09e24\\data\\SitePackages\\20220723034516.zip","lastModifiedTime":"2022/07/23 03:45:19.9224989","metricResponseType":"Success","serverLatencyMs":5,"operationCount":0,"requestHeaderSize":64,"requestBodySize":284,"responseHeaderSize":64,"responseBodySize":308,"smbSessionId":"0X84F058558C000505","smbTreeConnectID":"0X5","smbPersistentHandleID":"0XB7620949","smbVolatileHandleID":"0XFFFFFFFF000000FD","smbCreditsConsumed":1,"smbMessageID":"0X1512","smbCommandMajor":5,"smbCommandMinor":"FileOpen","smbFileId":"0XA4002C2000000000","smbStatusCode":"0"}, "uri": "\\\\myappfnappprod.file.core.windows.net\\myapp-fnapp-prod-39a09e24\\data\\SitePackages\\20220723034516.zip", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}
{ "time": "2022-07-25T02:10:57.4190319Z", "resourceId": "/subscriptions/sub-id/resourceGroups/MyApp-Prod/providers/Microsoft.Storage/storageAccounts/myappfnappprod/fileServices/default", "category": "StorageWrite", "operationName": "Close", "operationVersion": "0x311", "schemaVersion": "1.0", "statusCode": 0, "durationMs": 7, "callerIpAddress": "10.218.130.15", "correlationId": "21eda96c-401d-004f-00cb-9fce53000000", "identity": {"type":"NTLMv2"}, "location": "East US", "properties": {"accountName":"myappfnappprod","etag":"0x8da6c5dca43255d","serviceType":"file","objectKey":"\\\\myappfnappprod.file.core.windows.net\\myapp-fnapp-prod-39a09e24\\data\\SitePackages\\packagename.txt","lastModifiedTime":"2022/07/23 03:45:30.7502941","metricResponseType":"Success","serverLatencyMs":4,"operationCount":0,"requestHeaderSize":64,"requestBodySize":24,"responseHeaderSize":64,"responseBodySize":112,"smbSessionId":"0X84F058558C000505","smbTreeConnectID":"0X5","smbPersistentHandleID":"0XB7620948","smbVolatileHandleID":"0XFFFFFFFF000000F9","smbCreditsConsumed":1,"smbMessageID":"0X1513","smbCommandMajor":6,"smbCommandMinor":"FileClose","smbCommandDetail":"Detail=Client","smbFileId":"0X9C802C2000000000","smbStatusCode":"0"}, "uri": "\\\\myappfnappprod.file.core.windows.net\\myapp-fnapp-prod-39a09e24\\data\\SitePackages\\packagename.txt", "protocol": "SMB", "resourceType": "Microsoft.Storage/storageAccounts/fileServices"}

The difference here being that the objectKey is now data\\SitePackages\\20220723034516.zip as opposed to some random node_modules file, and there is not 1000x more transactions, this is also not happening randomly as it was before.

I don't know how all of this works under the hood, but I'm assuming prior an HTTP request was made to my function and that would access a ton of node_modules files and whatever else, and for every one of the files accessed it would write a log? And now with Run From Package it just accesses that zip. Perhaps I'm right/wrong, someone feel free to explain?

Now the last thing I have noticed is that if I start making a bunch of http requests to different endpoints on my function app, every 50 or so requests will create about 500 create operations, 500 reads etc on the storage account (sometimes around double) - does this sound reasonable?

Also another question I have is, is generating this number of logs really needed for the function app? What are these logs used for? If this is used to track function app usage and billing I feel that these costs should be abstracted away from the user as they are irrelevant to the function app (perhaps I'm wrong here, I'm just not sure what they're used for). I almost wish we could turn these off if they are unnecessary as it's these CREATE operations on the storage account which seem to blow out costs, and become more expensive than running the function app itself.

Anyways that's my update, at least in my case this seems to be the source of the issue that I was encountering and I'd be interested to hear if this solves the same issue for anyone else (assuming if you're doing a ZIP deploy it would introduce the same issue regardless of language used).

cc @KelvinTegelaar @simonsabin @nzthiago @Ved2806

[nzthiago]

@Krucial92 thank you for the extra information, would love to investigate further. Can you please share the support number that you had opened, and also share the execution time, execution Id value, and Region for that app following these instructions?

[KelvinTegelaar]

To follow up and keep @nzthiago updated too; migrating to v1 storage has helped the cost down for my queue writes and blob writes. I associated this with cost eith the issue getting fixed by using v1.

That is not the case. Unfortunately my File writes are still very high, so we're experiencing the same issue on v1 storage. (Sorry I didnt reply earlier Thiago!).

My function is a PowerShell function, and the SMB CREATE and SMB closes I see are all related to loading PowerShell module files, so it seems this is a cross platform issue.

[KelvinTegelaar]

I've been troubleshooting offline with @nzthiago. Adding WEBSITE_RUN_FROM_PACKAGE = 1 has decreased the writes extremely. Everything looks normal now. Included screenshot for illustration; pre-09:15 was without WEBSITE_RUN_FROM_PACKAGE = 1, everything POST 09:15 is WEBSITE_RUN_FROM_PACKAGE = 1

[msftbot[bot]]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.