Azure / azure-functions-python-worker

Python worker for Azure Functions.
http://aka.ms/azurefunctions
MIT License
331 stars 100 forks source link

MacOS ARM64 Failed to start language worker process for runtime grpc.FutureTimeoutError #1380

Closed rich-sykes closed 2 months ago

rich-sykes commented 6 months ago

Investigative information

Please can I get some help resolving GPRC timeout when trying to run Azure Function runner. This has been carried out on a clean MacOS ARM64 build

Please provide the following:

Repro steps

func init MyProjFolder --worker-runtime python --model V2

cd MyProjFolder

func new --template "Http Trigger" --name MyHttpTrigger

func start --debug --verbose

Expected behavior

Azure Functions Core Tools starts and functions are available.

Actual behavior

> python3 --version
> python --version
> python3.6 --version
> python3.7 --version
> python3.8 --version
> python3.9 --version
> python3.10 --version
> python3.11 --version
Found Python version 3.10.10 (python3).
languageWorkers:python:defaultExecutablePath is set to python3

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

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

[2023-12-12T11:18:06.194Z] Building host: version spec: , startup suppressed: 'False', configuration suppressed: 'False', startup operation id: '4a2445d6-d732-47c1-a40e-cd79483310d8'
[2023-12-12T11:18:06.197Z] Reading host configuration file '/Users/rsykes/dev/MyProjFolder/host.json'
[2023-12-12T11:18:06.198Z] Host configuration file read:
[2023-12-12T11:18:06.198Z] {
[2023-12-12T11:18:06.198Z]   "version": "2.0",
[2023-12-12T11:18:06.198Z]   "logging": {
[2023-12-12T11:18:06.198Z]     "applicationInsights": {
[2023-12-12T11:18:06.198Z]       "samplingSettings": {
[2023-12-12T11:18:06.198Z]         "isEnabled": true,
[2023-12-12T11:18:06.198Z]         "excludedTypes": "Request"
[2023-12-12T11:18:06.198Z]       }
[2023-12-12T11:18:06.198Z]     }
[2023-12-12T11:18:06.198Z]   },
[2023-12-12T11:18:06.198Z]   "extensionBundle": {
[2023-12-12T11:18:06.199Z]     "id": "Microsoft.Azure.Functions.ExtensionBundle",
[2023-12-12T11:18:06.199Z]     "version": "[4.*, 5.0.0)"
[2023-12-12T11:18:06.199Z]   }
[2023-12-12T11:18:06.199Z] }
[2023-12-12T11:18:06.232Z] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language: java
[2023-12-12T11:18:06.233Z] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language: powershell
[2023-12-12T11:18:06.233Z] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language: node
[2023-12-12T11:18:06.234Z] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle
[2023-12-12T11:18:06.234Z] Found a matching extension bundle at /Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/4.8.0
[2023-12-12T11:18:06.242Z] Loading functions metadata
[2023-12-12T11:18:06.243Z] Worker indexing is enabled
[2023-12-12T11:18:06.247Z] Fetching metadata for workerRuntime: python
[2023-12-12T11:18:06.247Z] Reading functions metadata (Worker)
[2023-12-12T11:18:06.978Z]  INFO: Starting Azure Functions Python Worker.
[2023-12-12T11:18:06.978Z]  INFO: Worker ID: c00ddc2e-238a-432b-9c65-3ebf490411a9, Request ID: 1875181e-9022-47b2-a701-d7c23fd99851, Host Address: 127.0.0.1:54842
[2023-12-12T11:18:12.420Z]  ERROR: unhandled error in functions worker: 
[2023-12-12T11:18:12.432Z] Language Worker Process exited. Pid=42185.
[2023-12-12T11:18:12.432Z] Microsoft.Azure.WebJobs.Script.Workers.WorkerProcessExitException: python3 exited with code 1 (0x1)
[2023-12-12T11:18:12.432Z]  ---> System.Exception: grpc.FutureTimeoutError,    raise grpc.FutureTimeoutError(),grpc.FutureTimeoutError
[2023-12-12T11:18:12.432Z]    --- End of inner exception stack trace ---
[2023-12-12T11:19:06.324Z] Starting worker process failed
[2023-12-12T11:19:06.324Z] System.TimeoutException: The operation has timed out.
[2023-12-12T11:19:06.324Z]    at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.PendingItem.OnTimeout() in /_/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs:line 1578
[2023-12-12T11:19:06.325Z] Failed to start language worker process for runtime: (null). workerId:c00ddc2e-238a-432b-9c65-3ebf490411a9
[2023-12-12T11:19:06.330Z] Removing errored webhost language worker channel for runtime: python workerId:c00ddc2e-238a-432b-9c65-3ebf490411a9
[2023-12-12T11:19:06.330Z] System.AggregateException: One or more errors occurred. (The operation has timed out.)
[2023-12-12T11:19:06.330Z]  ---> System.TimeoutException: The operation has timed out.
[2023-12-12T11:19:06.330Z]    at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.PendingItem.OnTimeout() in /_/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs:line 1578
[2023-12-12T11:19:06.330Z] --- End of stack trace from previous location ---
[2023-12-12T11:19:06.330Z]    at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.StartWorkerProcessAsync(CancellationToken cancellationToken) in /_/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs:line 283
[2023-12-12T11:19:06.330Z]    --- End of inner exception stack trace ---
[2023-12-12T11:19:06.331Z]    at Microsoft.Azure.WebJobs.Script.WorkerFunctionMetadataProvider.GetFunctionMetadataAsync(IEnumerable`1 workerConfigs, Boolean forceRefresh) in /_/src/WebJobs.Script/Host/WorkerFunctionMetadataProvider.cs:line 91
[2023-12-12T11:19:06.341Z] 0 functions loaded
[2023-12-12T11:19:06.342Z] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle
[2023-12-12T11:19:06.343Z] Found a matching extension bundle at /Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/4.8.0
[2023-12-12T11:19:06.343Z] Fetching information on versions of extension bundle Microsoft.Azure.Functions.ExtensionBundle available on https://functionscdn.azureedge.net/public/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/index.json
[2023-12-12T11:19:06.386Z] Skipping bundle download since it already exists at path /Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/4.8.0
[2023-12-12T11:19:06.387Z] Loading extension bundle from /Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/4.8.0/bin
[2023-12-12T11:19:06.388Z] Script Startup resetting load context with base path: '/Users/rsykes/.azure-functions-core-tools/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/4.8.0/bin'.
[2023-12-12T11:19:06.395Z] Reading host configuration file '/Users/rsykes/dev/MyProjFolder/host.json'
[2023-12-12T11:19:06.395Z] Host configuration file read:
[2023-12-12T11:19:06.395Z] {
[2023-12-12T11:19:06.395Z]   "version": "2.0",
[2023-12-12T11:19:06.395Z]   "logging": {
[2023-12-12T11:19:06.395Z]     "applicationInsights": {
[2023-12-12T11:19:06.395Z]       "samplingSettings": {
[2023-12-12T11:19:06.395Z]         "isEnabled": true,
[2023-12-12T11:19:06.395Z]         "excludedTypes": "Request"
[2023-12-12T11:19:06.396Z]       }
[2023-12-12T11:19:06.396Z]     }
[2023-12-12T11:19:06.396Z]   },
[2023-12-12T11:19:06.396Z]   "extensionBundle": {
[2023-12-12T11:19:06.396Z]     "id": "Microsoft.Azure.Functions.ExtensionBundle",
[2023-12-12T11:19:06.396Z]     "version": "[4.*, 5.0.0)"
[2023-12-12T11:19:06.396Z]   }
[2023-12-12T11:19:06.396Z] }
[2023-12-12T11:19:06.586Z] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language: java
[2023-12-12T11:19:06.586Z] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language: powershell
[2023-12-12T11:19:06.587Z] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language: node
[2023-12-12T11:19:06.660Z] Initializing Warmup Extension.
[2023-12-12T11:19:06.699Z] Initializing Host. OperationId: '4a2445d6-d732-47c1-a40e-cd79483310d8'.
[2023-12-12T11:19:06.706Z] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=4a2445d6-d732-47c1-a40e-cd79483310d8
[2023-12-12T11:19:06.732Z] Traceback (most recent call last):
[2023-12-12T11:19:06.732Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 60, in main
[2023-12-12T11:19:06.732Z]     return aio_compat.run(start_async(
[2023-12-12T11:19:06.732Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
[2023-12-12T11:19:06.732Z]     return loop.run_until_complete(main)
[2023-12-12T11:19:06.732Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
[2023-12-12T11:19:06.732Z]     return future.result()
[2023-12-12T11:19:06.733Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 72, in start_async
[2023-12-12T11:19:06.733Z]     disp = await dispatcher.Dispatcher.connect(host=host, port=port,
[2023-12-12T11:19:06.733Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 122, in connect
[2023-12-12T11:19:06.733Z]     await disp._grpc_connected_fut
[2023-12-12T11:19:06.733Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 784, in __poll_grpc
[2023-12-12T11:19:06.733Z]     grpc.channel_ready_future(channel).result(
[2023-12-12T11:19:06.733Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 151, in result
[2023-12-12T11:19:06.733Z]     self._block(timeout)
[2023-12-12T11:19:06.733Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 97, in _block
[2023-12-12T11:19:06.733Z]     raise grpc.FutureTimeoutError()
[2023-12-12T11:19:06.733Z] grpc.FutureTimeoutError
[2023-12-12T11:19:06.733Z] Traceback (most recent call last):
[2023-12-12T11:19:06.734Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 60, in main
[2023-12-12T11:19:06.734Z]     return aio_compat.run(start_async(
[2023-12-12T11:19:06.734Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
[2023-12-12T11:19:06.734Z]     return loop.run_until_complete(main)
[2023-12-12T11:19:06.734Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
[2023-12-12T11:19:06.734Z]     return future.result()
[2023-12-12T11:19:06.734Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 72, in start_async
[2023-12-12T11:19:06.734Z]     disp = await dispatcher.Dispatcher.connect(host=host, port=port,
[2023-12-12T11:19:06.734Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 122, in connect
[2023-12-12T11:19:06.734Z]     await disp._grpc_connected_fut
[2023-12-12T11:19:06.734Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 784, in __poll_grpc
[2023-12-12T11:19:06.734Z]     grpc.channel_ready_future(channel).result(
[2023-12-12T11:19:06.735Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 151, in result
[2023-12-12T11:19:06.735Z]     self._block(timeout)
[2023-12-12T11:19:06.735Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 97, in _block
[2023-12-12T11:19:06.735Z]     raise grpc.FutureTimeoutError()
[2023-12-12T11:19:06.735Z] grpc.FutureTimeoutError
[2023-12-12T11:19:06.735Z] Traceback (most recent call last):
[2023-12-12T11:19:06.735Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/worker.py", line 74, in <module>
[2023-12-12T11:19:06.735Z]     main.main()
[2023-12-12T11:19:06.735Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 60, in main
[2023-12-12T11:19:06.735Z]     return aio_compat.run(start_async(
[2023-12-12T11:19:06.735Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
[2023-12-12T11:19:06.735Z]     return loop.run_until_complete(main)
[2023-12-12T11:19:06.735Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
[2023-12-12T11:19:06.736Z]     return future.result()
[2023-12-12T11:19:06.736Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 72, in start_async
[2023-12-12T11:19:06.736Z]     disp = await dispatcher.Dispatcher.connect(host=host, port=port,
[2023-12-12T11:19:06.736Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 122, in connect
[2023-12-12T11:19:06.736Z]     await disp._grpc_connected_fut
[2023-12-12T11:19:06.736Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 784, in __poll_grpc
[2023-12-12T11:19:06.736Z]     grpc.channel_ready_future(channel).result(
[2023-12-12T11:19:06.736Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 151, in result
[2023-12-12T11:19:06.736Z]     self._block(timeout)
[2023-12-12T11:19:06.736Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 97, in _block
[2023-12-12T11:19:06.736Z]     raise grpc.FutureTimeoutError()
[2023-12-12T11:19:06.736Z] grpc.FutureTimeoutError
[2023-12-12T11:19:06.738Z] LoggerFilterOptions
[2023-12-12T11:19:06.739Z] {
[2023-12-12T11:19:06.739Z]   "MinLevel": "None",
[2023-12-12T11:19:06.739Z]   "Rules": [
[2023-12-12T11:19:06.739Z]     {
[2023-12-12T11:19:06.739Z]       "ProviderName": null,
[2023-12-12T11:19:06.739Z]       "CategoryName": null,
[2023-12-12T11:19:06.739Z]       "LogLevel": null,
[2023-12-12T11:19:06.739Z]       "Filter": "<AddFilter>b__0"
[2023-12-12T11:19:06.739Z]     },
[2023-12-12T11:19:06.739Z]     {
[2023-12-12T11:19:06.739Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2023-12-12T11:19:06.739Z]       "CategoryName": null,
[2023-12-12T11:19:06.739Z]       "LogLevel": "None",
[2023-12-12T11:19:06.739Z]       "Filter": null
[2023-12-12T11:19:06.739Z]     },
[2023-12-12T11:19:06.739Z]     {
[2023-12-12T11:19:06.740Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2023-12-12T11:19:06.740Z]       "CategoryName": null,
[2023-12-12T11:19:06.740Z]       "LogLevel": null,
[2023-12-12T11:19:06.740Z]       "Filter": "<AddFilter>b__0"
[2023-12-12T11:19:06.740Z]     },
[2023-12-12T11:19:06.740Z]     {
[2023-12-12T11:19:06.740Z]       "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider",
[2023-12-12T11:19:06.740Z]       "CategoryName": null,
[2023-12-12T11:19:06.740Z]       "LogLevel": null,
[2023-12-12T11:19:06.740Z]       "Filter": "<AddFilter>b__0"
[2023-12-12T11:19:06.740Z]     }
[2023-12-12T11:19:06.740Z]   ]
[2023-12-12T11:19:06.740Z] }
[2023-12-12T11:19:06.740Z] LoggerFilterOptions
[2023-12-12T11:19:06.740Z] {
[2023-12-12T11:19:06.741Z]   "MinLevel": "None",
[2023-12-12T11:19:06.741Z]   "Rules": [
[2023-12-12T11:19:06.741Z]     {
[2023-12-12T11:19:06.741Z]       "ProviderName": null,
[2023-12-12T11:19:06.741Z]       "CategoryName": null,
[2023-12-12T11:19:06.741Z]       "LogLevel": null,
[2023-12-12T11:19:06.741Z]       "Filter": "<AddFilter>b__0"
[2023-12-12T11:19:06.741Z]     },
[2023-12-12T11:19:06.741Z]     {
[2023-12-12T11:19:06.741Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2023-12-12T11:19:06.741Z]       "CategoryName": null,
[2023-12-12T11:19:06.741Z]       "LogLevel": "None",
[2023-12-12T11:19:06.741Z]       "Filter": null
[2023-12-12T11:19:06.741Z]     },
[2023-12-12T11:19:06.741Z]     {
[2023-12-12T11:19:06.741Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2023-12-12T11:19:06.742Z]       "CategoryName": null,
[2023-12-12T11:19:06.742Z]       "LogLevel": null,
[2023-12-12T11:19:06.742Z]       "Filter": "<AddFilter>b__0"
[2023-12-12T11:19:06.742Z]     },
[2023-12-12T11:19:06.742Z]     {
[2023-12-12T11:19:06.742Z]       "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider",
[2023-12-12T11:19:06.742Z]       "CategoryName": null,
[2023-12-12T11:19:06.742Z]       "LogLevel": null,
[2023-12-12T11:19:06.742Z]       "Filter": "<AddFilter>b__0"
[2023-12-12T11:19:06.742Z]     }
[2023-12-12T11:19:06.742Z]   ]
[2023-12-12T11:19:06.742Z] }
[2023-12-12T11:19:06.743Z] ConcurrencyOptions
[2023-12-12T11:19:06.743Z] {
[2023-12-12T11:19:06.743Z]   "DynamicConcurrencyEnabled": false,
[2023-12-12T11:19:06.743Z]   "MaximumFunctionConcurrency": 500,
[2023-12-12T11:19:06.743Z]   "CPUThreshold": 0.8,
[2023-12-12T11:19:06.743Z]   "SnapshotPersistenceEnabled": true
[2023-12-12T11:19:06.743Z] }
[2023-12-12T11:19:06.743Z] FunctionResultAggregatorOptions
[2023-12-12T11:19:06.743Z] {
[2023-12-12T11:19:06.743Z]   "BatchSize": 1000,
[2023-12-12T11:19:06.743Z]   "FlushTimeout": "00:00:30",
[2023-12-12T11:19:06.743Z]   "IsEnabled": true
[2023-12-12T11:19:06.743Z] }
[2023-12-12T11:19:06.743Z] SingletonOptions
[2023-12-12T11:19:06.744Z] {
[2023-12-12T11:19:06.744Z]   "LockPeriod": "00:00:15",
[2023-12-12T11:19:06.744Z]   "ListenerLockPeriod": "00:00:15",
[2023-12-12T11:19:06.744Z]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[2023-12-12T11:19:06.744Z]   "LockAcquisitionPollingInterval": "00:00:05",
[2023-12-12T11:19:06.744Z]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[2023-12-12T11:19:06.744Z] }
[2023-12-12T11:19:06.744Z] ScaleOptions
[2023-12-12T11:19:06.744Z] {
[2023-12-12T11:19:06.744Z]   "ScaleMetricsMaxAge": "00:02:00",
[2023-12-12T11:19:06.744Z]   "ScaleMetricsSampleInterval": "00:00:10",
[2023-12-12T11:19:06.744Z]   "MetricsPurgeEnabled": true,
[2023-12-12T11:19:06.744Z]   "IsTargetScalingEnabled": true,
[2023-12-12T11:19:06.744Z]   "IsRuntimeScalingEnabled": false
[2023-12-12T11:19:06.745Z] }
[2023-12-12T11:19:06.745Z] Starting JobHost
[2023-12-12T11:19:06.747Z] Starting Host (HostId=eudukpmmd72kp-1851097344, InstanceId=a608f022-8bd6-44be-874d-6cd5d454acd0, Version=4.27.5.21554, ProcessId=41204, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[2023-12-12T11:19:06.756Z] Loading functions metadata
[2023-12-12T11:19:06.756Z] Worker indexing is enabled
[2023-12-12T11:19:06.756Z] Fetching metadata for workerRuntime: python
[2023-12-12T11:19:06.756Z] Reading functions metadata (Worker)
[2023-12-12T11:19:07.134Z]  INFO: Starting Azure Functions Python Worker.
[2023-12-12T11:19:07.134Z]  INFO: Worker ID: 2a430b28-47bf-4a43-a749-4d7c3041a3b8, Request ID: 38a2998e-3d7e-4465-9937-c7ba9a40d3e2, Host Address: 127.0.0.1:54842
[2023-12-12T11:19:12.227Z]  ERROR: unhandled error in functions worker: 
[2023-12-12T11:19:12.229Z] Traceback (most recent call last):
[2023-12-12T11:19:12.229Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 60, in main
[2023-12-12T11:19:12.229Z]     return aio_compat.run(start_async(
[2023-12-12T11:19:12.230Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
[2023-12-12T11:19:12.230Z]     return loop.run_until_complete(main)
[2023-12-12T11:19:12.230Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
[2023-12-12T11:19:12.230Z]     return future.result()
[2023-12-12T11:19:12.230Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 72, in start_async
[2023-12-12T11:19:12.230Z]     disp = await dispatcher.Dispatcher.connect(host=host, port=port,
[2023-12-12T11:19:12.231Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 122, in connect
[2023-12-12T11:19:12.231Z]     await disp._grpc_connected_fut
[2023-12-12T11:19:12.231Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 784, in __poll_grpc
[2023-12-12T11:19:12.231Z]     grpc.channel_ready_future(channel).result(
[2023-12-12T11:19:12.231Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 151, in result
[2023-12-12T11:19:12.231Z]     self._block(timeout)
[2023-12-12T11:19:12.231Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 97, in _block
[2023-12-12T11:19:12.232Z]     raise grpc.FutureTimeoutError()
[2023-12-12T11:19:12.232Z] grpc.FutureTimeoutError
[2023-12-12T11:19:12.232Z] Traceback (most recent call last):
[2023-12-12T11:19:12.232Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 60, in main
[2023-12-12T11:19:12.232Z]     return aio_compat.run(start_async(
[2023-12-12T11:19:12.232Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
[2023-12-12T11:19:12.232Z]     return loop.run_until_complete(main)
[2023-12-12T11:19:12.232Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
[2023-12-12T11:19:12.233Z]     return future.result()
[2023-12-12T11:19:12.233Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 72, in start_async
[2023-12-12T11:19:12.233Z]     disp = await dispatcher.Dispatcher.connect(host=host, port=port,
[2023-12-12T11:19:12.233Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 122, in connect
[2023-12-12T11:19:12.233Z]     await disp._grpc_connected_fut
[2023-12-12T11:19:12.233Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 784, in __poll_grpc
[2023-12-12T11:19:12.234Z]     grpc.channel_ready_future(channel).result(
[2023-12-12T11:19:12.234Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 151, in result
[2023-12-12T11:19:12.234Z]     self._block(timeout)
[2023-12-12T11:19:12.234Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 97, in _block
[2023-12-12T11:19:12.234Z]     raise grpc.FutureTimeoutError()
[2023-12-12T11:19:12.234Z] grpc.FutureTimeoutError
[2023-12-12T11:19:12.234Z] Traceback (most recent call last):
[2023-12-12T11:19:12.235Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/worker.py", line 74, in <module>
[2023-12-12T11:19:12.235Z]     main.main()
[2023-12-12T11:19:12.235Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 60, in main
[2023-12-12T11:19:12.235Z]     return aio_compat.run(start_async(
[2023-12-12T11:19:12.235Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
[2023-12-12T11:19:12.235Z]     return loop.run_until_complete(main)
[2023-12-12T11:19:12.235Z]   File "/Users/rsykes/.pyenv/versions/3.10.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
[2023-12-12T11:19:12.235Z]     return future.result()
[2023-12-12T11:19:12.236Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/main.py", line 72, in start_async
[2023-12-12T11:19:12.236Z]     disp = await dispatcher.Dispatcher.connect(host=host, port=port,
[2023-12-12T11:19:12.236Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 122, in connect
[2023-12-12T11:19:12.236Z]     await disp._grpc_connected_fut
[2023-12-12T11:19:12.236Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/azure_functions_worker/dispatcher.py", line 784, in __poll_grpc
[2023-12-12T11:19:12.236Z]     grpc.channel_ready_future(channel).result(
[2023-12-12T11:19:12.236Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 151, in result
[2023-12-12T11:19:12.236Z]     self._block(timeout)
[2023-12-12T11:19:12.236Z]   File "/opt/homebrew/Cellar/azure-functions-core-tools@4/4.0.5455/workers/python/3.10/OSX/Arm64/grpc/_utilities.py", line 97, in _block
[2023-12-12T11:19:12.236Z]     raise grpc.FutureTimeoutError()
[2023-12-12T11:19:12.237Z] grpc.FutureTimeoutError
[2023-12-12T11:19:12.249Z] Language Worker Process exited. Pid=42278.
[2023-12-12T11:19:12.249Z] Microsoft.Azure.WebJobs.Script.Workers.WorkerProcessExitException: python3 exited with code 1 (0x1)
[2023-12-12T11:19:12.249Z]  ---> System.Exception: grpc.FutureTimeoutError,    raise grpc.FutureTimeoutError(),grpc.FutureTimeoutError
[2023-12-12T11:19:12.249Z]    --- End of inner exception stack trace ---
[2023-12-12T11:19:12.256Z] Exceeded language worker restart retry count for runtime:python. Shutting down and proactively recycling the Functions Host to recover
[2023-12-12T11:20:06.760Z] Starting worker process failed
[2023-12-12T11:20:06.760Z] System.TimeoutException: The operation has timed out.
[2023-12-12T11:20:06.760Z]    at Microsoft.Azure.WebJobs.Script.Grpc.GrpcWorkerChannel.PendingItem.OnTimeout() in /_/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs:line 1578
[2023-12-12T11:20:06.760Z] Failed to start language worker process for runtime: (null). workerId:2a430b28-47bf-4a43-a749-4d7c3041a3b8
[2023-12-12T11:20:06.765Z] A host error has occurred during startup operation '4a2445d6-d732-47c1-a40e-cd79483310d8'.
[2023-12-12T11:20:06.765Z] System.NullReferenceException: Object reference not set to an instance of an object.
[2023-12-12T11:20:06.765Z]    at Microsoft.Azure.WebJobs.Script.WorkerFunctionMetadataProvider.GetFunctionMetadataAsync(IEnumerable`1 workerConfigs, Boolean forceRefresh) in /_/src/WebJobs.Script/Host/WorkerFunctionMetadataProvider.cs:line 84
[2023-12-12T11:20:06.765Z]    at Microsoft.Azure.WebJobs.Script.WebHost.FunctionMetadataProvider.GetFunctionMetadataAsync(IEnumerable`1 workerConfigs, IEnvironment environment, Boolean forceRefresh) in /_/src/WebJobs.Script/Host/FunctionMetadataProvider.cs:line 45
[2023-12-12T11:20:06.766Z]    at Microsoft.Azure.WebJobs.Script.FunctionMetadataManager.LoadFunctionMetadata(Boolean forceRefresh, Boolean includeCustomProviders, IFunctionInvocationDispatcher dispatcher, IList`1 workerConfigs) in /_/src/WebJobs.Script/Host/FunctionMetadataManager.cs:line 146
[2023-12-12T11:20:06.766Z]    at Microsoft.Azure.WebJobs.Script.FunctionMetadataManager.GetFunctionMetadata(Boolean forceRefresh, Boolean applyAllowList, Boolean includeCustomProviders, IList`1 workerConfigs) in /_/src/WebJobs.Script/Host/FunctionMetadataManager.cs:line 90
[2023-12-12T11:20:06.766Z]    at Microsoft.Azure.WebJobs.Script.ScriptHost.GetFunctionsMetadata() in /_/src/WebJobs.Script/Host/ScriptHost.cs:line 372
[2023-12-12T11:20:06.766Z]    at Microsoft.Azure.WebJobs.Script.ScriptHost.InitializeAsync(CancellationToken cancellationToken) in /_/src/WebJobs.Script/Host/ScriptHost.cs:line 279
[2023-12-12T11:20:06.766Z]    at Microsoft.Azure.WebJobs.Script.ScriptHost.StartAsyncCore(CancellationToken cancellationToken) in /_/src/WebJobs.Script/Host/ScriptHost.cs:line 256
[2023-12-12T11:20:06.766Z]    at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
[2023-12-12T11:20:06.766Z]    at Microsoft.Azure.WebJobs.Script.WebHost.WebJobsScriptHostService.UnsynchronizedStartHostAsync(ScriptHostStartupOperation activeOperation, Int32 attemptCount, JobHostStartupMode startupMode) in /_/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs:line 328
[2023-12-12T11:20:06.769Z] Stopping JobHost
[2023-12-12T11:20:06.774Z] Failed to stop host instance 'a608f022-8bd6-44be-874d-6cd5d454acd0'.
[2023-12-12T11:20:06.774Z] System.AggregateException: One or more hosted services failed to stop. (The host has not yet started.)
[2023-12-12T11:20:06.774Z]  ---> System.InvalidOperationException: The host has not yet started.
[2023-12-12T11:20:06.774Z]    at Microsoft.Azure.WebJobs.JobHost.StopAsync() in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\JobHost.cs:line 119
[2023-12-12T11:20:06.774Z]    at Microsoft.Azure.WebJobs.Hosting.JobHostService.StopAsync(CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Hosting\JobHostService.cs:line 32
[2023-12-12T11:20:06.774Z]    at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
[2023-12-12T11:20:06.774Z]    --- End of inner exception stack trace ---
[2023-12-12T11:20:06.775Z]    at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
[2023-12-12T11:20:06.775Z]    at Microsoft.Azure.WebJobs.Script.WebHost.WebJobsScriptHostService.Orphan(IHost instance, CancellationToken cancellationToken) in /_/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs:line 741
System.ArgumentNullException: Value cannot be null. (Parameter 'provider')
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Azure.Functions.Cli.Actions.HostActions.StartHostAction.RunAsync() in D:\a\_work\1\s\src\Azure.Functions.Cli\Actions\HostActions\StartHostAction.cs:line 390
   at Azure.Functions.Cli.ConsoleApp.RunAsync[T](String[] args, IContainer container) in D:\a\_work\1\s\src\Azure.Functions.Cli\ConsoleApp.cs:line 64
[2023-12-12T11:20:06.805Z] Host startup operation has been canceled
[2023-12-12T11:20:06.805Z] Initialization cancellation requested by runtime.
[2023-12-12T11:20:06.807Z] Stopping host...
[2023-12-12T11:20:06.807Z] Host shutdown completed.

Known workarounds

None found yet.

Contents of the requirements.txt file:

Provide the requirements.txt file to help us find out module related issues.
azure-functions

Related information

Provide any related information

This is on a clean MacOS 13.6 build using homebrew.

bhagyshricompany commented 6 months ago

Thanks for reporting will check and update. pls share function invocation id,timestamp,region etc.

vrdmr commented 6 months ago

Can you share the work load that your function app is doing? The host starts the Python worker and if the initialization doesn't complete within 5 seconds, then the timeout occurs.

Initialization comprises of worker initialization, function being indexed (for V2 model) and loading of functions (V1 model). And if all the operations do not complete within the timeout period, this gets caused.

rich-sykes commented 6 months ago

Thank you for the response @vrdmr, to simplify debugging even if I use the example here docs. When pushed Az the function app runs fine online so I confident the workload might not be the cause.

func new --template "Http Trigger" --name MyHttpTrigger

Using V2 model:

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

Add a simple http trigger:

import azure.functions as func
import datetime
import json
import logging

app = func.FunctionApp()

@app.route(route="MyHttpTrigger", auth_level=func.AuthLevel.ANONYMOUS)
def MyHttpTrigger(req: func.HttpRequest) -> func.HttpResponse:
    logging.info('Python HTTP trigger function processed a request.')

    name = req.params.get('name')
    if not name:
        try:
            req_body = req.get_json()
        except ValueError:
            pass
        else:
            name = req_body.get('name')

    if name:
        return func.HttpResponse(f"Hello, {name}. This HTTP triggered function executed successfully.")
    else:
        return func.HttpResponse(
             "This HTTP triggered function executed successfully. Pass a name in the query string or in the request body for a personalized response.",
             status_code=200
        )
rich-sykes commented 5 months ago

@bhagyshricompany @vrdmr - this was actually a security agent running on the MacBook which was blocking the gRPC from initialising. Thank you for the support.