Host auto-restart on save closes debug session

[jeffhollan]

Feature Request:

The azure functions host will automatically detect file changes and reload. This is nice for javascript where you can make a quick edit in code and have host pick it up right away. However in VS Code the debug session terminates somewhere in this process. Not a huge deal but would be nice if the file watch and host restart could maintain a debug session. May include an ask on restart behavior for azure/azure-functions-core-tools

Extension version: 0.12.0
VS Code version: Code - Insiders 1.29.0-insider (d43f6cb9947c57a3254b556e69aeacc2b2025184, 2018-11-02T15:50:03.156Z)
OS version: Darwin x64 18.2.0

[ejizba]

This is being tracked in the functions host: Azure/azure-functions-host#3543

[FISHMANPET]

It's not super clear to me from reading the bugs in azure-functions-host, but I think there is a difference in behavior in vscode somehow.

I'm working on Python functions, and as this bug and the attached external bug says, when I change one of my function files the session ends.

However I can run the same command in a terminal (in this case bash in WSL): (. .venv/bin/activate && func host start)

When I do that, if I update a function file, the func command auto restarts correctly. So as far as I can tell the function tools are operating correctly (at least for me, with Python) but the extension isn't behaving correctly when the host restarts.

Another thing about the current behavior. It looks like what's happening when a debug session is intered is pip install is run, and then in a new terminal the func command is run. In addition to this method not handling the restart correctly, the new terminal goes away when the func command restarts (and this may be the root of the issue), which means all the output from func goes away as well.

I discovered this because my function was writing files into the function directory (not knowing this would restart the function host) but to me it just looked like my code had made the function host crash. it wasn't until I ran it outside of vscode that I saw that my file changes were causing the restart.

[ejizba]

@FISHMANPET there's definitely differences in behavior for VS Code. Here's what we do:

1. We set an environment variable telling the func cli what arguments to use to make the python process debug-able (If you search the logs for ptvsd_launcher.py, that's what I'm talking about)
2. We stop the func task after the debug session ends (which happens automatically when the job host stops). I've added a setting to control this behavior in Add a setting to control terminating func host #1565

If I run func host start in the terminal, it successfully restarts after a file save as you described. However, if I leverage the setting I just added, I can now see the full logs after a file save while in debug mode and it fails to restart the host with this error:

[10/9/19 6:21:19 PM] Starting worker process failed
[10/9/19 6:21:19 PM] The operation has timed out.

Full logs

> Executing task: . .venv/bin/activate && func host start <


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

