Force Log when host/worker is ready for VS Code debugger to attach when loglevel is set to None

[anthonychu]

After discussing with @pragnagopa, it sounds like the initial change in Azure/azure-functions-host#6230 is not quite sufficient for the purposes of VS Code attaching the debugger reliably.

There are 2 issues in particular:

• In-proc .NET apps will not print the new message
• The message is printed with log level Information. If default log levels are changed to Warning, Error, or None, the message will not print

We need this message to be printed regardless of stack or log level. Also suggest updating the message to something more generic and doesn't mention "worker process". (something like "Function app is ready"?)

Also needed for this: #1131

@EricJizbaMSFT

[pragnagopa]

cc @mhoeger

If default log levels are changed to Warning, Error, or None, the message will not print

New log is added at info level. Setting to any other level will include info level logs. This would break if the user turns off logging completely.

@EricJizbaMSFT - is there a way VS Code can attach debugger without relying on the logging?

If logging is the only, we need to figure out common log statement for .Net in-proc and out-of-proc functions.

[anthonychu]

@EricJizbaMSFT Is there another way to attach a debugger in VS Code without relying on output?

@pragnagopa Can the host Console.WriteLine the message (bypassing any configured log levels) if it's running inside Core Tools?

[pragnagopa]

@brettsam - As of now VS Code relies on logging to attach a debugger. If the user sets logLevel to None, is there way to still write logs to console when running in core tools?

[ejizba]

is there a way VS Code can attach debugger without relying on the logging?

Well we only use the logs for languages that use a port for debugging, like Python/JS/etc. because we can't attach until the port is open. For C#, we attach directly to the process and we don't need to wait

This would break if the user turns off logging completely.

Do you by chance log the log level? Aka do you print a line that says "Log level: 'None'" or "Logs will not be printed because log level is set to 'None'"? If so, we can detect that and throw an error telling users we need logs

[pragnagopa]

@EricJizbaMSFT - thanks for clarifying about C# vs out-of-proc languages. Fix in Azure/azure-functions-host#6230 is enough to address the issue on when attach debugger.

@anthonychu - Min loglevel is set to information. Setting log level to None in host.json

"Logging": {
		"LogLevel": {
			"Default": "None"
		}
	}

does not impact info level logs.

Do you have an example how attaching debugger fails due to log level?

[anthonychu]

@pragnagopa Pushed a repro here. I basically made the change in host.json you mentioned. It suppresses the current "Host lock lease acquired" message. I don't have the a build with the updated host with the new message. Perhaps that's not affected by the log level?

[ejizba]

Well we only use the logs for languages that use a port for debugging, like Python/JS/etc. because we can't attach until the port is open. For C#, we attach directly to the process and we don't need to wait

So I did more digging and turns out this isn't the case yet. I think it's possible, but still need to do some more investigating and work to flesh it out. If it's easy for you to add the log in the .NET case, that would be great - we would "just work" with little effort from my side. If that's not easy, I'm comfortable saying the .NET case is on our side to fix.

On another note - we have a release coming up in a week-ish and I plan to update our pattern in that release. @pragnagopa sound good to you? I plan to maintain backwards compatibility and keep looking for the old message, too. Once people update to the new cli, it should see the new message first and attach a little bit sooner (ideally fixing the runOnStartup issues)

[pragnagopa]

@EricJizbaMSFT - For C#, can you continue to rely on existing pattern Host lock lease acquired... ? For all other languages you can use new log message.

On another note - we have a release coming up in a week-ish and I plan to update our pattern in that release.
Release that includes the new log messages is not rolled out yet. But since your changes would be backward compatible, you do not have to block on host release.

@anthonychu - I can repro the issue. Setting log level to None does hide all info logs coming from JobHost. Tested with latest bits.
Following code applies the filter:

https://github.com/Azure/azure-functions-host/blob/c17b336f845dd24e9b8e80613535bd5333c47b3a/src/WebJobs.Script/Extensions/ScriptLoggingBuilderExtensions.cs#L36

I will dig a little more to figure out if we can enforce log out put for logs VS Code relies on even when logLevel is set to None.

Updating issue title and assigning to next sprint.

[ejizba]

For C#, can you continue to rely on existing pattern Host lock lease acquired... ? For all other languages you can use new log message.

Yes we can. It doesn't fix the "runOnStartup" issue for C#, but it maintains the current experience.

[fabiocav]

Moving this to the Core Tools repo as the work would be done there.

[anthonychu]

@pragnagopa Is this issue still needed to track this? From what I can tell, the message is emitted from the host so any changes need to be done there, not Core Tools.

[pragnagopa]

the message is emitted from the host so any changes need to be done there, not Core Tools.

Yes. Log is coming from the host. Both @fabiocav and @brettsam recommended adding a logging provider in core tools that will force log these logging statements even when logging level is set to None

I will look into this possibility.

[pragnagopa]

@brettsam - I am trying to force logs to flow through if logLevel is set to None and then filter the logs based on the content. Tried the following:

.ConfigureLogging( (context, loggingBuilder) =>
                {
                    loggingBuilder.ClearProviders();
                    if (hostJsonLogLevel == LogLevel.None)
                    {
                        loggingBuilder.SetMinimumLevel(LogLevel.Trace);
                        loggingBuilder.AddDefaultWebJobsFilters();
                        loggingBuilder.AddProvider(new ColoredConsoleLoggerProvider(hostJsonLogLevel));
                    }
                    else
                    {
                        loggingBuilder.AddDefaultWebJobsFilters();
                        loggingBuilder.AddProvider(new ColoredConsoleLoggerProvider((cat, level) => level >= LogLevel.Information));
                    }
                })

Even though minimum loglevel is set to to Trace, only webjost level logs and RpcWorkerChannel logs are written to console.

Any ideas on what I might be missing here?

[brettsam]

What logger do you need to write out your log? You need to add a filter specifically for that logger. If you have one, it wins above all other filters, even ones specified in configuration.

For example: loggingBuilder.AddFilter<ColoredConsoleLoggerProvider>(null, LogLevel.Trace);

Setting null here means all categories will be filtered at Trace level. If you want a specific category, you can specify it instead.

See this for how filtering rules work: https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-3.1#how-filtering-rules-are-applied.

[pragnagopa]

Moving this issue to Sprint 82 to give more time for PR reviews.

[fabiocav]

This is currently in the PR tracking the logging verbosity changes

[pragnagopa]

Addressed in referenced PR #2139