search

microsoft / vscode-azurefunctions

Azure Functions extension for VS Code
https://marketplace.visualstudio.com/items?itemName=ms-azuretools.vscode-azurefunctions
MIT License
291 stars 133 forks source link

Host auto-restart on save closes debug session #781

Closed jeffhollan closed 4 months ago

jeffhollan commented 5 years ago

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 commented 5 years ago

This is being tracked in the functions host: https://github.com/Azure/azure-functions-host/issues/3543

FISHMANPET commented 5 years ago

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 commented 5 years ago

@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 #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": "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": "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": "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": "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 [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 [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 commented 4 years ago

Could be related: https://github.com/microsoft/vscode/issues/40917

osbornm commented 4 years ago

Do we have any idea when this will be worked on? from a developer's perspective this makes having in type of serious flow impossible.

EDIT for those that come across this issue while you can't debug if you run func host start that will correctly watch and reload. No Debugging but it's better than restarting all the time.

KarFan-FS commented 4 years ago

I would also like an ETA please, like @osbornm. For me, workflow with AzFunc is unbearable.

Thank you for all your hard work, devs!

ejizba commented 4 years ago

No ETA from VS Code's side. Still blocked on https://github.com/Azure/azure-functions-host/issues/3543

For more details, you can set "azureFunctions.stopFuncTaskPostDebug" to "false", which will prevent the logs from disappearing after you do a file change. You can see that the func cli is running into problems attempting to restart and eventually just stops itself.

[8/12/2020 6:05:13 PM] Starting inspector on 127.0.0.1:9229 failed: address already in use
[8/12/2020 6:05:13 PM] Starting worker process with FileName:node WorkingDirectory:/Users/erijiz/TestRepos/js6 Arguments: --inspect=9229 "/usr/local/Cellar/azure-functions-core-tools@3/3.0.2750/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 50183 --workerId ab8becc1-4323-4ff1-a283-c2694318e610 --requestId 9dcd9566-3550-4432-ad51-e2174af3d6b8 --grpcMaxMessageLength 2147483647
[8/12/2020 6:05:13 PM] node process with Id=75852 started
[8/12/2020 6:05:13 PM] Starting inspector on 127.0.0.1:9229 failed: address already in use
[8/12/2020 6:05:13 PM] Starting worker process with FileName:node WorkingDirectory:/Users/erijiz/TestRepos/js6 Arguments: --inspect=9229 "/usr/local/Cellar/azure-functions-core-tools@3/3.0.2750/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 50183 --workerId 236c6158-407e-486c-824e-c21f4f920fd4 --requestId ddac141b-4517-4ca1-b66e-682ae0d7513c --grpcMaxMessageLength 2147483647
[8/12/2020 6:05:13 PM] node process with Id=75853 started
[8/12/2020 6:05:13 PM] Starting inspector on 127.0.0.1:9229 failed: address already in use
[8/12/2020 6:05:13 PM] Exceeded language worker restart retry count for runtime:node. Shutting down and proactively recycling the Functions Host to recover
[8/12/2020 6:05:13 PM] Stopping host...
[8/12/2020 6:05:13 PM] Stopping JobHost
[8/12/2020 6:05:13 PM] Job host stopped
[8/12/2020 6:05:13 PM] Host restarted.
[8/12/2020 6:05:13 PM] Stopping JobHost
[8/12/2020 6:05:13 PM] Job host stopped
[8/12/2020 6:05:13 PM] Host shutdown completed.

With that in mind, not much we can do other than bother the Functions team. Per this comment seems like they're aware of the problem and have looked into it, but it's not an easy thing to fix.

alexweininger commented 3 years ago

For anyone still trying to get this work on Mac, I got it to work using the "restart" property in the task and with the following arguments:

func start --javascript --language-worker -- "--inspect=9229"

Launch.json

{
    "name": "Debug Azure Functions API",
    "type": "node",
    "request": "attach",
    "port": 9229,
    "restart": true
}

edit: found another person who used this workaround/fix

PCOffline commented 2 years ago

Hey, bumping this as I'd love to see this getting solved

trevrobwhite commented 1 year ago

Is there any update on this?

PCOffline commented 1 year ago

Hey, this issue is better covered at https://github.com/Azure/azure-functions-core-tools/issues/1239. With this solution being the current prime workaround. My team has been using it for a while now and it's a huge time-saver and seems stable 90% of the time.