Debugger attaches too late to JavaScript function with "RunOnStartup" option #1492

heinrich-ulbricht · 2019-09-15T21:29:04Z

Use case:
Debug Azure Function locally by pressing F5 and have the function run immediately with breakpoints being set.

Expected result:
Set breakpoints are hit.

Observed result:
Breakpoints are not hit. The message "Debugger attached" appears after completing the first function execution.

Repro steps:

Create JavaScript Azure Function
Add "runOnStartup": true to function.json

{
  "bindings": [
    {
      "name": "myTimer",
      "type": "timerTrigger",
      "direction": "in",
      "schedule": "0 */30 * * * *",
      "runOnStartup": true
    }
  ]
}

press F5 to run function
see function running while breakpoints not being hit

Click to expand console output:

> Executing task: func host start <


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

Azure Functions Core Tools (2.7.1585 Commit hash: 9a2b7239b937148e3b76e6f7999798629a82134a)
Function Runtime Version: 2.0.12641.0
[9/15/19 9:18:11 PM] Building host: startup suppressed:False, configuration suppressed: False
[9/15/19 9:18:11 PM] Initializing Host.
[9/15/19 9:18:11 PM] Host initialization: ConsecutiveErrors=0, StartupCount=1
[9/15/19 9:18:11 PM] LoggerFilterOptions
[9/15/19 9:18:11 PM] {
[9/15/19 9:18:11 PM]   "MinLevel": "None",
[9/15/19 9:18:11 PM]   "Rules": [
[9/15/19 9:18:11 PM]     {
[9/15/19 9:18:11 PM]       "ProviderName": null,
[9/15/19 9:18:11 PM]       "CategoryName": null,
[9/15/19 9:18:11 PM]       "LogLevel": null,
[9/15/19 9:18:11 PM]       "Filter": "<AddFilter>b__0"
[9/15/19 9:18:11 PM]     },
[9/15/19 9:18:11 PM]     {
[9/15/19 9:18:11 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[9/15/19 9:18:11 PM]       "CategoryName": null,
[9/15/19 9:18:11 PM]       "LogLevel": "None",
[9/15/19 9:18:11 PM]       "Filter": null
[9/15/19 9:18:11 PM]     },
[9/15/19 9:18:11 PM]     {
[9/15/19 9:18:11 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[9/15/19 9:18:11 PM]       "CategoryName": null,
[9/15/19 9:18:11 PM]       "LogLevel": null,
[9/15/19 9:18:11 PM]       "Filter": "<AddFilter>b__0"
[9/15/19 9:18:11 PM]     }
[9/15/19 9:18:11 PM]   ]
[9/15/19 9:18:11 PM] }
[9/15/19 9:18:11 PM] FunctionResultAggregatorOptions
[9/15/19 9:18:11 PM] {
[9/15/19 9:18:11 PM]   "BatchSize": 1000,
[9/15/19 9:18:11 PM]   "FlushTimeout": "00:00:30",
[9/15/19 9:18:11 PM]   "IsEnabled": true
[9/15/19 9:18:11 PM] }
[9/15/19 9:18:11 PM] SingletonOptions
[9/15/19 9:18:11 PM] {
[9/15/19 9:18:11 PM]   "LockPeriod": "00:00:15",
[9/15/19 9:18:11 PM]   "ListenerLockPeriod": "00:00:15",
[9/15/19 9:18:11 PM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[9/15/19 9:18:11 PM]   "LockAcquisitionPollingInterval": "00:00:05",
[9/15/19 9:18:11 PM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[9/15/19 9:18:11 PM] }
[9/15/19 9:18:11 PM] HttpOptions
[9/15/19 9:18:11 PM] {
[9/15/19 9:18:11 PM]   "DynamicThrottlesEnabled": false,
[9/15/19 9:18:11 PM]   "MaxConcurrentRequests": -1,
[9/15/19 9:18:11 PM]   "MaxOutstandingRequests": -1,
[9/15/19 9:18:11 PM]   "RoutePrefix": "api"
[9/15/19 9:18:11 PM] }
[9/15/19 9:18:12 PM] Starting JobHost
[9/15/19 9:18:12 PM] Starting Host (HostId=devazure-1294318200, InstanceId=c68b6c58-e698-44b8-a328-3095d7fcef8c, Version=2.0.12641.0, ProcessId=3991, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=)
[9/15/19 9:18:12 PM] Loading functions metadata
[9/15/19 9:18:12 PM] 1 functions loaded
[9/15/19 9:18:12 PM] Loading proxies metadata
[9/15/19 9:18:12 PM] Initializing Azure Function proxies
[9/15/19 9:18:12 PM] 0 proxies loaded
[9/15/19 9:18:12 PM] Starting language worker process:node  --inspect=9229 "<snip>.js" --host 127.0.0.1 --port 44647 --workerId 7f1ae1bd-d625-4852-ad5d-72281b0f8e4f --requestId 4c5e1d71-cf06-44ef-afde-11344a161a69 --grpcMaxMessageLength 134217728
[9/15/19 9:18:12 PM] node process with Id=4016 started
[9/15/19 9:18:12 PM] Generating 1 job function(s)
[9/15/19 9:18:12 PM] Worker 7f1ae1bd-d625-4852-ad5d-72281b0f8e4f connecting on 127.0.0.1:44647
[9/15/19 9:18:12 PM] Found the following functions:
[9/15/19 9:18:12 PM] Host.Functions.CheckContoso
[9/15/19 9:18:12 PM] 
[9/15/19 9:18:12 PM] Host initialized (890ms)
[9/15/19 9:18:14 PM] Executing 'Functions.CheckContoso' (Reason='Timer fired at 2019-09-15T23:18:14.4738404+02:00', Id=c460f3e9-ef10-43ff-a5f3-6ce11c730ada)
[9/15/19 9:18:14 PM] Trigger Details: UnscheduledInvocationReason: RunOnStartup
[9/15/19 9:18:21 PM] Executed 'Functions.CheckContoso' (Succeeded, Id=c460f3e9-ef10-43ff-a5f3-6ce11c730ada)
[9/15/19 9:18:21 PM] The next 5 occurrences of the 'Functions.CheckContoso' schedule (Cron: '0 0,30 * * * *') will be:
[9/15/19 9:18:21 PM] 09/15/2019 23:30:00+02:00 (09/15/2019 21:30:00Z)
[9/15/19 9:18:21 PM] 09/16/2019 00:00:00+02:00 (09/15/2019 22:00:00Z)
[9/15/19 9:18:21 PM] 09/16/2019 00:30:00+02:00 (09/15/2019 22:30:00Z)
[9/15/19 9:18:21 PM] 09/16/2019 01:00:00+02:00 (09/15/2019 23:00:00Z)
[9/15/19 9:18:21 PM] 09/16/2019 01:30:00+02:00 (09/15/2019 23:30:00Z)
[9/15/19 9:18:21 PM] 
[9/15/19 9:18:21 PM] Host started (9386ms)
[9/15/19 9:18:21 PM] Job host started
[9/15/19 9:18:21 PM] Debugger listening on ws://127.0.0.1:9229/afdfde67-e7ff-4c7c-af0a-ec1eaa52bd74
[9/15/19 9:18:21 PM] For help, see: https://nodejs.org/en/docs/inspector
[9/15/19 9:18:21 PM] <...>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <LOGGED OUTPUT FROM FUNCTION>
[9/15/19 9:18:21 PM] <...>
Hosting environment: Production
Content root path: /home/user/<snip>
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.
[9/15/19 9:18:26 PM] Host lock lease acquired by instance ID '000000000000000000000000658112C5'.
[9/15/19 9:18:27 PM] Debugger attached.

The function is run before the debugger is being attached. In the log you see

[9/15/19 9:18:14 PM] Trigger Details: UnscheduledInvocationReason: RunOnStartup

before

[9/15/19 9:18:27 PM] Debugger attached.

I added some initial delay to my function to rule out race conditions. But it seems like the initial function execution is being waited for before attaching the debugger.

Context info:
OS: linux (Debian 9)
Product: Visual Studio Code - Insiders
Product Version: 1.39.0-insider
Language: en
Node.js: v10.16.3

The text was updated successfully, but these errors were encountered:

heinrich-ulbricht · 2019-09-15T22:05:19Z

Workaround: Remove the runOnStartup option, press F5 and wait for the debugger to be attached. Then run the local function manually in the Azure Extension under "Local Project" -> "Functions" -> Right click on function -> "Execute Function Now". Breakpoints will be hit.

ejizba · 2019-09-16T20:39:58Z

Could be related to #1245 and Azure/azure-functions-host#4384

heinrich-ulbricht · 2019-09-19T11:32:55Z

@EricJizbaMSFT Is there anything I should check or try that could help supporting (or falsifying) this assumption?

ejizba · 2019-09-20T23:18:59Z

@heinrich-ulbricht the debugger knows when to attach based on the problem matcher in your .vscode/tasks.json file. Related to this comment, you can try modifying the problem matcher from:

"problemMatcher": "$func-watch",

to something like this:

"problemMatcher": {
  "base": "$func-watch",
  "background": {
    "activeOnStart": true,
    "beginsPattern": "...TODO: Figure out what this should be...",
    "endsPattern": "...TODO: Figure out what this should be..."
  }
}

You'll want to check the logs for the "func host start" task and modify the beginsPattern and endsPattern to match some line of output being printed earlier than our current patterns. This is where we define the default patterns:
https://github.com/microsoft/vscode-azurefunctions/blob/master/package.json#L738

We're currently looking for the "Host lock leased" line, which might be printed after the first timer trigger is run.

heinrich-ulbricht · 2019-09-21T06:01:10Z

Ok will try after returning from vacation.

heinrich-ulbricht · 2019-10-11T13:17:43Z

I got the debugger to attach early to my runOnStartup function doing two things:

modifying .vscode/tasks.json
adding a delay at function startup

My tasks.json looks like this:

    "tasks": [
        {
            "type": "func",
            "command": "host start",
            "problemMatcher": {
                "base": "$func-watch",
                "background": {
                  "activeOnStart": true,
                  "beginsPattern": "^.*(Job host stopped|signaling restart).*$",
                  "endsPattern": "^.*Executing '.*?' \\(Reason='Timer fired at .*?', Id=.*?\\).*$"
                }
              },
            "isBackground": true,
            "dependsOn": "npm install"
        },
        # snip
    ]

I copied the beginsPattern from the source you linked and modified the endPattern to match the line indicating that the function starts (note that the log message says "timer fired" but actually means the startup execution).
This works. BUT the debugger apparently takes some time to attach (while the function starts running) which is why breakpoints early in the function's code are not hit. Later ones are. Thus I needed to add some kind of sleep to my function (setTimeout worked).
This works but is not pretty as long as it needs the initial sleep. So for now I'm fine with manually executing the function via the workaround I mentioned above because I can leave out the sleep.

ejizba added this to the tracking milestone Sep 19, 2019

ejizba added bug external blocked labels Sep 19, 2019

ejizba mentioned this issue Jan 25, 2020

Python timer trigger does not run locally when runonstartup is set to true Azure/azure-functions-host#5262

Closed

pragnagopa mentioned this issue Jan 28, 2020

Python timer trigger does not run locally when runonstartup is set to true #1841

Closed

ejizba mentioned this issue Mar 12, 2020

Debugger attaching too late - Unable to hit breakpoints in Startup.cs #1971

Open

ejizba added the startup label Mar 12, 2020

ejizba modified the milestones: tracking, 0.22.0 Mar 16, 2020

yojagad mentioned this issue Mar 19, 2020

Getting "Did not find any initialized language workers" error when running in debugger Azure/azure-functions-host#5811

Closed

ejizba modified the milestones: tracking, 0.23.0 Jun 18, 2020

ejizba mentioned this issue Jun 30, 2020

Update "func-watch" to reflect new message #2200

Merged

ejizba closed this as completed in #2200 Jul 2, 2020

vscodebot bot locked and limited conversation to collaborators Aug 16, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Debugger attaches too late to JavaScript function with "RunOnStartup" option #1492

Debugger attaches too late to JavaScript function with "RunOnStartup" option #1492

heinrich-ulbricht commented Sep 15, 2019 •

edited

Loading

heinrich-ulbricht commented Sep 15, 2019

ejizba commented Sep 16, 2019

heinrich-ulbricht commented Sep 19, 2019

ejizba commented Sep 20, 2019

heinrich-ulbricht commented Sep 21, 2019

heinrich-ulbricht commented Oct 11, 2019 •

edited

Loading

Debugger attaches too late to JavaScript function with "RunOnStartup" option #1492

Debugger attaches too late to JavaScript function with "RunOnStartup" option #1492

Comments

heinrich-ulbricht commented Sep 15, 2019 • edited Loading

heinrich-ulbricht commented Sep 15, 2019

ejizba commented Sep 16, 2019

heinrich-ulbricht commented Sep 19, 2019

ejizba commented Sep 20, 2019

heinrich-ulbricht commented Sep 21, 2019

heinrich-ulbricht commented Oct 11, 2019 • edited Loading

heinrich-ulbricht commented Sep 15, 2019 •

edited

Loading

heinrich-ulbricht commented Oct 11, 2019 •

edited

Loading