[BUG] Logging level debug does not work in local or portal logs

[ijoosong]

Investigative information

Please provide the following:

In any python function, log level debug does not display in both local and portal logs.

Repro steps

Provide the steps required to reproduce the problem:

Expected behavior

Provide a description of the expected behavior.

Actual behavior

Provide a description of the actual behavior observed.

Known workarounds

Provide a description of any known workarounds.

Contents of the requirements.txt file:

Provide the requirements.txt file to help us find out module related issues.

Related information

Provide any related information

• Links to source
• Bindings used

[ijoosong]

[Hazhzeng]

Just synced with my team offline @vrmdr and @stefanushinardi

The debug level log was controlled by the azure-functions-host --log-level flag. https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/main.py#L21

I think the debug level was reserved for the python worker log in old days. We're currently following up the function-host team to ensure if the debug level is no longer used.

Thanks for reporting this issue.

[pragnagopa]

@ijoosong - can you please share your host.json

Default log level is set to information for anything else you need to update host.json with the loglevel. For debug, your host.json should look like this:

{
	"version": "2.0",
	"logging": {
		"LogLevel": {
			"Default": "Debug"
		}
	},
	"extensionBundle": {
		"id": "Microsoft.Azure.Functions.ExtensionBundle",
		"version": "[1.*, 2.0.0)"
	}
}

[anthonychu]

I was investigating this with @ijoosong a while back. Changing host.json doesn’t make a difference In this case because the worker currently hardcodes function logs to INFO as @vrdmr discovered.

[ijoosong]

@pragnagopa I've tried this and it doesn't work :(

[vrdmr]

@ijoosong We've figured out the fix and I'll send out the fix post-testing.

[Hazhzeng]

Thanks @pragnagopa, @vrdmr and @stefanushinardi for the offline sync up.
We determine that there're two places blocking the logging from emitting debug level logs:

1. When the worker process is created, the host is not passing --log-level flag into the argument, thus the Python worker will only emit the INFO log into console. https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/main.py#L21
2. After the worker establishes GRPC channel to the host, the root logger will stop using console log and switch to GRPC log which is pinned to INFO https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/dispatcher.py#L125

Since the GRPC logging handler is attached onto the root logger, currently we have a concern on the performance when dropping the INFO level constrain, since some third-party libraries are using DEBUG level logs (e.g. azure-storage-blob https://github.com/Azure/azure-sdk-for-python/blob/master/sdk/storage/azure-storage-blob/azure/storage/blob/_shared/policies.py#L201-L203).

[vrdmr]

@Hazhzeng

When the worker process is created, the host is not passing --log-level flag into the argument, thus the Python worker will only emit the INFO log into console. https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/main.py#L21

How do we configure debug logging for workers logs from the host side? Is there an app setting that the host can pass in?

[Hazhzeng]

@vrdmr The host redirect all stdout and stderr from the Python process into asp.net logging infra. They don't control logging level in Python worker, they're just filtering the worker logs.