Javascript Azure Timer function restarts repeatedly, Exceeded language worker restart retry count for runtime:node. Shutting down and proactively recycling the Functions Host to recover

Question

I am attempting to deploy a node.js timer function to Azure. Locally the function executes fine using func host start.

In Azure, however, the function repeatedly invokes but never executes the body of the function. The Function App I am deploying to is on a Windows based consumption plan due to current trial subscription whilst I wait for Startup program approval, and lack of resource availablility in the US for premium plans.

In Application Insights I see an endless repeat of:

FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:java
FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:powershell
Initializing Warmup Extension.
Initializing Host. OperationId: 'e463776b-1975-44ca-af1d-0e1a1281f26b'.
ApplicationInsightsLoggerOptions { "SamplingSettings": { "EvaluationInterval": "00:00:15", "InitialSamplingPercentage": 100.0, "MaxSamplingPercentage": 100.0, "MaxTelemetryItemsPerSecond": 20.0, "MinSamplingPercentage": 0.1, "MovingAverageRatio": 0.25, "SamplingPercentageDecreaseTimeout": "00:02:00", "SamplingPercentageIncreaseTimeout": "00:15:00" }, "SamplingExcludedTypes": "Request", "SamplingIncludedTypes": null, "SnapshotConfiguration": null, "EnablePerformanceCountersCollection": true, "HttpAutoCollectionOptions": { "EnableHttpTriggerExtendedInfoCollection": true, "EnableW3CDistributedTracing": true, "EnableResponseHeaderInjection": true }, "LiveMetricsInitializationDelay": "00:00:15", "EnableLiveMetrics": true, "EnableDependencyTracking": true, "DependencyTrackingOptions": null }
LoggerFilterOptions { "MinLevel": "None", "Rules": [ { "ProviderName": null, "CategoryName": null, "LogLevel": null, "Filter": "<AddFilter>b__0" }, { "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider", "CategoryName": null, "LogLevel": "None", "Filter": null }, { "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider", "CategoryName": null, "LogLevel": null, "Filter": "<AddFilter>b__0" }, { "ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider", "CategoryName": null, "LogLevel": "Trace", "Filter": null } ] }
ConcurrencyOptions { "DynamicConcurrencyEnabled": false, "MaximumFunctionConcurrency": 500, "CPUThreshold": 0.8, "SnapshotPersistenceEnabled": true }
SingletonOptions { "LockPeriod": "00:00:15", "ListenerLockPeriod": "00:01:00", "LockAcquisitionTimeout": "10675199.02:48:05.4775807", "LockAcquisitionPollingInterval": "00:00:05", "ListenerLockRecoveryPollingInterval": "00:01:00" }
FunctionResultAggregatorOptions { "BatchSize": 1000, "FlushTimeout": "00:00:30", "IsEnabled": true }
Starting JobHost
Starting Host (HostId=<...>, InstanceId=ad2bab32-3a80-461d-a6c4-fe0fe03bd761, Version=4.1.3.17473, ProcessId=5408, AppDomainId=1, InDebugMode=True, InDiagnosticMode=False, FunctionsExtensionVersion=~4)
Loading functions metadata
1 functions loaded
Generating 1 job function(s)
Found the following functions: Host.Functions.TimerTrigger2
Initializing function HTTP routes No HTTP routes mapped
Host initialized (89ms)
HttpOptions { "DynamicThrottlesEnabled": true, "EnableChunkedRequestBinding": false, "MaxConcurrentRequests": 100, "MaxOutstandingRequests": 200, "RoutePrefix": "api" }
The next 5 occurrences of the 'TimerTrigger2' schedule (Cron: '0 0,5,10,15,20,25,30,35,40,45,50,55 * * * *') will be: 04/06/2022 04:50:00Z 04/06/2022 04:55:00Z 04/06/2022 05:00:00Z 04/06/2022 05:05:00Z 04/06/2022 05:10:00Z
Host started (618ms)
Job host started
Executing 'Functions.TimerTrigger2' (Reason='Timer fired at 2022-04-06T04:47:23.6840023+00:00', Id=266ce824-24b4-4e9d-99dd-bbd501ec10a8)
Trigger Details: UnscheduledInvocationReason: IsPastDue, OriginalSchedule: 2022-04-06T03:15:00.0000000+00:00
Host Status: { "id": "<...>", "state": "Running", "version": "4.1.3.17473", "versionDetails": "4.1.3+3ed9ce8ebeef5b156badaf203a016a56e819a852", "platformVersion": "97.0.10.675", "instanceId": "67e6291f7d1d1b8a0c5e6e152950302f66ae43457d3d8d27b631859a25560b00", "computerName": "10-30-1-65", "processUptime": 3614, "functionAppContentEditingState": "Unknown", "extensionBundle": { "id": "Microsoft.Azure.Functions.ExtensionBundle", "version": "2.9.1" } }
Worker process started and initialized.
<console.log statements from import section of function script, *none* from body of exported async function>
Worker process started and initialized.
<console.log statements from import section of function script, *none* from body of exported async function>
...
Host lock lease acquired by instance ID '67e6291f7d1d1b8a0c5e6e152950302f'.
Exceeded language worker restart retry count for runtime:node. Shutting down and proactively recycling the Functions Host to recover
Stopping JobHost
Stopping the listener 'Microsoft.Azure.WebJobs.Host.Listeners.SingletonListener' for function 'TimerTrigger2'
Stopped the listener 'Microsoft.Azure.WebJobs.Host.Listeners.SingletonListener' for function 'TimerTrigger2'
Job host stopped
<repeat>