Azure Functions Core Tools (2.7.1704 Commit hash: fbab3b9c1de5ab95e3b4b6a471ead62c4f37e89c)
Function Runtime Version: 2.0.12742.0
source /Users/erijiz/TestRepos/py5/.venv/bin/activate
[10/9/19 6:20:08 PM] Building host: startup suppressed:False, configuration suppressed: False
[10/9/19 6:20:09 PM] Initializing Host.
[10/9/19 6:20:09 PM] Host initialization: ConsecutiveErrors=0, StartupCount=1
[10/9/19 6:20:09 PM] LoggerFilterOptions
[10/9/19 6:20:09 PM] {
[10/9/19 6:20:09 PM]   "MinLevel": "None",
[10/9/19 6:20:09 PM]   "Rules": [
[10/9/19 6:20:09 PM]     {
[10/9/19 6:20:09 PM]       "ProviderName": null,
[10/9/19 6:20:09 PM]       "CategoryName": null,
[10/9/19 6:20:09 PM]       "LogLevel": null,
[10/9/19 6:20:09 PM]       "Filter": "<AddFilter>b__0"
[10/9/19 6:20:09 PM]     },
[10/9/19 6:20:09 PM]     {
[10/9/19 6:20:09 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[10/9/19 6:20:09 PM]       "CategoryName": null,
[10/9/19 6:20:09 PM]       "LogLevel": "None",
[10/9/19 6:20:09 PM]       "Filter": null
[10/9/19 6:20:09 PM]     },
[10/9/19 6:20:09 PM]     {
[10/9/19 6:20:09 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[10/9/19 6:20:09 PM]       "CategoryName": null,
[10/9/19 6:20:09 PM]       "LogLevel": null,
[10/9/19 6:20:09 PM]       "Filter": "<AddFilter>b__0"
[10/9/19 6:20:09 PM]     }
[10/9/19 6:20:09 PM]   ]
[10/9/19 6:20:09 PM] }
[10/9/19 6:20:09 PM] FunctionResultAggregatorOptions
[10/9/19 6:20:09 PM] {
[10/9/19 6:20:09 PM]   "BatchSize": 1000,
[10/9/19 6:20:09 PM]   "FlushTimeout": "00:00:30",
[10/9/19 6:20:09 PM]   "IsEnabled": true
[10/9/19 6:20:09 PM] }
[10/9/19 6:20:09 PM] SingletonOptions
[10/9/19 6:20:09 PM] {
[10/9/19 6:20:09 PM]   "LockPeriod": "00:00:15",
[10/9/19 6:20:09 PM]   "ListenerLockPeriod": "00:00:15",
[10/9/19 6:20:09 PM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[10/9/19 6:20:09 PM]   "LockAcquisitionPollingInterval": "00:00:05",
[10/9/19 6:20:09 PM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[10/9/19 6:20:09 PM] }
[10/9/19 6:20:09 PM] HttpOptions
[10/9/19 6:20:09 PM] {
[10/9/19 6:20:09 PM]   "DynamicThrottlesEnabled": false,
[10/9/19 6:20:09 PM]   "MaxConcurrentRequests": -1,
[10/9/19 6:20:09 PM]   "MaxOutstandingRequests": -1,
[10/9/19 6:20:09 PM]   "RoutePrefix": "api"
[10/9/19 6:20:09 PM] }
[10/9/19 6:20:09 PM] Starting JobHost
[10/9/19 6:20:09 PM] Starting Host (HostId=ericsmbp-1825278939, InstanceId=68bc0aee-b4bf-438f-af80-6368d588e423, Version=2.0.12742.0, ProcessId=29596, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=)
[10/9/19 6:20:09 PM] Loading functions metadata
[10/9/19 6:20:09 PM] 1 functions loaded
[10/9/19 6:20:09 PM] Loading proxies metadata
[10/9/19 6:20:09 PM] Initializing Azure Function proxies
[10/9/19 6:20:09 PM] 0 proxies loaded
[10/9/19 6:20:09 PM] Starting language worker process:python  /Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools/2.7.1704/workers/python/worker.py" --host 127.0.0.1 --port 61133 --workerId 2be82a79-7af8-4d80-897b-26dba8c6970e --requestId d49a9b31-add7-4ee2-92af-a4831664cbcc --grpcMaxMessageLength 134217728
[10/9/19 6:20:09 PM] python process with Id=29600 started
[10/9/19 6:20:09 PM] Generating 1 job function(s)
[10/9/19 6:20:09 PM] Found the following functions:
[10/9/19 6:20:09 PM] Host.Functions.HttpTrigger
[10/9/19 6:20:09 PM] 
[10/9/19 6:20:09 PM] Host initialized (600ms)
[10/9/19 6:20:09 PM] Host started (616ms)
[10/9/19 6:20:09 PM] Job host started
Hosting environment: Production
Content root path: /Users/erijiz/TestRepos/py5
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.

Http Functions:

        HttpTrigger: [GET,POST] http://localhost:7071/api/HttpTrigger

[10/9/19 6:20:14 PM] Host lock lease acquired by instance ID '0000000000000000000000005B68C9AF'.
[10/9/19 6:20:15 PM]  INFO: Starting Azure Functions Python Worker.
[10/9/19 6:20:15 PM]  INFO: Worker ID: 2be82a79-7af8-4d80-897b-26dba8c6970e, Request ID: d49a9b31-add7-4ee2-92af-a4831664cbcc, Host Address: 127.0.0.1:61133
[10/9/19 6:20:15 PM]  INFO: Successfully opened gRPC channel to 127.0.0.1:61133
[10/9/19 6:20:15 PM]  INFO: Received WorkerInitRequest, request ID d49a9b31-add7-4ee2-92af-a4831664cbcc
[10/9/19 6:20:15 PM]  INFO: Received FunctionLoadRequest, request ID: d49a9b31-add7-4ee2-92af-a4831664cbcc, function ID: fdf7b953-a5e3-421a-a980-b39762be78ec
[10/9/19 6:20:15 PM]  INFO: Successfully processed FunctionLoadRequest, request ID: d49a9b31-add7-4ee2-92af-a4831664cbcc, function ID: fdf7b953-a5e3-421a-a980-b39762be78ec
[10/9/19 6:20:18 PM] Restarting host.
[10/9/19 6:20:18 PM] Building host: startup suppressed:False, configuration suppressed: False
[10/9/19 6:20:19 PM] Initializing Host.
[10/9/19 6:20:19 PM] Host initialization: ConsecutiveErrors=0, StartupCount=2
[10/9/19 6:20:19 PM] LoggerFilterOptions
[10/9/19 6:20:19 PM] {
[10/9/19 6:20:19 PM]   "MinLevel": "None",
[10/9/19 6:20:19 PM]   "Rules": [
[10/9/19 6:20:19 PM]     {
[10/9/19 6:20:19 PM]       "ProviderName": null,
[10/9/19 6:20:19 PM]       "CategoryName": null,
[10/9/19 6:20:19 PM]       "LogLevel": null,
[10/9/19 6:20:19 PM]       "Filter": "<AddFilter>b__0"
[10/9/19 6:20:19 PM]     },
[10/9/19 6:20:19 PM]     {
[10/9/19 6:20:19 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[10/9/19 6:20:19 PM]       "CategoryName": null,
[10/9/19 6:20:19 PM]       "LogLevel": "None",
[10/9/19 6:20:19 PM]       "Filter": null
[10/9/19 6:20:19 PM]     },
[10/9/19 6:20:19 PM]     {
[10/9/19 6:20:19 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[10/9/19 6:20:19 PM]       "CategoryName": null,
[10/9/19 6:20:19 PM]       "LogLevel": null,
[10/9/19 6:20:19 PM]       "Filter": "<AddFilter>b__0"
[10/9/19 6:20:19 PM]     }
[10/9/19 6:20:19 PM]   ]
[10/9/19 6:20:19 PM] }
[10/9/19 6:20:19 PM] FunctionResultAggregatorOptions
[10/9/19 6:20:19 PM] {
[10/9/19 6:20:19 PM]   "BatchSize": 1000,
[10/9/19 6:20:19 PM]   "FlushTimeout": "00:00:30",
[10/9/19 6:20:19 PM]   "IsEnabled": true
[10/9/19 6:20:19 PM] }
[10/9/19 6:20:19 PM] SingletonOptions
[10/9/19 6:20:19 PM] {
[10/9/19 6:20:19 PM]   "LockPeriod": "00:00:15",
[10/9/19 6:20:19 PM]   "ListenerLockPeriod": "00:00:15",
[10/9/19 6:20:19 PM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[10/9/19 6:20:19 PM]   "LockAcquisitionPollingInterval": "00:00:05",
[10/9/19 6:20:19 PM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[10/9/19 6:20:19 PM] }
[10/9/19 6:20:19 PM] HttpOptions
[10/9/19 6:20:19 PM] {
[10/9/19 6:20:19 PM]   "DynamicThrottlesEnabled": false,
[10/9/19 6:20:19 PM]   "MaxConcurrentRequests": -1,
[10/9/19 6:20:19 PM]   "MaxOutstandingRequests": -1,
[10/9/19 6:20:19 PM]   "RoutePrefix": "api"
[10/9/19 6:20:19 PM] }
[10/9/19 6:20:19 PM] Starting JobHost
[10/9/19 6:20:19 PM] Starting Host (HostId=ericsmbp-1825278939, InstanceId=bd63309e-584c-49b8-928c-4a5484f6249b, Version=2.0.12742.0, ProcessId=29596, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=)
[10/9/19 6:20:19 PM] Loading functions metadata
[10/9/19 6:20:19 PM] 1 functions loaded
[10/9/19 6:20:19 PM] Loading proxies metadata
[10/9/19 6:20:19 PM] Initializing Azure Function proxies
[10/9/19 6:20:19 PM] 0 proxies loaded
[10/9/19 6:20:19 PM] Starting language worker process:python  /Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools/2.7.1704/workers/python/worker.py" --host 127.0.0.1 --port 61133 --workerId 15dd63a1-ca63-45c2-9108-0d94c3646a71 --requestId 2457f6ee-b1a2-450d-b9cb-a2608083174e --grpcMaxMessageLength 134217728
[10/9/19 6:20:19 PM] python process with Id=29617 started
[10/9/19 6:20:19 PM] Generating 1 job function(s)
[10/9/19 6:20:19 PM] Found the following functions:
[10/9/19 6:20:19 PM] Host.Functions.HttpTrigger
[10/9/19 6:20:19 PM] 
[10/9/19 6:20:19 PM] Host initialized (40ms)
[10/9/19 6:20:19 PM] Host started (41ms)
[10/9/19 6:20:19 PM] Job host started
[10/9/19 6:20:19 PM] Traceback (most recent call last):
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/ptvsd_launcher.py", line 43, in <module>
[10/9/19 6:20:19 PM]     main(ptvsdArgs)
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/__main__.py", line 432, in main
[10/9/19 6:20:19 PM]     run()
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/__main__.py", line 300, in run_file
[10/9/19 6:20:19 PM]     setup_connection()
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/__main__.py", line 293, in setup_connection
[10/9/19 6:20:19 PM]     daemon = ptvsd._remote.enable_attach(addr)
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/_remote.py", line 79, in enable_attach
[10/9/19 6:20:19 PM]     patch_multiprocessing=ptvsd.options.multiprocess)
[10/9/19 6:20:19 PM]     wait_for_ready_to_run,
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/_vendored/pydevd/pydevd.py", line 2179, in settrace
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/_vendored/pydevd/pydevd.py", line 2230, in _locked_settrace
[10/9/19 6:20:19 PM]     debugger.connect(host, port)  # Note: connect can raise error.
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/_vendored/pydevd/pydevd.py", line 1060, in connect
[10/9/19 6:20:19 PM]     s = start_client(host, port)
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/pydevd_hooks.py", line 136, in _start_client
[10/9/19 6:20:19 PM]     return start_client(daemon, h, p)
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/_remote.py", line 62, in <lambda>
[10/9/19 6:20:19 PM]     start_client=(lambda daemon, h, port: start_daemon()),
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/_remote.py", line 50, in start_daemon
[10/9/19 6:20:19 PM]     _, next_session = daemon.start_server(addr=(host, port))
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/daemon.py", line 161, in start_server
[10/9/19 6:20:19 PM]     self._server = create_server(addr.host, addr.port)
[10/9/19 6:20:19 PM]   File "/Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/lib/python/old_ptvsd/ptvsd/socket.py", line 79, in create_server
[10/9/19 6:20:19 PM]     server.bind((host, port))
[10/9/19 6:20:19 PM] OSError: [Errno 48] Address already in use
[10/9/19 6:20:19 PM] Host restarted.
[10/9/19 6:20:19 PM] Stopping JobHost
[10/9/19 6:20:19 PM] Job host stopped
[10/9/19 6:20:19 PM] Starting language worker process:python  /Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools/2.7.1704/workers/python/worker.py" --host 127.0.0.1 --port 61133 --workerId fb4fd7a7-f25f-4a2d-ab5d-3328ebab4501 --requestId 8ea17b50-b8a2-4bdd-a3ff-3d3909943ee8 --grpcMaxMessageLength 134217728
[10/9/19 6:20:19 PM] python process with Id=29621 started
[10/9/19 6:20:24 PM] Host lock lease acquired by instance ID '0000000000000000000000005B68C9AF'.
[10/9/19 6:21:19 PM] Starting worker process failed
[10/9/19 6:21:19 PM] The operation has timed out.
[10/9/19 6:21:19 PM] Starting language worker process:python  /Users/erijiz/.vscode/extensions/ms-python.python-2019.10.41019/pythonFiles/ptvsd_launcher.py --default --host 127.0.0.1 --port 9091 --wait "/usr/local/Cellar/azure-functions-core-tools/2.7.1704/workers/python/worker.py" --host 127.0.0.1 --port 61133 --workerId 7c48b2ec-da77-46e3-a124-1a06ea074dc3 --requestId 9f26f832-eda6-4de5-95b1-f016c192a09e --grpcMaxMessageLength 134217728
[10/9/19 6:21:19 PM] python process with Id=29631 started
[10/9/19 6:22:19 PM] Starting worker process failed
[10/9/19 6:22:19 PM] The operation has timed out.
[10/9/19 6:22:19 PM] Exceeded language worker restart retry count for runtime:python. Shutting down Functions Host
[10/9/19 6:22:19 PM] Stopping host...
[10/9/19 6:22:19 PM] Stopping JobHost
[10/9/19 6:22:19 PM] Job host stopped
[10/9/19 6:22:19 PM] Host shutdown completed.
Application is shutting down...

Terminal will be reused by tasks, press any key to close it.

This leads me to believe we still need the func cli to fix the above linked issue to get this to work fully.

[ejizba]

Could be related: microsoft/vscode#40917