Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

debug inspector fails to release port on restart #2031

Closed
andycmaj opened this issue Jun 14, 2020 · 2 comments
Closed

debug inspector fails to release port on restart #2031

andycmaj opened this issue Jun 14, 2020 · 2 comments
Milestone
Triaged

Comments

@andycmaj
Copy link

running into a problem when i have the node debugger started on port 5858 and i change a file that triggers a func process restart.

command used to run functions:

$ func host start --language-worker -- "--inspect=5858" --script-root build --javscript

specifically, after a file change triggers a restart, indicated by this:

[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/session/function.json'

... i see this appear a bunch of times:

[6/14/2020 12:57:24 AM] Job host started
[6/14/2020 12:57:24 AM] Starting inspector on 127.0.0.1:5858 failed: address already in use
[6/14/2020 12:57:24 AM] Starting worker process:node  --inspect=5858 "/Workspace/github/dig/covid-bot/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 54395 --workerId 05439bd4-5cee-40a4-8574-572394b4bb89 --requestId 0752e59a-750a-4ee0-a2a9-d08aade9f2e0 --grpcMaxMessageLength 134217728
[6/14/2020 12:57:24 AM] node process with Id=39750 started
[6/14/2020 12:57:24 AM] Starting inspector on 127.0.0.1:5858 failed: address already in use
[6/14/2020 12:57:24 AM] Starting worker process:node  --inspect=5858 "/Workspace/github/dig/covid-bot/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 54395 --workerId 94d6f016-70dc-42c4-934d-2e193b7beb8c --requestId 559065e9-3bfa-436e-a662-0e9930ea7540 --grpcMaxMessageLength 134217728
[6/14/2020 12:57:24 AM] node process with Id=39751 started
[6/14/2020 12:57:24 AM] Starting inspector on 127.0.0.1:5858 failed: address already in use
[6/14/2020 12:57:24 AM] Exceeded language worker restart retry count for runtime:node. Shutting down Functions Host

here's the full log.

╰ yarn workspace server dev:functions                                                                                  
yarn workspace v1.22.4
yarn run v1.22.4
$ func host start --language-worker -- "--inspect=5858" --script-root build --javscript

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

Azure Functions Core Tools (3.0.2534 Commit hash: bc1e9efa8fa78dd1a138dd1ac1ebef97aac8d78e)
Function Runtime Version: 3.0.13353.0
[6/14/2020 12:55:57 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:python
[6/14/2020 12:55:57 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:java
[6/14/2020 12:55:57 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:powershell
[6/14/2020 12:55:57 AM] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: 'a02edac5-e6d8-4fc2-a131-30fa84c002f8'
[6/14/2020 12:55:57 AM] Reading host configuration file '/Workspace/github/dig/covid-bot/server/build/host.json'
[6/14/2020 12:55:57 AM] Host configuration file read:
[6/14/2020 12:55:57 AM] {
[6/14/2020 12:55:57 AM]   "version": "2.0",
[6/14/2020 12:55:57 AM]   "extensionBundle": {
[6/14/2020 12:55:57 AM]     "id": "Microsoft.Azure.Functions.ExtensionBundle",
[6/14/2020 12:55:57 AM]     "version": "[1.*, 2.0.0)"
[6/14/2020 12:55:57 AM]   }
[6/14/2020 12:55:57 AM] }
[6/14/2020 12:55:57 AM] Reading functions metadata
[6/14/2020 12:55:57 AM] 6 functions found
[6/14/2020 12:55:57 AM] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle
[6/14/2020 12:55:57 AM] Found a matching extension bundle at /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[6/14/2020 12:55:57 AM] 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
[6/14/2020 12:55:57 AM] Skipping bundle download since it already exists at path /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[6/14/2020 12:55:57 AM] Loading Extention bundle from /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[6/14/2020 12:55:58 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:python
[6/14/2020 12:55:58 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:java
[6/14/2020 12:55:58 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:powershell
[6/14/2020 12:55:58 AM] Initializing Warmup Extension.
[6/14/2020 12:55:58 AM] Initializing Host. OperationId: 'a02edac5-e6d8-4fc2-a131-30fa84c002f8'.
[6/14/2020 12:55:58 AM] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=a02edac5-e6d8-4fc2-a131-30fa84c002f8
[6/14/2020 12:55:58 AM] ApplicationInsightsLoggerOptions
[6/14/2020 12:55:58 AM] {
[6/14/2020 12:55:58 AM]   "SamplingSettings": {
[6/14/2020 12:55:58 AM]     "EvaluationInterval": "00:00:15",
[6/14/2020 12:55:58 AM]     "InitialSamplingPercentage": 100.0,
[6/14/2020 12:55:58 AM]     "MaxSamplingPercentage": 100.0,
[6/14/2020 12:55:58 AM]     "MaxTelemetryItemsPerSecond": 20.0,
[6/14/2020 12:55:58 AM]     "MinSamplingPercentage": 0.1,
[6/14/2020 12:55:58 AM]     "MovingAverageRatio": 0.25,
[6/14/2020 12:55:58 AM]     "SamplingPercentageDecreaseTimeout": "00:02:00",
[6/14/2020 12:55:58 AM]     "SamplingPercentageIncreaseTimeout": "00:15:00"
[6/14/2020 12:55:58 AM]   },
[6/14/2020 12:55:58 AM]   "SamplingExcludedTypes": null,
[6/14/2020 12:55:58 AM]   "SamplingIncludedTypes": null,
[6/14/2020 12:55:58 AM]   "SnapshotConfiguration": null,
[6/14/2020 12:55:58 AM]   "EnablePerformanceCountersCollection": true,
[6/14/2020 12:55:58 AM]   "HttpAutoCollectionOptions": {
[6/14/2020 12:55:58 AM]     "EnableHttpTriggerExtendedInfoCollection": true,
[6/14/2020 12:55:58 AM]     "EnableW3CDistributedTracing": true,
[6/14/2020 12:55:58 AM]     "EnableResponseHeaderInjection": true
[6/14/2020 12:55:58 AM]   },
[6/14/2020 12:55:58 AM]   "LiveMetricsInitializationDelay": "00:00:15",
[6/14/2020 12:55:58 AM]   "EnableLiveMetrics": true,
[6/14/2020 12:55:58 AM]   "EnableDependencyTracking": true
[6/14/2020 12:55:58 AM] }
[6/14/2020 12:55:58 AM] LoggerFilterOptions
[6/14/2020 12:55:58 AM] {
[6/14/2020 12:55:58 AM]   "MinLevel": "None",
[6/14/2020 12:55:58 AM]   "Rules": [
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": null,
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": null,
[6/14/2020 12:55:58 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:55:58 AM]     },
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": "None",
[6/14/2020 12:55:58 AM]       "Filter": null
[6/14/2020 12:55:58 AM]     },
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": null,
[6/14/2020 12:55:58 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:55:58 AM]     },
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider",
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": "Trace",
[6/14/2020 12:55:58 AM]       "Filter": null
[6/14/2020 12:55:58 AM]     }
[6/14/2020 12:55:58 AM]   ]
[6/14/2020 12:55:58 AM] }
[6/14/2020 12:55:58 AM] LoggerFilterOptions
[6/14/2020 12:55:58 AM] {
[6/14/2020 12:55:58 AM]   "MinLevel": "None",
[6/14/2020 12:55:58 AM]   "Rules": [
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": null,
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": null,
[6/14/2020 12:55:58 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:55:58 AM]     },
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": "None",
[6/14/2020 12:55:58 AM]       "Filter": null
[6/14/2020 12:55:58 AM]     },
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": null,
[6/14/2020 12:55:58 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:55:58 AM]     },
[6/14/2020 12:55:58 AM]     {
[6/14/2020 12:55:58 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider",
[6/14/2020 12:55:58 AM]       "CategoryName": null,
[6/14/2020 12:55:58 AM]       "LogLevel": "Trace",
[6/14/2020 12:55:58 AM]       "Filter": null
[6/14/2020 12:55:58 AM]     }
[6/14/2020 12:55:58 AM]   ]
[6/14/2020 12:55:58 AM] }
[6/14/2020 12:55:58 AM] FunctionResultAggregatorOptions
[6/14/2020 12:55:58 AM] {
[6/14/2020 12:55:58 AM]   "BatchSize": 1000,
[6/14/2020 12:55:58 AM]   "FlushTimeout": "00:00:30",
[6/14/2020 12:55:58 AM]   "IsEnabled": true
[6/14/2020 12:55:58 AM] }
[6/14/2020 12:55:58 AM] SingletonOptions
[6/14/2020 12:55:58 AM] {
[6/14/2020 12:55:58 AM]   "LockPeriod": "00:00:15",
[6/14/2020 12:55:58 AM]   "ListenerLockPeriod": "00:00:15",
[6/14/2020 12:55:58 AM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[6/14/2020 12:55:58 AM]   "LockAcquisitionPollingInterval": "00:00:05",
[6/14/2020 12:55:58 AM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[6/14/2020 12:55:58 AM] }
[6/14/2020 12:55:58 AM] HttpOptions
[6/14/2020 12:55:58 AM] {
[6/14/2020 12:55:58 AM]   "DynamicThrottlesEnabled": false,
[6/14/2020 12:55:58 AM]   "MaxConcurrentRequests": -1,
[6/14/2020 12:55:58 AM]   "MaxOutstandingRequests": -1,
[6/14/2020 12:55:58 AM]   "RoutePrefix": ""
[6/14/2020 12:55:58 AM] }
[6/14/2020 12:55:58 AM] Starting JobHost
[6/14/2020 12:55:58 AM] Starting Host (HostId=acmbp2019-382845607, InstanceId=4b18af41-0461-4f78-979b-f30d69dd4d4c, Version=3.0.13353.0, ProcessId=38146, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[6/14/2020 12:55:58 AM] Loading functions metadata
[6/14/2020 12:55:58 AM] 6 functions loaded
[6/14/2020 12:55:58 AM] Starting worker process:node  --inspect=5858 "/Workspace/github/dig/covid-bot/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 54395 --workerId b28d214a-29c7-4752-af8b-24bf78ecc262 --requestId 643fb426-b747-4954-b65d-2bbdab926701 --grpcMaxMessageLength 134217728
[6/14/2020 12:55:58 AM] node process with Id=38147 started
[6/14/2020 12:55:58 AM] Generating 6 job function(s)
[6/14/2020 12:55:58 AM] Found the following functions:
[6/14/2020 12:55:58 AM] Host.Functions.webhook
[6/14/2020 12:55:58 AM] Host.Functions.ping
[6/14/2020 12:55:58 AM] Host.Functions.get
[6/14/2020 12:55:58 AM] Host.Functions.profile
[6/14/2020 12:55:58 AM] Host.Functions.echoSkill
[6/14/2020 12:55:58 AM] Host.Functions.session
[6/14/2020 12:55:58 AM]
[6/14/2020 12:55:58 AM] Initializing function HTTP routes
[6/14/2020 12:55:58 AM] Mapped function route '/webhook' [get,post] to 'webhook'
[6/14/2020 12:55:58 AM] Mapped function route '/ping' [get,post] to 'ping'
[6/14/2020 12:55:58 AM] Mapped function route '//' [get,post] to 'get'
[6/14/2020 12:55:58 AM] Mapped function route '/profile' [get] to 'profile'
[6/14/2020 12:55:58 AM] Mapped function route '//skill/echo' [get,post] to 'echoSkill'
[6/14/2020 12:55:58 AM] Mapped function route '/session' [get,post,options] to 'session'
[6/14/2020 12:55:58 AM]
[6/14/2020 12:55:58 AM] Host initialized (198ms)
[6/14/2020 12:55:58 AM] Host started (206ms)
[6/14/2020 12:55:58 AM] Job host started
[6/14/2020 12:55:58 AM] Debugger listening on ws://127.0.0.1:5858/e2d5722b-e72f-4227-9a0e-5303d5eea2c8
[6/14/2020 12:55:58 AM] For help, see: https://nodejs.org/en/docs/inspector
[6/14/2020 12:55:58 AM] Worker b28d214a-29c7-4752-af8b-24bf78ecc262 connecting on 127.0.0.1:54395
Hosting environment: Development
Content root path: /Workspace/github/dig/covid-bot/server/build
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.

Http Functions:

	webhook: [GET,POST] http://localhost:7071/webhook

	ping: [GET,POST] http://localhost:7071/ping

	get: [GET,POST] http://localhost:7071//

	profile: [GET] http://localhost:7071/profile

	echoSkill: [GET,POST] http://localhost:7071//skill/echo

	session: [GET,POST,OPTIONS] http://localhost:7071/session

[6/14/2020 12:56:03 AM] Host lock lease acquired by instance ID '000000000000000000000000EB726AEC'.
[6/14/2020 12:56:16 AM] Debugger attached.
[6/14/2020 12:56:23 AM] Executing HTTP request: {
[6/14/2020 12:56:23 AM]   "requestId": "0cba4c31-442f-4cb1-b287-82d05c9ee026",
[6/14/2020 12:56:23 AM]   "method": "GET",
[6/14/2020 12:56:23 AM]   "uri": "/ping"
[6/14/2020 12:56:23 AM] }
[6/14/2020 12:56:23 AM] Executing 'Functions.ping' (Reason='This function was programmatically called via the host APIs.', Id=2d31b8f7-c563-4cd4-b3d0-1445abb509b6)
[6/14/2020 12:56:25 AM] Debugger listening on ws://127.0.0.1:5858/e2d5722b-e72f-4227-9a0e-5303d5eea2c8
[6/14/2020 12:56:25 AM] For help, see: https://nodejs.org/en/docs/inspector
[6/14/2020 12:56:25 AM] Executed 'Functions.ping' (Succeeded, Id=2d31b8f7-c563-4cd4-b3d0-1445abb509b6)
[6/14/2020 12:56:25 AM] Executed HTTP request: {
[6/14/2020 12:56:25 AM]   "requestId": "0cba4c31-442f-4cb1-b287-82d05c9ee026",
[6/14/2020 12:56:25 AM]   "method": "GET",
[6/14/2020 12:56:25 AM]   "uri": "/ping",
[6/14/2020 12:56:25 AM]   "identities": [
[6/14/2020 12:56:25 AM]     {
[6/14/2020 12:56:25 AM]       "type": "WebJobsAuthLevel",
[6/14/2020 12:56:25 AM]       "level": "Admin"
[6/14/2020 12:56:25 AM]     }
[6/14/2020 12:56:25 AM]   ],
[6/14/2020 12:56:25 AM]   "status": 200,
[6/14/2020 12:56:25 AM]   "duration": 2445
[6/14/2020 12:56:25 AM] }
[6/14/2020 12:56:25 AM] Executing HTTP request: {
[6/14/2020 12:56:25 AM]   "requestId": "21aab47b-86e3-4aa7-9ecc-8258a5023c9a",
[6/14/2020 12:56:25 AM]   "method": "GET",
[6/14/2020 12:56:25 AM]   "uri": "/ping"
[6/14/2020 12:56:25 AM] }
[6/14/2020 12:56:25 AM] Executing 'Functions.ping' (Reason='This function was programmatically called via the host APIs.', Id=06a0d5d3-2645-48e8-9cac-b9a188515849)
[6/14/2020 12:56:25 AM] Executed 'Functions.ping' (Succeeded, Id=06a0d5d3-2645-48e8-9cac-b9a188515849)
[6/14/2020 12:56:25 AM] Executed HTTP request: {
[6/14/2020 12:56:25 AM]   "requestId": "21aab47b-86e3-4aa7-9ecc-8258a5023c9a",
[6/14/2020 12:56:25 AM]   "method": "GET",
[6/14/2020 12:56:25 AM]   "uri": "/ping",
[6/14/2020 12:56:25 AM]   "identities": [
[6/14/2020 12:56:25 AM]     {
[6/14/2020 12:56:25 AM]       "type": "WebJobsAuthLevel",
[6/14/2020 12:56:25 AM]       "level": "Admin"
[6/14/2020 12:56:25 AM]     }
[6/14/2020 12:56:25 AM]   ],
[6/14/2020 12:56:25 AM]   "status": 200,
[6/14/2020 12:56:25 AM]   "duration": 14
[6/14/2020 12:56:25 AM] }

======== HERE IS WHERE I CHANGED SOME FILES ==============
=============================================================


[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/host.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/echoSkill/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/get/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/host.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/echoSkill/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/get/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/ping/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/webhook/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/profile/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/session/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/ping/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/webhook/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/profile/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:22 AM] File change of type 'Changed' detected for '/Workspace/github/dig/covid-bot/server/build/session/function.json'
[6/14/2020 12:57:22 AM] Host configuration has changed. Signaling restart
[6/14/2020 12:57:23 AM] Restarting host.
[6/14/2020 12:57:23 AM] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: 'dec874b6-ad80-4401-b557-5b73ea227a4f'
[6/14/2020 12:57:23 AM] Reading host configuration file '/Workspace/github/dig/covid-bot/server/build/host.json'
[6/14/2020 12:57:23 AM] Host configuration file read:
[6/14/2020 12:57:23 AM] {
[6/14/2020 12:57:23 AM]   "version": "2.0",
[6/14/2020 12:57:23 AM]   "extensionBundle": {
[6/14/2020 12:57:23 AM]     "id": "Microsoft.Azure.Functions.ExtensionBundle",
[6/14/2020 12:57:23 AM]     "version": "[1.*, 2.0.0)"
[6/14/2020 12:57:23 AM]   }
[6/14/2020 12:57:23 AM] }
[6/14/2020 12:57:23 AM] Reading functions metadata
[6/14/2020 12:57:23 AM] 6 functions found
[6/14/2020 12:57:23 AM] Looking for extension bundle Microsoft.Azure.Functions.ExtensionBundle at /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle
[6/14/2020 12:57:23 AM] Found a matching extension bundle at /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[6/14/2020 12:57:23 AM] 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
[6/14/2020 12:57:23 AM] Skipping bundle download since it already exists at path /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[6/14/2020 12:57:23 AM] Loading Extention bundle from /var/folders/jf/bc_52gps5vb0wl3qwj0yr2440000gn/T/Functions/ExtensionBundles/Microsoft.Azure.Functions.ExtensionBundle/1.1.1
[6/14/2020 12:57:23 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:python
[6/14/2020 12:57:23 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:java
[6/14/2020 12:57:23 AM] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:powershell
[6/14/2020 12:57:23 AM] Initializing Warmup Extension.
[6/14/2020 12:57:23 AM] Initializing Host. OperationId: 'dec874b6-ad80-4401-b557-5b73ea227a4f'.
[6/14/2020 12:57:23 AM] Host initialization: ConsecutiveErrors=0, StartupCount=2, OperationId=dec874b6-ad80-4401-b557-5b73ea227a4f
[6/14/2020 12:57:24 AM] ApplicationInsightsLoggerOptions
[6/14/2020 12:57:24 AM] {
[6/14/2020 12:57:24 AM]   "SamplingSettings": {
[6/14/2020 12:57:24 AM]     "EvaluationInterval": "00:00:15",
[6/14/2020 12:57:24 AM]     "InitialSamplingPercentage": 100.0,
[6/14/2020 12:57:24 AM]     "MaxSamplingPercentage": 100.0,
[6/14/2020 12:57:24 AM]     "MaxTelemetryItemsPerSecond": 20.0,
[6/14/2020 12:57:24 AM]     "MinSamplingPercentage": 0.1,
[6/14/2020 12:57:24 AM]     "MovingAverageRatio": 0.25,
[6/14/2020 12:57:24 AM]     "SamplingPercentageDecreaseTimeout": "00:02:00",
[6/14/2020 12:57:24 AM]     "SamplingPercentageIncreaseTimeout": "00:15:00"
[6/14/2020 12:57:24 AM]   },
[6/14/2020 12:57:24 AM]   "SamplingExcludedTypes": null,
[6/14/2020 12:57:24 AM]   "SamplingIncludedTypes": null,
[6/14/2020 12:57:24 AM]   "SnapshotConfiguration": null,
[6/14/2020 12:57:24 AM]   "EnablePerformanceCountersCollection": true,
[6/14/2020 12:57:24 AM]   "HttpAutoCollectionOptions": {
[6/14/2020 12:57:24 AM]     "EnableHttpTriggerExtendedInfoCollection": true,
[6/14/2020 12:57:24 AM]     "EnableW3CDistributedTracing": true,
[6/14/2020 12:57:24 AM]     "EnableResponseHeaderInjection": true
[6/14/2020 12:57:24 AM]   },
[6/14/2020 12:57:24 AM]   "LiveMetricsInitializationDelay": "00:00:15",
[6/14/2020 12:57:24 AM]   "EnableLiveMetrics": true,
[6/14/2020 12:57:24 AM]   "EnableDependencyTracking": true
[6/14/2020 12:57:24 AM] }
[6/14/2020 12:57:24 AM] LoggerFilterOptions
[6/14/2020 12:57:24 AM] {
[6/14/2020 12:57:24 AM]   "MinLevel": "None",
[6/14/2020 12:57:24 AM]   "Rules": [
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": null,
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": null,
[6/14/2020 12:57:24 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:57:24 AM]     },
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": "None",
[6/14/2020 12:57:24 AM]       "Filter": null
[6/14/2020 12:57:24 AM]     },
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": null,
[6/14/2020 12:57:24 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:57:24 AM]     },
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider",
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": "Trace",
[6/14/2020 12:57:24 AM]       "Filter": null
[6/14/2020 12:57:24 AM]     }
[6/14/2020 12:57:24 AM]   ]
[6/14/2020 12:57:24 AM] }
[6/14/2020 12:57:24 AM] LoggerFilterOptions
[6/14/2020 12:57:24 AM] {
[6/14/2020 12:57:24 AM]   "MinLevel": "None",
[6/14/2020 12:57:24 AM]   "Rules": [
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": null,
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": null,
[6/14/2020 12:57:24 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:57:24 AM]     },
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": "None",
[6/14/2020 12:57:24 AM]       "Filter": null
[6/14/2020 12:57:24 AM]     },
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": null,
[6/14/2020 12:57:24 AM]       "Filter": "<AddFilter>b__0"
[6/14/2020 12:57:24 AM]     },
[6/14/2020 12:57:24 AM]     {
[6/14/2020 12:57:24 AM]       "ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider",
[6/14/2020 12:57:24 AM]       "CategoryName": null,
[6/14/2020 12:57:24 AM]       "LogLevel": "Trace",
[6/14/2020 12:57:24 AM]       "Filter": null
[6/14/2020 12:57:24 AM]     }
[6/14/2020 12:57:24 AM]   ]
[6/14/2020 12:57:24 AM] }
[6/14/2020 12:57:24 AM] FunctionResultAggregatorOptions
[6/14/2020 12:57:24 AM] {
[6/14/2020 12:57:24 AM]   "BatchSize": 1000,
[6/14/2020 12:57:24 AM]   "FlushTimeout": "00:00:30",
[6/14/2020 12:57:24 AM]   "IsEnabled": true
[6/14/2020 12:57:24 AM] }
[6/14/2020 12:57:24 AM] SingletonOptions
[6/14/2020 12:57:24 AM] {
[6/14/2020 12:57:24 AM]   "LockPeriod": "00:00:15",
[6/14/2020 12:57:24 AM]   "ListenerLockPeriod": "00:00:15",
[6/14/2020 12:57:24 AM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[6/14/2020 12:57:24 AM]   "LockAcquisitionPollingInterval": "00:00:05",
[6/14/2020 12:57:24 AM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[6/14/2020 12:57:24 AM] }
[6/14/2020 12:57:24 AM] HttpOptions
[6/14/2020 12:57:24 AM] {
[6/14/2020 12:57:24 AM]   "DynamicThrottlesEnabled": false,
[6/14/2020 12:57:24 AM]   "MaxConcurrentRequests": -1,
[6/14/2020 12:57:24 AM]   "MaxOutstandingRequests": -1,
[6/14/2020 12:57:24 AM]   "RoutePrefix": ""
[6/14/2020 12:57:24 AM] }
[6/14/2020 12:57:24 AM] Starting JobHost
[6/14/2020 12:57:24 AM] Starting Host (HostId=acmbp2019-382845607, InstanceId=6a47ff14-a3a9-4740-b1f9-24960643ccb3, Version=3.0.13353.0, ProcessId=38146, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[6/14/2020 12:57:24 AM] Loading functions metadata
[6/14/2020 12:57:24 AM] 6 functions loaded
[6/14/2020 12:57:24 AM] Starting worker process:node  --inspect=5858 "/Workspace/github/dig/covid-bot/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 54395 --workerId 125a8d47-2951-4d06-af4d-14679883cedf --requestId 23517a84-24bb-47c0-aff1-2cda543244fb --grpcMaxMessageLength 134217728
[6/14/2020 12:57:24 AM] node process with Id=39748 started
[6/14/2020 12:57:24 AM] Generating 6 job function(s)
[6/14/2020 12:57:24 AM] Found the following functions:
[6/14/2020 12:57:24 AM] Host.Functions.webhook
[6/14/2020 12:57:24 AM] Host.Functions.ping
[6/14/2020 12:57:24 AM] Host.Functions.get
[6/14/2020 12:57:24 AM] Host.Functions.profile
[6/14/2020 12:57:24 AM] Host.Functions.echoSkill
[6/14/2020 12:57:24 AM] Host.Functions.session
[6/14/2020 12:57:24 AM]
[6/14/2020 12:57:24 AM] Initializing function HTTP routes
[6/14/2020 12:57:24 AM] Mapped function route '/webhook' [get,post] to 'webhook'
[6/14/2020 12:57:24 AM] Mapped function route '/ping' [get,post] to 'ping'
[6/14/2020 12:57:24 AM] Mapped function route '//' [get,post] to 'get'
[6/14/2020 12:57:24 AM] Mapped function route '/profile' [get] to 'profile'
[6/14/2020 12:57:24 AM] Mapped function route '//skill/echo' [get,post] to 'echoSkill'
[6/14/2020 12:57:24 AM] Mapped function route '/session' [get,post,options] to 'session'
[6/14/2020 12:57:24 AM]
[6/14/2020 12:57:24 AM] Host initialized (29ms)
[6/14/2020 12:57:24 AM] Host started (29ms)
[6/14/2020 12:57:24 AM] Job host started
[6/14/2020 12:57:24 AM] Starting inspector on 127.0.0.1:5858 failed: address already in use
[6/14/2020 12:57:24 AM] Starting worker process:node  --inspect=5858 "/Workspace/github/dig/covid-bot/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 54395 --workerId 05439bd4-5cee-40a4-8574-572394b4bb89 --requestId 0752e59a-750a-4ee0-a2a9-d08aade9f2e0 --grpcMaxMessageLength 134217728
[6/14/2020 12:57:24 AM] node process with Id=39750 started
[6/14/2020 12:57:24 AM] Starting inspector on 127.0.0.1:5858 failed: address already in use
[6/14/2020 12:57:24 AM] Starting worker process:node  --inspect=5858 "/Workspace/github/dig/covid-bot/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 54395 --workerId 94d6f016-70dc-42c4-934d-2e193b7beb8c --requestId 559065e9-3bfa-436e-a662-0e9930ea7540 --grpcMaxMessageLength 134217728
[6/14/2020 12:57:24 AM] node process with Id=39751 started
[6/14/2020 12:57:24 AM] Starting inspector on 127.0.0.1:5858 failed: address already in use
[6/14/2020 12:57:24 AM] Exceeded language worker restart retry count for runtime:node. Shutting down Functions Host
[6/14/2020 12:57:24 AM] Stopping host...
[6/14/2020 12:57:24 AM] Stopping JobHost
[6/14/2020 12:57:24 AM] Job host stopped
[6/14/2020 12:57:24 AM] Host restarted.
[6/14/2020 12:57:24 AM] Stopping JobHost
[6/14/2020 12:57:24 AM] Job host stopped
[6/14/2020 12:57:26 AM] Host shutdown completed.
✨  Done in 89.80s.
✨  Done in 90.12s.
@anthonychu
Copy link
Member

@mhoeger Can you please take a look at this? Do we support hot reloading with Node apps? Thanks.

@anthonychu anthonychu added this to the Triaged milestone Jun 16, 2020
@mhoeger
Copy link
Contributor

mhoeger commented Jun 16, 2020 •
edited
Loading

@anthonychu - unfortunately no :( The issue is here mainly tracked here: Azure/azure-functions-host#3543

There's a problem with the ordering of process shutdown + spin-up. It typically isn't a problem (and arguably better for perf), but not when debugging. The code area is pretty sensitive, so I'm not totally sure what all would go into this change, but if it should be prioritized I think it would make sense to.

Here's VS Code flavor of the issue: microsoft/vscode-azurefunctions#781

Closing as duplicate in favor of Azure/azure-functions-host#3543

@mhoeger mhoeger closed this as completed Jun 16, 2020
@ghost ghost locked as resolved and limited conversation to collaborators Jul 16, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
Triaged
Development

No branches or pull requests
3 participants
@andycmaj @anthonychu @mhoeger