Add log to signify when debugger can attach

[ejizba]

In the VS Code extension, we look for Host lock lease acquired by instance ID to signal that we can attach the debugger. We originally used Job host started but that apparently didn't work in all cases - see microsoft/vscode-azurefunctions#660.

However, the "host lock lease" message doesn't always get printed - see here. We ran into this when trying to debug with Azurite, which doesn't seem to work well with leases - see here. A few other concerns:

1. I've also always been a little nervous that someone will change the "Host lock lease" message without realizing that it will break VS Code debugging
2. The message feels like an internal implementation detail that shouldn't really matter for debugging

Can we add a message that's sole purpose is to signify that debuggers can attach? I think the problem with Job host started in microsoft/vscode-azurefunctions#660 was that the worker wasn't fully started yet. Perhaps we just need a message like Language worker started? I honestly don't really care about the wording as long as it meets these criteria:

1. It always gets printed, regardless of lease status
2. It's unique enough that we won't run into false positives from other logs
3. We agree that the message won't change going forward

[fabiocav]

@kashimiz moving this back to triaged, but can you comment whether there was any progress made here?

[Hazhzeng]

Hi @fabiocav,

This also causes Azure/azure-functions-python-worker#607

@mhoeger and I investigated the same issue happens in Python worker VSCode.
When a user hit F5, the $func-watch problem watcher attempts to find Host lock lease acquired by instance ID, as it acts like the green light for debugger to attach. (code here)

However, for Python scenario, the languageWorkers__python__arguments environment variable is set to python /home/hazeng/.vscode/extensions/ms-python.python-2020.5.86806/pythonFiles/lib/python/debugpy/no_wheels/debugpy --listen 127.0.0.1:9091 --wait-for-client "/usr/lib/node_modules/azure-functions-core-tools/bin/workers/python/3.7/LINUX/X64/worker.py" --host 127.0.0.1 --port 36779 --workerId 0418316d-1c26-473a-bef8-db10134d0a0e --requestId 4cb4f2e7-5ab1-473e-8ccd-0bca60789db2 --grpcMaxMessageLength 134217728.

The actual issue occurs when the processes start in the following order:

1. Python interpreter process starts, and it is launched with debugpy module
2. Host emits the log entry Host lock lease acquired by instance ID
3. Debugger attaches to the debugpy server
4. The debugpy module ignites Python worker when it is ready

In this case, the debugger client will attach to the server before the Python worker starts, causing the process to fail.

So my suggestion is to emit a debugger can attach message when the host receives the WorkerInitResponse GRPC message.

[pragnagopa]

Assigned this to current sprint. Will send a PR soon.

[pragnagopa]

@EricJizbaMSFT - I sent a PR adding a log that gets emitted after a worker process starts. Is there a way we can test this?

[ejizba]

Yeah you can override the default problemMatcher in .vscode/tasks.json. Instead of just "problemMatcher": "$func-watch",, it'll look something like this:

{
  "version": "2.0.0",
  "tasks": [
    {
      "type": "func",
      "command": "host start",
      "problemMatcher": {
        "base": "$func-watch",
        "background": {
          "activeOnStart": true,
          "beginsPattern": "^.*(Job host stopped|signaling restart).*$",
          "endsPattern": "^.*Host lock lease acquired by instance ID.*$"
        }
      },
      "isBackground": true,
      "dependsOn": "pipInstall"
    },
    ...
  ]
}

Then just change the "Host lock lease" regular expression to match your new log

[anthonychu]

@pragnagopa Could you please confirm if the message is printed:

• if it's an in-proc .NET app (and custom handlers)
• if all log levels are set to Warning (or Error/None)

We're going to work on reducing verbosity of Core Tools and will likely use log levels to control what gets printed. Azure/azure-functions-core-tools#1131

[anthonychu]

@Hazhzeng: FYI @vrdmr and I were helping someone last week who was running into an issue that looks like what you're describing here: #4384 (comment)