Azure / azure-functions-host

The host/runtime that powers Azure Functions
https://functions.azure.com
MIT License
1.94k stars 441 forks source link

"Initializing worker process failed" in Azure Functions Core Tools #8504

Closed naokoshiiba closed 3 months ago

naokoshiiba commented 3 years ago

I have been having this error after runnning "func start" locally:

[2021-08-12T01:54:19.789Z] Initializing worker process failed
[2021-08-12T01:54:19.790Z] The operation has timed out.
[2021-08-12T01:54:19.816Z] Failed to start a new language worker for runtime: node.
[2021-08-12T01:54:19.817Z] System.Private.CoreLib: The operation has timed out.
[2021-08-12T01:54:50.005Z] Initializing worker process failed
[2021-08-12T01:54:50.012Z] The operation has timed out.
Unhandled exception. System.TimeoutException: The operation has timed out.
   at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.StartWorkerProcessAsync() in D:\a\1\s\src\WebJobs.Script.Grpc\Channel\GrpcWorkerChannel.cs:line 146
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.InitializeJobhostLanguageWorkerChannelAsync(Int32 attemptCount) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 116
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.RestartWorkerChannel(String runtime) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 414
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.RestartWorkerChannel(String runtime) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 426
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.DisposeAndRestartWorkerChannel(String runtime, String workerId, Exception workerException) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 386
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.WorkerError(WorkerErrorEvent workerError) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 336
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__139_1(Object state)
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

I have updated Functions Core tools from v2 to v3, but the error continues. It is the simple function that was made by "func int" and "func new" (node, typescript, HttpTrigger).

My Function Tools Version is :

Azure Functions Core Tools
Core Tools Version:       3.0.3477 Commit hash: 5fbb9a76fc00e4168f2cc90d6ff0afe5373afc6d  (64-bit)
Function Runtime Version: 3.0.15584.0

My node version is :

node version
{ npm: '6.4.1',
  ares: '1.14.0',
  cldr: '33.1',
  http_parser: '2.8.0',
  icu: '62.1',
  modules: '64',
  napi: '3',
  nghttp2: '1.33.0',
  node: '10.10.0',
  openssl: '1.1.0i',
  tz: '2018e',
  unicode: '11.0',
  uv: '1.23.0',
  v8: '6.8.275.30-node.24',
  zlib: '1.2.11' }

I know the node version is old, but on the other environment that has same versions of node and functions core tools it works with no error.

I have tried to run with "npm init" and "npm start" instead of "func start". It has the same result, "Initializing worker process failed".

Could you help me any information about the error, please ?

boylec commented 2 years ago

+1

Build succeeded. 0 Warning(s) 0 Error(s)

Time Elapsed 00:00:04.50

              %%%%%%
             %%%%%%
        @   %%%%%%    @
      @@   %%%%%%      @@
   @@@    %%%%%%%%%%%    @@@
 @@      %%%%%%%%%%        @@
   @@         %%%%       @@
     @@      %%%       @@
       @@    %%      @@
            %%
            %

Azure Functions Core Tools Core Tools Version: 4.0.3971 Commit hash: d0775d487c93ebd49e9c1166d5c3c01f3c76eaaf (64-bit) Function Runtime Version: 4.0.1.16815

