azure-functions-python-worker: logging.debug() doesn't seem to make it to the logs

@empz The thread above doesn’t make it very clear, but you have to do 2 things. You already did one of them. But for the record, the 2 steps to achieve debug logging in Azure Functions are:

1. Set root logger level to 10

logging.Logger.root.level = 10

1. Configure log level in host.json

{
  "version":  "2.0",
  "logging": {
    "fileLoggingMode": "always",
    "logLevel": {
      "default": "Debug"
    }
  } 
}

This is still an issue as far as I can see, I just lost quite a bit of time trying to track down why logging.debug() never makes it to the console using azure-functions-core-tools 3.0.2245. The snippet posted earlier does not help; core tools shows its own debug messages but the logging.debug() calls from the python worker continue to be swallowed.

If I change this line to DEBUG, I see the output I expect in the console: https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/dispatcher.py#L122

I tried to follow the suggestion to pass --log-level=DEBUG to the worker, but this log level is not included in the argparse setup: https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/main.py#L19

Furthermore, azure-functions-core-tools does not seem to provide a functioning mechanism to actually pass this argument, but my C# is a bit rusty, I have no development environment to use to debug that project on this work machine, and the way the code comes together to construct the config for Microsoft.Azure.WebJobs is a bit inscrutable and stringly-typed, so I couldn’t quite follow it without investing significantly more time.

I did manage to discover that I can pass args through to the worker using --language-worker, but it’s prepend only and shoves the new arguments before the worker.py file, so it’s close to useless without a shim script:

# exec-fa.py
import subprocess
import sys
sys.exit(subprocess.call(["python", *sys.argv[1:], "--log-level=TRACE"]))

$ func start --python  --language-worker ./exec-fa.py

So my shim script “works”, in the sense that it starts the worker with the extra arguments appended, but the logging.debug() calls are still swallowed unless I manually hack dispatcher.py:122. This will do for me for now, but I can’t share this workflow with the other developers on my team, it’s unreasonable to expect them to be willing to do this.

I don’t really know what to suggest here, but unless debug logging is explicitly not supported (if so, it should be documented prominently), it really seems to me like this issue should still be open.

@elprans, we should be fine to keep the system logs at the informational level. Those are already being sent to the table where keep our debugging information.

As for the original issue noted here, the desired behavior can be achieved with a combination of two steps:

1. Setting the root logger in user code to use the debug level (it is set to to info by default).
2. Configuring the host.json to log Debug messages:

{
  "version":  "2.0",
  "logging": {
    "fileLoggingMode": "always",
    "logLevel": {
      "default": "Debug"
    }
  } 
}

With these changes, the logs should be visible on both the console as well as Application Insights. @asavaritayal, we can make note of this in our development wiki. Changing the logging settings currently would require re-deployment but we might be able to introduce some app settings to achieve this if that’s the route we want to go.

@asavaritayal Probably documenting how to do that for an active, deployed function would be helpful.

The default log level is INFO, you need to run the worker with --log-level=DEBUG to get the debug messages.

@DanielBell-Io host.json is supposed to be part of your Python project that you deploy to Azure. If you create a new Azure Python project in Visual Studio Code, the file is auto-generated for you with defaults.