My host.json looks like

{
  "version": "2.0",
  "logging": {
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      }
    }
  },
  "extensionBundle": {
    "id": "Microsoft.Azure.Functions.ExtensionBundle",
    "version": "[2.*, 3.0.0)"
  },
}

and my function.json

{
  "bindings": [
    {
      "name": "myTimer",
      "type": "timerTrigger",
      "direction": "in",
      "schedule": "0 */5 * * * *",
      "runOnStartup": false
    }
  ],
  "scriptFile": "../dist/func.js"
}

I checked that the AzureWebJobsStorage is set, and I see that in the associated storage account locks are being created and leased. I also checked that the necessary app settings that my code is expecting are defined in the Function App configuration, and that they are being resolved successfully in Kudu.

I see unresolved complaints of similar behavior in forums such as https://github.com/MicrosoftDocs/azure-docs/issues/66877. This thread explicitly mentions the use of Postgres, which I am also using; I am unsure if this may be related, however I see no error output of any description to have any understanding of what may be happening.

I've spent 6 hours on this and a couple of those on chat with Azure support and they were unable help, requesting I post here instead.

UPDATE:

Adding AzureFunctionsJobHost__logging__logLevel__Default with a value of Trace to the App settings resulted in the cause of the failure to be surfaced.

timestamp [UTC]
2022-04-06T05:35:48.931Z
message
Handling WorkerErrorEvent for runtime:node, workerId:node. Failed with: Microsoft.Azure.WebJobs.Script.Workers.WorkerProcessExitException: node exited with code 1
LanguageWorkerConsoleLog[error] Worker a283db50-634c-4f9d-81eb-de511f8922d5 uncaught exception (learn more: https://go.microsoft.com/fwlink/?linkid=2097909 ): Error: Query engine library for current platform "windows" could not be found...

This WAS an issue with the deployed bundle, however, looking at the trace context, it was logged as a Debug trace, despite being an error, and therefore wasn't surfaced by default in any of the Azure function monitoring/app insights!

{"prop__workerId":"node","prop__runtime":"node","LogLevel":"Debug","HostInstanceId":"a3865510-fad3-4703-87bd-4cb25b334c58","Category":"Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher","prop__exception":"Microsoft.Azure.WebJobs.Script.Workers.WorkerProcessExitException: node exited with code 1\n LanguageWorkerConsoleLog[error] Worker a283db50-634c-4f9d-81eb-de511f8922d5 uncaught exception (learn more: https://go.microsoft.com/fwlink/?linkid=2097909 ): ...","ProcessId":"2708","prop__{OriginalFormat}":"Handling WorkerErrorEvent for runtime:{runtime}, workerId:{workerId}. Failed with: {exception}"}

If this had been correctly surfaced, it would have saved me several hours of frustration.