[2021-12-01T19:35:59.059Z] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: 'd322eb64-f2de-458c-a6aa-51a53c5c6d4f' [2021-12-01T19:35:59.065Z] Reading host configuration file '//////.Web/../...///host.json' [2021-12-01T19:35:59.066Z] Host configuration file read: [2021-12-01T19:35:59.066Z] { [2021-12-01T19:35:59.066Z] "version": "2.0", [2021-12-01T19:35:59.066Z] "logging": { [2021-12-01T19:35:59.066Z] "applicationInsights": { [2021-12-01T19:35:59.067Z] "samplingSettings": { [2021-12-01T19:35:59.067Z] "isEnabled": true, [2021-12-01T19:35:59.067Z] "excludedTypes": "Request" [2021-12-01T19:35:59.067Z] } [2021-12-01T19:35:59.067Z] } [2021-12-01T19:35:59.067Z] } [2021-12-01T19:35:59.067Z] } [2021-12-01T19:35:59.085Z] Loading functions metadata [2021-12-01T19:35:59.104Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:python [2021-12-01T19:35:59.106Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:java [2021-12-01T19:35:59.108Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:powershell [2021-12-01T19:35:59.108Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:node [2021-12-01T19:35:59.109Z] Reading functions metadata [2021-12-01T19:35:59.113Z] 0 functions found [2021-12-01T19:35:59.121Z] 0 functions loaded [2021-12-01T19:35:59.124Z] Loading extensions from //////.Web/../...//. BundleConfigured: False, PrecompiledFunctionApp: False, LegacyBundle: False [2021-12-01T19:35:59.124Z] Script Startup resetting load context with base path: '//////.Web/../...///.azurefunctions'. [2021-12-01T19:35:59.128Z] Loading startup extension 'Startup' [2021-12-01T19:35:59.177Z] Loaded extension 'Startup' (1.0.0.0) [2021-12-01T19:35:59.203Z] Reading host configuration file '//////.Web/../...///host.json' [2021-12-01T19:35:59.203Z] Host configuration file read: [2021-12-01T19:35:59.203Z] { [2021-12-01T19:35:59.203Z] "version": "2.0", [2021-12-01T19:35:59.203Z] "logging": { [2021-12-01T19:35:59.203Z] "applicationInsights": { [2021-12-01T19:35:59.203Z] "samplingSettings": { [2021-12-01T19:35:59.203Z] "isEnabled": true, [2021-12-01T19:35:59.203Z] "excludedTypes": "Request" [2021-12-01T19:35:59.203Z] } [2021-12-01T19:35:59.203Z] } [2021-12-01T19:35:59.203Z] } [2021-12-01T19:35:59.203Z] } [2021-12-01T19:35:59.536Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:python [2021-12-01T19:35:59.536Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:java [2021-12-01T19:35:59.536Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:powershell [2021-12-01T19:35:59.537Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:node [2021-12-01T19:35:59.679Z] Initializing Warmup Extension. [2021-12-01T19:35:59.740Z] Initializing Host. OperationId: 'd322eb64-f2de-458c-a6aa-51a53c5c6d4f'. [2021-12-01T19:35:59.750Z] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=d322eb64-f2de-458c-a6aa-51a53c5c6d4f [2021-12-01T19:35:59.782Z] Loading functions metadata [2021-12-01T19:35:59.782Z] Reading functions metadata [2021-12-01T19:35:59.783Z] 0 functions found [2021-12-01T19:35:59.855Z] 5 functions loaded [2021-12-01T19:35:59.864Z] LoggerFilterOptions [2021-12-01T19:35:59.864Z] { [2021-12-01T19:35:59.864Z] "MinLevel": "None", [2021-12-01T19:35:59.864Z] "Rules": [ [2021-12-01T19:35:59.864Z] { [2021-12-01T19:35:59.864Z] "ProviderName": null, [2021-12-01T19:35:59.864Z] "CategoryName": null, [2021-12-01T19:35:59.864Z] "LogLevel": null, [2021-12-01T19:35:59.864Z] "Filter": "b0" [2021-12-01T19:35:59.864Z] }, [2021-12-01T19:35:59.864Z] { [2021-12-01T19:35:59.864Z] "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider", [2021-12-01T19:35:59.864Z] "CategoryName": null, [2021-12-01T19:35:59.864Z] "LogLevel": "None", [2021-12-01T19:35:59.864Z] "Filter": null [2021-12-01T19:35:59.864Z] }, [2021-12-01T19:35:59.864Z] { [2021-12-01T19:35:59.864Z] "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider", [2021-12-01T19:35:59.864Z] "CategoryName": null, [2021-12-01T19:35:59.864Z] "LogLevel": null, [2021-12-01T19:35:59.864Z] "Filter": "b0" [2021-12-01T19:35:59.864Z] }, [2021-12-01T19:35:59.864Z] { [2021-12-01T19:35:59.864Z] "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider", [2021-12-01T19:35:59.864Z] "CategoryName": null, [2021-12-01T19:35:59.864Z] "LogLevel": null, [2021-12-01T19:35:59.864Z] "Filter": "b0" [2021-12-01T19:35:59.864Z] } [2021-12-01T19:35:59.864Z] ] [2021-12-01T19:35:59.864Z] } [2021-12-01T19:35:59.865Z] LoggerFilterOptions [2021-12-01T19:35:59.865Z] { [2021-12-01T19:35:59.865Z] "MinLevel": "None", [2021-12-01T19:35:59.865Z] "Rules": [ [2021-12-01T19:35:59.865Z] { [2021-12-01T19:35:59.865Z] "ProviderName": null, [2021-12-01T19:35:59.865Z] "CategoryName": null, [2021-12-01T19:35:59.865Z] "LogLevel": null, [2021-12-01T19:35:59.865Z] "Filter": "b0" [2021-12-01T19:35:59.865Z] }, [2021-12-01T19:35:59.865Z] { [2021-12-01T19:35:59.865Z] "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider", [2021-12-01T19:35:59.865Z] "CategoryName": null, [2021-12-01T19:35:59.865Z] "LogLevel": "None", [2021-12-01T19:35:59.865Z] "Filter": null [2021-12-01T19:35:59.865Z] }, [2021-12-01T19:35:59.865Z] { [2021-12-01T19:35:59.865Z] "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider", [2021-12-01T19:35:59.865Z] "CategoryName": null, [2021-12-01T19:35:59.865Z] "LogLevel": null, [2021-12-01T19:35:59.865Z] "Filter": "b0" [2021-12-01T19:35:59.865Z] }, [2021-12-01T19:35:59.865Z] { [2021-12-01T19:35:59.865Z] "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider", [2021-12-01T19:35:59.865Z] "CategoryName": null, [2021-12-01T19:35:59.865Z] "LogLevel": null, [2021-12-01T19:35:59.865Z] "Filter": "b0" [2021-12-01T19:35:59.865Z] } [2021-12-01T19:35:59.865Z] ] [2021-12-01T19:35:59.865Z] } [2021-12-01T19:35:59.865Z] ConcurrencyOptions [2021-12-01T19:35:59.865Z] { [2021-12-01T19:35:59.865Z] "DynamicConcurrencyEnabled": false, [2021-12-01T19:35:59.865Z] "MaximumFunctionConcurrency": 500, [2021-12-01T19:35:59.865Z] "CPUThreshold": 0.8, [2021-12-01T19:35:59.865Z] "SnapshotPersistenceEnabled": true [2021-12-01T19:35:59.865Z] } [2021-12-01T19:35:59.865Z] FunctionResultAggregatorOptions [2021-12-01T19:35:59.866Z] { [2021-12-01T19:35:59.866Z] "BatchSize": 1000, [2021-12-01T19:35:59.866Z] "FlushTimeout": "00:00:30", [2021-12-01T19:35:59.866Z] "IsEnabled": true [2021-12-01T19:35:59.866Z] } [2021-12-01T19:35:59.866Z] SingletonOptions [2021-12-01T19:35:59.866Z] { [2021-12-01T19:35:59.866Z] "LockPeriod": "00:00:15", [2021-12-01T19:35:59.866Z] "ListenerLockPeriod": "00:00:15", [2021-12-01T19:35:59.866Z] "LockAcquisitionTimeout": "10675199.02:48:05.4775807", [2021-12-01T19:35:59.866Z] "LockAcquisitionPollingInterval": "00:00:05", [2021-12-01T19:35:59.866Z] "ListenerLockRecoveryPollingInterval": "00:01:00" [2021-12-01T19:35:59.866Z] } [2021-12-01T19:35:59.867Z] Starting JobHost [2021-12-01T19:35:59.872Z] Starting Host (HostId=zerocool-1607526613, InstanceId=f71b33d5-ea7d-4ed1-8317-beecaa3e0c51, Version=4.0.1.16815, ProcessId=3249, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null)) [2021-12-01T19:35:59.886Z] Loading functions metadata [2021-12-01T19:35:59.886Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:python [2021-12-01T19:35:59.887Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:java [2021-12-01T19:35:59.887Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:powershell [2021-12-01T19:35:59.887Z] FUNCTIONS_WORKER_RUNTIME set to dotnet-isolated. Skipping WorkerConfig for language:node [2021-12-01T19:35:59.888Z] Reading functions metadata [2021-12-01T19:35:59.889Z] 0 functions found [2021-12-01T19:35:59.898Z] 5 functions loaded [2021-12-01T19:35:59.939Z] Generating 5 job function(s) [2021-12-01T19:36:00.000Z] Found the following functions: [2021-12-01T19:36:00.000Z] Host.Functions. [2021-12-01T19:36:00.000Z] Host.Functions. [2021-12-01T19:36:00.000Z] Host.Functions. [2021-12-01T19:36:00.000Z] Host.Functions. [2021-12-01T19:36:00.000Z] Host.Functions. [2021-12-01T19:36:00.000Z] [2021-12-01T19:36:00.011Z] HttpOptions [2021-12-01T19:36:00.011Z] { [2021-12-01T19:36:00.011Z] "DynamicThrottlesEnabled": false, [2021-12-01T19:36:00.011Z] "EnableChunkedRequestBinding": false, [2021-12-01T19:36:00.011Z] "MaxConcurrentRequests": -1, [2021-12-01T19:36:00.011Z] "MaxOutstandingRequests": -1, [2021-12-01T19:36:00.011Z] "RoutePrefix": "api" [2021-12-01T19:36:00.011Z] } [2021-12-01T19:36:00.013Z] Initializing function HTTP routes [2021-12-01T19:36:00.013Z] Mapped function route to [2021-12-01T19:36:00.013Z] Mapped function route to [2021-12-01T19:36:00.013Z] Mapped function route to [2021-12-01T19:36:00.013Z] Mapped function route to [2021-12-01T19:36:00.013Z] Mapped function route to *** [2021-12-01T19:36:00.013Z] [2021-12-01T19:36:00.025Z] Host initialized (140ms) [2021-12-01T19:36:00.028Z] Host started (155ms) [2021-12-01T19:36:00.028Z] Job host started

Functions:

    ***: [DELETE] ***

    ***: [GET] ***

    ***: [GET] ***

    ***: [GET] ***

    ***: [PUT] ***

[2021-12-01T19:36:04.998Z] Host lock lease acquired by instance ID '0000000000000000000000007EF87728'. [2021-12-01T19:36:59.961Z] Starting worker process failed [2021-12-01T19:36:59.961Z] The operation has timed out. [2021-12-01T19:36:59.977Z] Failed to start a new language worker for runtime: dotnet-isolated. [2021-12-01T19:36:59.977Z] System.Private.CoreLib: The operation has timed out. Unhandled exception. System.TimeoutException: The operation has timed out. at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.StartWorkerProcessAsync(CancellationToken cancellationToken) in D:\a\1\s\src\WebJobs.Script.Grpc\Channel\GrpcWorkerChannel.cs:line 155 at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.InitializeJobhostLanguageWorkerChannelAsync(Int32 attemptCount) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 118 at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.StartWorkerChannel(String runtime) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 462 at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.StartWorkerChannel(String runtime) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 474 at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.DisposeAndRestartWorkerChannel(String runtime, String workerId, Exception workerException) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 429 at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.WorkerError(WorkerErrorEvent workerError) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 374 at System.Threading.Tasks.Task.<>c.b__127_1(Object state) at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() at System.Threading.ThreadPoolWorkQueue.Dispatch() at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() at System.Threading.Thread.StartCallback()



Seems to be intermittent, failing to start about 80% of the time. Quite disruptive.
boylec commented 2 years ago

I had a call to .AddAzureKeyVault in my ConfigureAppConfiguration hook.

Once I removed that the issue is entirely resolved.

reste85 commented 2 years ago

Hi, we're facing the same issue, but with java worker. Here's the log:

Azure Functions Core Tools
Core Tools Version:       4.0.3971 Commit hash: d0775d487c93ebd49e9c1166d5c3c01f3c76eaaf  (64-bit)
Function Runtime Version: 4.0.1.16815

[2022-02-16T15:59:45.921Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:node
[2022-02-16T15:59:45.935Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:powershell
[2022-02-16T15:59:45.948Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:python
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 POST http://127.0.0.1:52147/AzureFunctionsRpcMessages.FunctionRpc/EventStream application/grpc -
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /AzureFunctionsRpcMessages.FunctionRpc/EventStream'
[2022-02-16T16:00:01.592Z] Initializing worker process failed
[2022-02-16T16:00:01.597Z] The operation has timed out.
[2022-02-16T16:00:01.606Z] Failed to start language worker process for runtime: (null). workerId:a64671fc-abe5-4c9f-9f31-66e8d2de0116
[2022-02-16T16:00:01.650Z] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: '657d5f3c-6995-43fb-be78-f835a05298c5'
[2022-02-16T16:00:01.673Z] Reading host configuration file 'C:\path_to_azure_func\host.json'
[2022-02-16T16:00:01.686Z] Host configuration file read:
[2022-02-16T16:00:01.689Z] {
[2022-02-16T16:00:01.693Z]   "version": "2.0",
[2022-02-16T16:00:01.698Z]   "functionTimeout": "00:10:00"
[2022-02-16T16:00:01.702Z] }
[2022-02-16T16:00:01.774Z] Loading functions metadata
[2022-02-16T16:00:01.783Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:node
[2022-02-16T16:00:01.788Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:powershell
[2022-02-16T16:00:01.791Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:python
[2022-02-16T16:00:01.801Z] Reading functions metadata
[2022-02-16T16:00:01.829Z] 1 functions found
[2022-02-16T16:00:01.845Z] 1 functions loaded
[2022-02-16T16:00:01.855Z] Loading extensions from C:\path_to_azure_func\bin. BundleConfigured: False, PrecompiledFunctionApp: False, LegacyBundle: False
[2022-02-16T16:00:01.874Z] Script Startup resetting load context with base path: 'C:\path_to_azure_func\bin'.
[2022-02-16T16:00:01.905Z] Reading host configuration file 'C:\path_to_azure_func\host.json'
[2022-02-16T16:00:01.912Z] Host configuration file read:
[2022-02-16T16:00:01.915Z] {
[2022-02-16T16:00:01.921Z]   "version": "2.0",
[2022-02-16T16:00:01.930Z]   "functionTimeout": "00:10:00"
[2022-02-16T16:00:01.934Z] }
[2022-02-16T16:00:02.647Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:node
[2022-02-16T16:00:02.655Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:powershell
[2022-02-16T16:00:02.668Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:python
[2022-02-16T16:00:03.061Z] Initializing Warmup Extension.
[2022-02-16T16:00:03.229Z] Initializing Host. OperationId: '657d5f3c-6995-43fb-be78-f835a05298c5'.
[2022-02-16T16:00:03.266Z] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=657d5f3c-6995-43fb-be78-f835a05298c5
[2022-02-16T16:00:03.344Z] LoggerFilterOptions
[2022-02-16T16:00:03.349Z] {
[2022-02-16T16:00:03.355Z]   "MinLevel": "None",
[2022-02-16T16:00:03.370Z]   "Rules": [
[2022-02-16T16:00:03.375Z]     {
[2022-02-16T16:00:03.382Z]       "ProviderName": null,
[2022-02-16T16:00:03.388Z]       "CategoryName": null,
[2022-02-16T16:00:03.397Z]       "LogLevel": null,
[2022-02-16T16:00:03.405Z]       "Filter": "<AddFilter>b__0"
[2022-02-16T16:00:03.411Z]     },
[2022-02-16T16:00:03.417Z]     {
[2022-02-16T16:00:03.430Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2022-02-16T16:00:03.435Z]       "CategoryName": null,
[2022-02-16T16:00:03.441Z]       "LogLevel": "None",
[2022-02-16T16:00:03.451Z]       "Filter": null
[2022-02-16T16:00:03.457Z]     },
[2022-02-16T16:00:03.459Z]     {
[2022-02-16T16:00:03.471Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2022-02-16T16:00:03.486Z]       "CategoryName": null,
[2022-02-16T16:00:03.492Z]       "LogLevel": null,
[2022-02-16T16:00:03.502Z]       "Filter": "<AddFilter>b__0"
[2022-02-16T16:00:03.507Z]     },
[2022-02-16T16:00:03.514Z]     {
[2022-02-16T16:00:03.522Z]       "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider",
[2022-02-16T16:00:03.536Z]       "CategoryName": null,
[2022-02-16T16:00:03.544Z]       "LogLevel": null,
[2022-02-16T16:00:03.554Z]       "Filter": "<AddFilter>b__0"
[2022-02-16T16:00:03.564Z]     }
[2022-02-16T16:00:03.578Z]   ]
[2022-02-16T16:00:03.598Z] }
[2022-02-16T16:00:03.606Z] LoggerFilterOptions
[2022-02-16T16:00:03.618Z] {
[2022-02-16T16:00:03.628Z]   "MinLevel": "None",
[2022-02-16T16:00:03.638Z]   "Rules": [
[2022-02-16T16:00:03.644Z]     {
[2022-02-16T16:00:03.661Z]       "ProviderName": null,
[2022-02-16T16:00:03.671Z]       "CategoryName": null,
[2022-02-16T16:00:03.696Z]       "LogLevel": null,
[2022-02-16T16:00:03.706Z]       "Filter": "<AddFilter>b__0"
[2022-02-16T16:00:03.719Z]     },
[2022-02-16T16:00:03.738Z]     {
[2022-02-16T16:00:03.740Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2022-02-16T16:00:03.753Z]       "CategoryName": null,
[2022-02-16T16:00:03.759Z]       "LogLevel": "None",
[2022-02-16T16:00:03.770Z]       "Filter": null
[2022-02-16T16:00:03.776Z]     },
[2022-02-16T16:00:03.786Z]     {
[2022-02-16T16:00:03.798Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2022-02-16T16:00:03.807Z]       "CategoryName": null,
[2022-02-16T16:00:03.816Z]       "LogLevel": null,
[2022-02-16T16:00:03.831Z]       "Filter": "<AddFilter>b__0"
[2022-02-16T16:00:03.836Z]     },
[2022-02-16T16:00:03.848Z]     {
[2022-02-16T16:00:03.853Z]       "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider",
[2022-02-16T16:00:03.861Z]       "CategoryName": null,
[2022-02-16T16:00:03.868Z]       "LogLevel": null,
[2022-02-16T16:00:03.882Z]       "Filter": "<AddFilter>b__0"
[2022-02-16T16:00:03.886Z]     }
[2022-02-16T16:00:03.893Z]   ]
[2022-02-16T16:00:03.902Z] }
[2022-02-16T16:00:03.912Z] ConcurrencyOptions
[2022-02-16T16:00:03.922Z] {
[2022-02-16T16:00:03.928Z]   "DynamicConcurrencyEnabled": false,
[2022-02-16T16:00:03.950Z]   "MaximumFunctionConcurrency": 500,
[2022-02-16T16:00:03.955Z]   "CPUThreshold": 0.8,
[2022-02-16T16:00:03.961Z]   "SnapshotPersistenceEnabled": true
[2022-02-16T16:00:03.972Z] }
[2022-02-16T16:00:03.982Z] FunctionResultAggregatorOptions
[2022-02-16T16:00:04.005Z] {
[2022-02-16T16:00:04.015Z]   "BatchSize": 1000,
[2022-02-16T16:00:04.020Z]   "FlushTimeout": "00:00:30",
[2022-02-16T16:00:04.032Z]   "IsEnabled": true
[2022-02-16T16:00:04.052Z] }
[2022-02-16T16:00:04.060Z] SingletonOptions
[2022-02-16T16:00:04.077Z] {
[2022-02-16T16:00:04.092Z]   "LockPeriod": "00:00:15",
[2022-02-16T16:00:04.104Z]   "ListenerLockPeriod": "00:00:15",
[2022-02-16T16:00:04.113Z]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[2022-02-16T16:00:04.136Z]   "LockAcquisitionPollingInterval": "00:00:05",
[2022-02-16T16:00:04.163Z]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[2022-02-16T16:00:04.193Z] }
[2022-02-16T16:00:04.248Z] Starting JobHost
[2022-02-16T16:00:04.276Z] Starting Host (HostId=fgvil011947-48094238, InstanceId=6f7714a2-e0a5-49ef-859e-aaae01e6c305, Version=4.0.1.16815, ProcessId=17012, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[2022-02-16T16:00:04.395Z] Loading functions metadata
[2022-02-16T16:00:04.404Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:node
[2022-02-16T16:00:04.427Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:powershell
[2022-02-16T16:00:04.436Z] FUNCTIONS_WORKER_RUNTIME set to java. Skipping WorkerConfig for language:python
[2022-02-16T16:00:04.475Z] 1 functions loaded
[2022-02-16T16:00:04.609Z] Removing errored webhost language worker channel for runtime: java workerId:a64671fc-abe5-4c9f-9f31-66e8d2de0116
[2022-02-16T16:00:04.616Z] System.Private.CoreLib: The operation has timed out.
[2022-02-16T16:00:04.631Z] Generating 1 job function(s)
[2022-02-16T16:00:05.078Z] Found the following functions:
[2022-02-16T16:00:05.103Z] Host.Functions.myFunction
[2022-02-16T16:00:05.111Z]
[2022-02-16T16:00:05.212Z] HttpOptions
[2022-02-16T16:00:05.219Z] {
[2022-02-16T16:00:05.221Z] Initializing function HTTP routes
[2022-02-16T16:00:05.230Z]   "DynamicThrottlesEnabled": false,
[2022-02-16T16:00:05.237Z] No HTTP routes mapped
[2022-02-16T16:00:05.257Z]   "EnableChunkedRequestBinding": false,
[2022-02-16T16:00:05.262Z]
[2022-02-16T16:00:05.279Z]   "MaxConcurrentRequests": -1,
[2022-02-16T16:00:05.297Z]   "MaxOutstandingRequests": -1,
[2022-02-16T16:00:05.303Z]   "RoutePrefix": "api"
[2022-02-16T16:00:05.327Z] }
[2022-02-16T16:00:05.344Z] Host initialized (981ms)

Functions:

        myFunction: timerTrigger

[2022-02-16T16:00:05.501Z] The next 5 occurrences of the 'myFunction' schedule (Cron: '0,2,4,6,8,10,12,14,16,18,20,22,24,26,28,30,32,34,36,38,40,42,44,46,48,50,52,54,56,58 * * * * *') will be:
[2022-02-16T16:00:05.511Z] 02/16/2022 17:00:06+01:00 (02/16/2022 16:00:06Z)
[2022-02-16T16:00:05.521Z] 02/16/2022 17:00:08+01:00 (02/16/2022 16:00:08Z)
[2022-02-16T16:00:05.531Z] 02/16/2022 17:00:10+01:00 (02/16/2022 16:00:10Z)
[2022-02-16T16:00:05.539Z] 02/16/2022 17:00:12+01:00 (02/16/2022 16:00:12Z)
[2022-02-16T16:00:05.557Z] 02/16/2022 17:00:14+01:00 (02/16/2022 16:00:14Z)
[2022-02-16T16:00:05.563Z]
[2022-02-16T16:00:05.611Z] Host started (1305ms)
[2022-02-16T16:00:05.620Z] Job host started
[2022-02-16T16:00:06.241Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:06.0711097+01:00', Id=8595e8e5-1462-40b8-bfae-bbc268e6ec13)
[2022-02-16T16:00:08.389Z] Host lock lease acquired by instance ID '0000000000000000000000009F1C094D'.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 POST http://127.0.0.1:52147/AzureFunctionsRpcMessages.FunctionRpc/EventStream application/grpc -
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /AzureFunctionsRpcMessages.FunctionRpc/EventStream'
[2022-02-16T16:00:21.296Z] Initializing worker process failed
[2022-02-16T16:00:21.305Z] The operation has timed out.
[2022-02-16T16:00:21.321Z] Failed to start language worker process for runtime: (null). workerId:37397361-cfc0-4372-8e24-7d3982ebbcb5
[2022-02-16T16:00:21.356Z] Worker process started and initialized.
[2022-02-16T16:00:21.423Z] Executed 'Functions.myFunction' (Failed, Id=8595e8e5-1462-40b8-bfae-bbc268e6ec13, Duration=15331ms)
[2022-02-16T16:00:21.430Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:21.497Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:21.4967895+01:00', Id=69a561cc-06cb-49cb-b97b-4c3d2a7cdd96)
[2022-02-16T16:00:21.510Z] Executed 'Functions.myFunction' (Failed, Id=69a561cc-06cb-49cb-b97b-4c3d2a7cdd96, Duration=11ms)
[2022-02-16T16:00:21.527Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:22.012Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:22.0126306+01:00', Id=a048ecaa-dcd9-4f00-b8ac-390fad82ecdd)
[2022-02-16T16:00:22.021Z] Executed 'Functions.myFunction' (Failed, Id=a048ecaa-dcd9-4f00-b8ac-390fad82ecdd, Duration=7ms)
[2022-02-16T16:00:22.027Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:24.001Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:24.0011902+01:00', Id=5730cf9a-bdd0-4b27-8c0a-637ef6e13a87)
[2022-02-16T16:00:24.010Z] Executed 'Functions.myFunction' (Failed, Id=5730cf9a-bdd0-4b27-8c0a-637ef6e13a87, Duration=7ms)
[2022-02-16T16:00:24.029Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 POST http://127.0.0.1:52147/AzureFunctionsRpcMessages.FunctionRpc/EventStream application/grpc -
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /AzureFunctionsRpcMessages.FunctionRpc/EventStream'
[2022-02-16T16:00:26.001Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:26.0011639+01:00', Id=5beb0a63-3696-4c92-8f73-32f4044fe349)
[2022-02-16T16:00:26.007Z] Executed 'Functions.myFunction' (Failed, Id=5beb0a63-3696-4c92-8f73-32f4044fe349, Duration=5ms)
[2022-02-16T16:00:26.008Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:28.015Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:28.0150206+01:00', Id=121d0a5d-bf49-4834-99ae-8b574c9edf28)
[2022-02-16T16:00:28.021Z] Executed 'Functions.myFunction' (Failed, Id=121d0a5d-bf49-4834-99ae-8b574c9edf28, Duration=6ms)
[2022-02-16T16:00:28.023Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:30.005Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:30.0055341+01:00', Id=d269b27b-fac1-4698-ab17-e4579148ff13)
[2022-02-16T16:00:30.026Z] Executed 'Functions.myFunction' (Failed, Id=d269b27b-fac1-4698-ab17-e4579148ff13, Duration=19ms)
[2022-02-16T16:00:30.035Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:32.003Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:32.0032694+01:00', Id=f4adc94a-7b36-437a-8fe9-b8b343c13cc6)
[2022-02-16T16:00:32.015Z] Executed 'Functions.myFunction' (Failed, Id=f4adc94a-7b36-437a-8fe9-b8b343c13cc6, Duration=10ms)
[2022-02-16T16:00:32.020Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:34.011Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:34.0116034+01:00', Id=96812d9f-8414-4a76-8e5d-d5fee84576e1)
[2022-02-16T16:00:34.017Z] Executed 'Functions.myFunction' (Failed, Id=96812d9f-8414-4a76-8e5d-d5fee84576e1, Duration=5ms)
[2022-02-16T16:00:34.018Z] System.Private.CoreLib: Exception while executing function: Functions.myFunction. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[2022-02-16T16:00:35.544Z] Initializing worker process failed
[2022-02-16T16:00:35.551Z] The operation has timed out.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'gRPC - /AzureFunctionsRpcMessages.FunctionRpc/EventStream'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/2 POST http://127.0.0.1:52147/AzureFunctionsRpcMessages.FunctionRpc/EventStream application/grpc - - 200 - application/grpc 10067.9010ms
info: Grpc.AspNetCore.Server.ServerCallHandler[14]
      Error reading message.
      System.IO.IOException: The request stream was aborted.
       ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
       ---> Microsoft.AspNetCore.Connections.ConnectionResetException: Connessione in corso interrotta forzatamente dall'host remoto.
       ---> System.Net.Sockets.SocketException (10054): Connessione in corso interrotta forzatamente dall'host remoto.
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketAwaitableEventArgs.<GetResult>g__ThrowSocketException|5_0(SocketError e)
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketAwaitableEventArgs.GetResult(Int16 token)
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.DoReceive()
         --- End of inner exception stack trace ---
         at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
         at System.IO.Pipelines.Pipe.GetReadAsyncResult()
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ReadInputAsync()
         at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
         at System.IO.Pipelines.Pipe.GetReadAsyncResult()
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
         --- End of inner exception stack trace ---
         --- End of inner exception stack trace ---
         at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
         at System.IO.Pipelines.Pipe.GetReadAsyncResult()
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
         at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
         at Grpc.AspNetCore.Server.Internal.PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken)
info: Microsoft.AspNetCore.Server.Kestrel[32]
      Connection id "0HMFHCLENMGA2", Request id "0HMFHCLENMGA2:00000003": the application completed without reading the entire request body.
[2022-02-16T16:00:36.003Z] Executing 'Functions.myFunction' (Reason='Timer fired at 2022-02-16T17:00:36.0036732+01:00', Id=38715950-00c7-4855-a676-e0c3fb82c9a3)
Unhandled exception. System.TimeoutException: The operation has timed out.
   at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.StartWorkerProcessAsync(CancellationToken cancellationToken) in D:\a\1\s\src\WebJobs.Script.Grpc\Channel\GrpcWorkerChannel.cs:line 155
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.InitializeJobhostLanguageWorkerChannelAsync(Int32 attemptCount) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 118
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.StartWorkerChannel(String runtime) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 462
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.StartWorkerChannel(String runtime) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 474
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.DisposeAndRestartWorkerChannel(String runtime, String workerId, Exception workerException) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 429
   at Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcFunctionInvocationDispatcher.WorkerError(WorkerErrorEvent workerError) in D:\a\1\s\src\WebJobs.Script\Workers\Rpc\FunctionRegistration\RpcFunctionInvocationDispatcher.cs:line 374
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__127_1(Object state)
   at System.Threading.QueueUserWorkItemCallback.<>c.<.cctor>b__6_0(QueueUserWorkItemCallback quwi)
   at System.Threading.ExecutionContext.RunForThreadPoolUnsafe[TState](ExecutionContext executionContext, Action`1 callback, TState& state)
   at System.Threading.QueueUserWorkItemCallback.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()

Is it possible to understand what is happening? On 3 hosts we're facing this error, on another host it works and we can debug locally through IntelliJIdea

nikolaj-kaplan commented 2 years ago

I have a similar issue. And I can also fix it by removing my call to AddAzureKeyVault during startup. Is there any way to increase the timeout? I experienced no issues on one laptop. But it started when I cloned the solution to a new laptop.

Azure Functions Core Tools
Core Tools Version:       4.0.4590 Commit hash: N/A  (64-bit)
Function Runtime Version: 4.5.2.18383

"FUNCTIONS_WORKER_RUNTIME": "dotnet-isolated"
boylec commented 2 years ago

Still experiencing startup timeouts w/ .AddAzureKeyVault when using managed identity locally (az login ...)

boylec commented 2 years ago

Update:

I have resolved my issue.

I was using the "Microsoft.Extensions.Configuration.AzureKeyVault" package. Apparently this package is deprecated.

Switching to "Azure.Extensions.AspNetCore.Configuration.Secrets" solved the issue for me.

Didn't even have to update any actual code aside from using statements.

Some applicable docs

soninaren commented 3 months ago

@boylec Thanks for updating the thread with the resolution. glad to hear you were able to find a fix for it. Closing as the issue is resolved