Azure / Azure/azure-functions-host
StopApplication delayed until DelayUntilFunctionDispatcherInitializedOrShutdown times out
- Dominant language
- C#
- Stars
- 2k
- Forks
- 482
- Avg merge
- 2d 12h
- Merged PRs (30d)
- 38
Description
Application shutdown from [RpcFunctionInvocationDispatcher here](https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script/Workers/Rpc/FunctionRegistration/RpcFunctionInvocationDispatcher.cs#L367) does not cause the host to shut down. ~4 minutes later, we see a shutdown from [worker function invoker here](https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script/Description/Workers/WorkerFunctionInvoker.cs#L108)
```
[3/9/2020 11:38:27 PM] Exceeded language worker restart retry count for runtime:python. Shutting down Functions Host
Application is shutting down...
[3/9/2020 11:42:45 PM] Final functionDispatcher state: WorkerProcessRestarting. Initialization timed out and host is shutting down
```
Reported by @cecilphillip while investigating this issue: https://github.com/Azure/azure-functions-python-worker/issues/607
Appears that ordering may be an issue if shut down is called during initialization? Although I'm not sure.
cc @yojagad, @pragnagopa, @fabiocav
Full logs here:
Logs
```
> Executing task: . .venv/bin/activate && func host start <
Found Python version 3.7.5 (python).
%%%%%%
%%%%%%
@ %%%%%% @
@@ %%%%%% @@
@@@ %%%%%%%%%%% @@@
@@ %%%%%%%%%% @@
@@ %%%% @@
@@ %%% @@
@@ %% @@
%%
%
Azure Functions Core Tools (3.0.2245 Commit hash: 1d094e2f3ef79b9a478a1621ea7ec3f93ac1910d)
Function Runtime Version: 3.0.13139.0
source /Users/cecilphillip/Desktop/nasapod/.venv/bin/activate
[3/9/2020 11:38:25 PM] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:java
[3/9/2020 11:38:25 PM] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:powershell
[3/9/2020 11:38:25 PM] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:node
[3/9/2020 11:38:25 PM] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: 'e6456eb9-c7f6-47e8-b9dd-dd18a3fe457d'
[3/9/2020 11:38:25 PM] Reading host configuration file '/Users/cecilphillip/Desktop/nasapod/host.json'
[3/9/2020 11:38:25 PM] Host configuration file read:
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "version": "2.0",
[3/9/2020 11:38:25 PM] "extensionBundle": {
[3/9/2020 11:38:25 PM] "id": "Microsoft.Azure.Functions.ExtensionBundle",
[3/9/2020 11:38:25 PM] "version": "[1.*, 2.0.0)"
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] Reading functions metadata
[3/9/2020 11:38:25 PM] 1 functions found
[3/9/2020 11:38:25 PM] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /var/folders/9h/zk9td27j2h72gr2rd_xrq64w0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle
[3/9/2020 11:38:25 PM] Found a matching extension bundle at /var/folders/9h/zk9td27j2h72gr2rd_xrq64w0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[3/9/2020 11:38:25 PM] 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
[3/9/2020 11:38:25 PM] Skipping bundle download since it already exists at path /var/folders/9h/zk9td27j2h72gr2rd_xrq64w0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[3/9/2020 11:38:25 PM] Loading Extention bundle from /var/folders/9h/zk9td27j2h72gr2rd_xrq64w0000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[3/9/2020 11:38:25 PM] Initializing Warmup Extension.
[3/9/2020 11:38:25 PM] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:java
[3/9/2020 11:38:25 PM] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:powershell
[3/9/2020 11:38:25 PM] FUNCTIONS_WORKER_RUNTIME set to python. Skipping WorkerConfig for language:node
[3/9/2020 11:38:25 PM] Initializing Host. OperationId: 'e6456eb9-c7f6-47e8-b9dd-dd18a3fe457d'.
[3/9/2020 11:38:25 PM] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=e6456eb9-c7f6-47e8-b9dd-dd18a3fe457d
[3/9/2020 11:38:25 PM] LoggerFilterOptions
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "MinLevel": "None",
[3/9/2020 11:38:25 PM] "Rules": [
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "ProviderName": null,
[3/9/2020 11:38:25 PM] "CategoryName": null,
[3/9/2020 11:38:25 PM] "LogLevel": null,
[3/9/2020 11:38:25 PM] "Filter": "b__0"
[3/9/2020 11:38:25 PM] },
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[3/9/2020 11:38:25 PM] "CategoryName": null,
[3/9/2020 11:38:25 PM] "LogLevel": "None",
[3/9/2020 11:38:25 PM] "Filter": null
[3/9/2020 11:38:25 PM] },
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[3/9/2020 11:38:25 PM] "CategoryName": null,
[3/9/2020 11:38:25 PM] "LogLevel": null,
[3/9/2020 11:38:25 PM] "Filter": "b__0"
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] ]
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] FunctionResultAggregatorOptions
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "BatchSize": 1000,
[3/9/2020 11:38:25 PM] "FlushTimeout": "00:00:30",
[3/9/2020 11:38:25 PM] "IsEnabled": true
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] SingletonOptions
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "LockPeriod": "00:00:15",
[3/9/2020 11:38:25 PM] "ListenerLockPeriod": "00:00:15",
[3/9/2020 11:38:25 PM] "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[3/9/2020 11:38:25 PM] "LockAcquisitionPollingInterval": "00:00:05",
[3/9/2020 11:38:25 PM] "ListenerLockRecoveryPollingInterval": "00:01:00"
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] HttpOptions
[3/9/2020 11:38:25 PM] {
[3/9/2020 11:38:25 PM] "DynamicThrottlesEnabled": false,
[3/9/2020 11:38:25 PM] "MaxConcurrentRequests": -1,
[3/9/2020 11:38:25 PM] "MaxOutstandingRequests": -1,
[3/9/2020 11:38:25 PM] "RoutePrefix": "api"
[3/9/2020 11:38:25 PM] }
[3/9/2020 11:38:25 PM] Starting JobHost
[3/9/2020 11:38:25 PM] Starting Host (HostId=apexmacbook2018-984030709, InstanceId=26fa1eeb-1d6e-4fb7-9692-e2f31319c92d, Version=3.0.13139.0, ProcessId=37774, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[3/9/2020 11:38:25 PM] Loading functions metadata
[3/9/2020 11:38:25 PM] 1 functions loaded
[3/9/2020 11:38:25 PM] Loading proxies metadata
[3/9/2020 11:38:25 PM] Initializing Azure Function proxies
[3/9/2020 11:38:26 PM] 0 proxies loaded
[3/9/2020 11:38:26 PM] Starting worker process:python /Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools@3/3.0.2245/workers/python/3.7/OSX/X64/worker.py" --host 127.0.0.1 --port 60356 --workerId f50669ab-69c6-4b4c-86f3-aa1329c45485 --requestId 53ecef63-bcf7-4bc4-a85f-efabb5d20b8d --grpcMaxMessageLength 134217728
[3/9/2020 11:38:26 PM] python process with Id=37851 started
[3/9/2020 11:38:26 PM] Generating 1 job function(s)
[3/9/2020 11:38:26 PM] Found the following functions:
[3/9/2020 11:38:26 PM] Host.Functions.podtrigger
[3/9/2020 11:38:26 PM]
[3/9/2020 11:38:26 PM] Initializing function HTTP routes
[3/9/2020 11:38:26 PM] No HTTP routes mapped
[3/9/2020 11:38:26 PM]
[3/9/2020 11:38:26 PM] Host initialized (503ms)
[3/9/2020 11:38:26 PM] Executing 'Functions.podtrigger' (Reason='Timer fired at 2020-03-09T19:38:26.5147620-04:00', Id=6c182336-30b1-4886-a394-068127498b50)
[3/9/2020 11:38:26 PM] Trigger Details: UnscheduledInvocationReason: IsPastDue, OriginalSchedule: 2020-03-09T19:17:00.0000000-04:00
[3/9/2020 11:38:26 PM] Starting worker process:python /Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools@3/3.0.2245/workers/python/3.7/OSX/X64/worker.py" --host 127.0.0.1 --port 60356 --workerId e36c3bc2-45b3-4afe-91c4-ada21c224f0b --requestId cdbd5716-df93-439d-9e1a-e5abcda1b7be --grpcMaxMessageLength 134217728
[3/9/2020 11:38:26 PM] python process with Id=37860 started
[3/9/2020 11:38:27 PM] Starting worker process:python /Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools@3/3.0.2245/workers/python/3.7/OSX/X64/worker.py" --host 127.0.0.1 --port 60356 --workerId d9131e06-6649-4c01-aef1-524762e336e7 --requestId 20da3d2f-b59e-4b55-8f1d-4be495e0559c --grpcMaxMessageLength 134217728
[3/9/2020 11:38:27 PM] python process with Id=37869 started
[3/9/2020 11:38:27 PM] Exceeded language worker restart retry count for runtime:python. Shutting down Functions Host
Application is shutting down...
[3/9/2020 11:42:45 PM] Final functionDispatcher state: WorkerProcessRestarting. Initialization timed out and host is shutting down
[3/9/2020 11:42:45 PM] Executed 'Functions.podtrigger' (Failed, Id=6c182336-30b1-4886-a394-068127498b50)
[3/9/2020 11:42:45 PM] System.Private.CoreLib: Exception while executing function: Functions.podtrigger. Microsoft.Azure.WebJobs.Script: Did not find any initialized language workers.
[3/9/2020 11:42:45 PM] The next 5 occurrences of the 'podtrigger' schedule (Cron: '0 * * * * *') will be:
[3/9/2020 11:42:45 PM] 03/09/2020 19:43:00-04:00 (03/09/2020 23:43:00Z)
[3/9/2020 11:42:45 PM] 03/09/2020 19:44:00-04:00 (03/09/2020 23:44:00Z)
[3/9/2020 11:42:45 PM] 03/09/2020 19:45:00-04:00 (03/09/2020 23:45:00Z)
[3/9/2020 11:42:45 PM] 03/09/2020 19:46:00-04:00 (03/09/2020 23:46:00Z)
[3/9/2020 11:42:45 PM] 03/09/2020 19:47:00-04:00 (03/09/2020 23:47:00Z)
[3/9/2020 11:42:45 PM]
[3/9/2020 11:42:45 PM] Executing 'Functions.podtrigger' (Reason='Timer fired at 2020-03-09T19:42:45.6611450-04:00', Id=20b3338e-c719-46ee-939f-81e8a53f17ee)
[3/9/2020 11:42:45 PM] Host started (259786ms)
[3/9/2020 11:42:45 PM] Job host started
[3/9/2020 11:42:45 PM] Traceback (most recent call last):
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.pyenv/versions/3.7.5/lib/python3.7/runpy.py", line 193, in _run_module_as_main
[3/9/2020 11:42:45 PM] "__main__", mod_spec)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.pyenv/versions/3.7.5/lib/python3.7/runpy.py", line 85, in _run_code
[3/9/2020 11:42:45 PM] exec(code, run_globals)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/__main__.py", line 45, in
[3/9/2020 11:42:45 PM] cli.main()
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 361, in main
[3/9/2020 11:42:45 PM] run()
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 189, in run_file
[3/9/2020 11:42:45 PM] setup_debug_server(options.target)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 182, in setup_debug_server
[3/9/2020 11:42:45 PM] debug(address=options, multiprocess=options)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/__init__.py", line 81, in enable_attach
[3/9/2020 11:42:45 PM] return api.enable_attach(address, log_dir)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 75, in debug
[3/9/2020 11:42:45 PM] raise log.exception("{0}() failed:", func.__name__, level="info")
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 73, in debug
[3/9/2020 11:42:45 PM] return func(start_patterns, end_patterns)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 167, in enable_attach
[3/9/2020 11:42:45 PM] raise RuntimeError(str(endpoints["error"]))
[3/9/2020 11:42:45 PM] RuntimeError: Can't listen for IDE connections: [Errno 48] Address already in use
[3/9/2020 11:42:45 PM] Traceback (most recent call last):
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.pyenv/versions/3.7.5/lib/python3.7/runpy.py", line 193, in _run_module_as_main
[3/9/2020 11:42:45 PM] "__main__", mod_spec)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.pyenv/versions/3.7.5/lib/python3.7/runpy.py", line 85, in _run_code
[3/9/2020 11:42:45 PM] exec(code, run_globals)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/__main__.py", line 45, in
[3/9/2020 11:42:45 PM] cli.main()
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 361, in main
[3/9/2020 11:42:45 PM] run()
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 189, in run_file
[3/9/2020 11:42:45 PM] setup_debug_server(options.target)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 182, in setup_debug_server
[3/9/2020 11:42:45 PM] debug(address=options, multiprocess=options)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/__init__.py", line 81, in enable_attach
[3/9/2020 11:42:45 PM] return api.enable_attach(address, log_dir)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 75, in debug
[3/9/2020 11:42:45 PM] raise log.exception("{0}() failed:", func.__name__, level="info")
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 73, in debug
[3/9/2020 11:42:45 PM] return func(start_patterns, end_patterns)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 167, in enable_attach
[3/9/2020 11:42:45 PM] raise RuntimeError(str(endpoints["error"]))
[3/9/2020 11:42:45 PM] RuntimeError: Can't listen for IDE connections: [Errno 48] Address already in use
[3/9/2020 11:42:45 PM] Traceback (most recent call last):
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.pyenv/versions/3.7.5/lib/python3.7/runpy.py", line 193, in _run_module_as_main
[3/9/2020 11:42:45 PM] "__main__", mod_spec)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.pyenv/versions/3.7.5/lib/python3.7/runpy.py", line 85, in _run_code
[3/9/2020 11:42:45 PM] exec(code, run_globals)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/__main__.py", line 45, in
[3/9/2020 11:42:45 PM] cli.main()
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 361, in main
[3/9/2020 11:42:45 PM] run()
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 189, in run_file
[3/9/2020 11:42:45 PM] setup_debug_server(options.target)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/cli.py", line 182, in setup_debug_server
[3/9/2020 11:42:45 PM] debug(address=options, multiprocess=options)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/__init__.py", line 81, in enable_attach
[3/9/2020 11:42:45 PM] return api.enable_attach(address, log_dir)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 75, in debug
[3/9/2020 11:42:45 PM] raise log.exception("{0}() failed:", func.__name__, level="info")
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 73, in debug
[3/9/2020 11:42:45 PM] return func(start_patterns, end_patterns)
[3/9/2020 11:42:45 PM] File "/Users/cecilphillip/.vscode/extensions/ms-python.python-2020.2.64397/pythonFiles/lib/python/new_ptvsd/no_wheels/ptvsd/../ptvsd/server/api.py", line 167, in enable_attach
[3/9/2020 11:42:45 PM] raise RuntimeError(str(endpoints["error"]))
[3/9/2020 11:42:45 PM] RuntimeError: Can't listen for IDE connections: [Errno 48] Address already in use
Hosting environment: Production
Content root path: /Users/cecilphillip/Desktop/nasapod
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.
[3/9/2020 11:42:46 PM] Stopping host...
[3/9/2020 11:42:46 PM] Stopping JobHost
[3/9/2020 11:42:46 PM] Job host stopped
[3/9/2020 11:42:46 PM] Host shutdown completed.
Terminal will be reused by tasks, press any key to close it.
```
Contributor guide
Assessment
This issue has not been assessed yet.