question

Pieter-0413 avatar image
0 Votes"
Pieter-0413 asked MayankBargali-MSFT edited

Azure functions intermittent function loading issue

Hi,
we have an Azure function app running two functions in python on a shared Linux app service plan. Both functions run based on a timer trigger. This has been running for more than a year with some minor code updates every now and then. The last three months we did not touch the deployment.

Mostly it runs very smooth however the last few days I noticed intermittent issues of the functions not doing their work. I did not see any errors in the logs. After taking a deeper look I noticed that the functions are not always loaded properly by the jobhost.

Here are two extracts of the traces that show the difference between a correct run and a run with issues.

For example this occurrence went well:
8/9/2021, 7:19:48.546 AM Initializing Warmup Extension.
8/9/2021, 7:19:48.554 AM Initializing Host. OperationId: '6ddd0526-5a0e-4a47-8639-e3d5c13876de'.
8/9/2021, 7:19:48.555 AM Host initialization: ConsecutiveErrors=0, StartupCount=3, OperationId=6ddd0526-5a0e-4a47-8639-e3d5c13876de
8/9/2021, 7:19:48.568 AM Starting JobHost
8/9/2021, 7:19:48.572 AM Starting Host (HostId=qcify, InstanceId=54fe791e-a60d-4071-99a2-18210b681790, Version=3.0.15885.0, ProcessId=48, AppDomainId=1, InDebugMode=True, InDiagnosticMode=False, FunctionsExtensionVersion=~3)
8/9/2021, 7:19:48.575 AM Loading functions metadata
8/9/2021, 7:19:48.576 AM FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:java
8/9/2021, 7:19:48.577 AM FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:node
8/9/2021, 7:19:48.577 AM FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:powershell
8/9/2021, 7:19:48.584 AM 2 functions loaded
8/9/2021, 7:19:48.595 AM Worker process started and initialized.
8/9/2021, 7:19:48.595 AM Generating 2 job function(s)

For example this occurrence went wrong:
8/9/2021, 5:28:54.360 AM Initializing Warmup Extension.
8/9/2021, 5:28:54.369 AM Initializing Host. OperationId: '64f05677-7fd1-499f-afd8-d0e958c7c979'.
8/9/2021, 5:28:54.369 AM Host initialization: ConsecutiveErrors=0, StartupCount=3, OperationId=64f05677-7fd1-499f-afd8-d0e958c7c979
8/9/2021, 5:28:54.379 AM Starting JobHost
8/9/2021, 5:28:54.380 AM Starting Host (HostId=qcify, InstanceId=31e05d77-e41d-41d6-b4a1-2ec833ad11cd, Version=3.0.15885.0, ProcessId=47, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=~3)
8/9/2021, 5:28:54.382 AM Loading functions metadata
8/9/2021, 5:28:54.383 AM FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:java
8/9/2021, 5:28:54.386 AM FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:node
8/9/2021, 5:28:54.388 AM FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:powershell
8/9/2021, 5:28:54.390 AM 0 functions loaded
8/9/2021, 5:28:54.392 AM Generating 0 job function(s)
8/9/2021, 5:28:54.393 AM No job functions found. Try making your job classes and methods public. If you're using binding extensions (e.g. Azure Storage, ServiceBus, Timers, etc.) make sure you've called the registration method for the extension(s) in your startup code (e.g. builder.AddAzureStorage(), builder.AddServiceBus(), builder.AddTimers(), etc.).
8/9/2021, 5:28:54.394 AM "Initializing function HTTP routes No HTTP routes mapped"
8/9/2021, 5:28:54.395 AM Host initialized (13ms)
8/9/2021, 5:28:54.395 AM Host started (14ms)
8/9/2021, 5:28:54.395 AM Job host started
8/9/2021, 5:31:14.721 AM Host lock lease acquired by instance ID '000000000000000000000000160F6A10'.

  • Note that I did not change the deployment between these two runs. Sometimes it works, sometimes it doesn't.

  • One difference I spotted in both logs above is that the problematic execution starts the host with InDebugMode=False. However I have also found correct executions with debug mode set to False so I don't think it is my root cause. I do find it strange that DebugMode=False only shows up in my logs since the last few days. I did not touch that setting, no idea where to manage it and I don't understand why it would not always be the same.

More information on the DebugMode would be appreciated but the big question is why are the functions not always loaded correctly by the jobhost? Any thoughts on what could be causing this are very welcome.

thanks,

Pieter


azure-functions
· 5
5 |1600 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

@Pieter-0413 Looks like function host is unable to start as per the error message in your second log. Can you confirm if there was no restart or run the Diagnose and solve problem
for Availability and performance/function app down and reporting errors to see if there was issue around 8/9/2021, 5:28:54 AM (around 20 min window) for which you have shared the logs.

1 Vote 1 ·
Pieter-0413 avatar image Pieter-0413 MayankBargali-MSFT ·

Hi @MayankBargali-MSFT,
there was no restart that I'm aware off.

The 2 timertrigger functions were deployed in March 2021 and not touched until I noticed this problem. These are the only two functions in the function app, they trigger every 5 minutes. Yesterday I redeployed the functions but the issue has persisted and happened again this morning.

I have pulled the "Diagnose and solve problem" report like you suggested for interval 2021-08-09 05:20 - 2021-08-09 05:45
There are two things that pop up in red:

  • Functions that are not triggering
    As of 2021-08-09 05:45:00, the Function App runtime encountered the below exceptions:
    Exception Type Total Occurrences Exception Message Latest Timestamp
    No job functions found. Try making your job classes and methods 1 No job functions found. Try making your job classes and methods public. If you're using binding extensions (e.g. Azure Storage, ServiceBus, Timers, etc.) make sure you've called the registration method for the extension(s) in your startup code (e.g. builder.AddAzureStorage(), builder.AddServiceBus(), builder.AddTimers(), etc.). 8/9/2021 5:28:54 AM

  • This looks to match up with my earlier finding from the log.

0 Votes 0 ·
  • Function App Settings Check
    Status App Settings Description
    APPLICATIONINSIGHTS_CONNECTION_STRING and APPINSIGHTS_INSTRUMENTATIONKEY both exist We detected both app settings APPLICATIONINSIGHTS_CONNECTION_STRING and APPINSIGHTS_INSTRUMENTATIONKEY are being used with your app. In this scenario the connection string will take precedence and as discussed at APPLICATIONINSIGHTS_CONNECTION_STRING it will send the data to the endpoints from the connection string.
    The SMB share will be mounted on /home/ directory. It will be shared across scale instances and files written will persist across restarts. If this is not the expected behavior for your custom container, please configure WEBSITES_ENABLE_APP_SERVICE_STORAGE to false in app settings.

  • I don't think these are immediately related but listing them for completeness.

0 Votes 0 ·
Show more comments

1 Answer

Pieter-0413 avatar image
0 Votes"
Pieter-0413 answered Pieter-0413 edited

Status update:

  • 9th of August I have redeployed my functions. This did not solve the issue.

  • 10th of August I was still seeing a mix of "0 functions loaded" and "2 functions loaded" depending on the run.

  • 23rd of August the problem looks to have gone away without further changes from my side. Not sure what happened but something looks to have improved in the back end. Microsoft support did offer to investigate so a support ticket was created.

  • 23rd of September Microsoft support confirmed that this was due to a backend issue which has been resolved in the mean time.


5 |1600 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.