CLI: Respect config log levels if --verbosity not explicitly passed

[sphuber]

Fixes #5923

The config allows to define the default log level for the logger of the Python API through the logging.aiida_loglevel option. The verdi CLI provides the --verbosity option to control the level of log messages written to console by the command itself, but also by the API code that is called by it. It does so by overriding the logging.aiida_loglevel option.

The problem was that it was always doing this, even if the --verbosity option was not explicitly specified. The reason is that the option defines REPORT as the default. This means the callback is always called and so the CLI_LOG_LEVEL global would always be set, causing the configure_logging to override the config setting with REPORT.

The solution is to remove the default from the option. If the option is not explicitly defined, the callback receives None and it doesn't set the CLI_LOG_LEVEL. This change brings a new problem though, as now, when verdi is called without --verbosity the configure_logging will not actually configure the handlers of the aiida logger to be the CliHandler.

To solve this problem, a new global aiida.common.log.CLI_ACTIVE is added which is None by default. The callback of the verbosity option sets this to True to indicate that we are in a verdi call. The configure_logging will check this global and if set will replace the console handler of the aiida logger to the cli handler.`

Finally, a new config option logging.verdi_loglevel is introduced. This is necessary because since the default for --verbository has been removed, it means the default from logging.aiida_loglevel would be taken. However, since this could be set to something higher than REPORT, e.g. WARNING, it would mean that most of the verdi commands would not print anything, which would suprise a lot of users.

The logger used by aiida.cmdline.utils.echo is changed from aiida.cmdline to verdi, to decouple it from the aiida logger. Its default log level is defined by the logging.verdi_loglevel, which is overridden if a more specific level is set with the --verbosity option.

[sphuber]

@astamminger tentative solution for the problem you reported. Haven't fully tested everything yet, but at least it seems to satisfy your requirement that the logging.aiida_loglevel is respected when --verbosity is not explicitly specified, while stile guaranteeing that report log messages are shown by default when going through the CLI.

[astamminger]

Hi @sphuber,

thanks for the effort! Haven't had the time yet to test your implementation, but I want to leave you some feedback. From a first sight this looks very reasonable to me. Basically that's a clearly laid-out version of the hacky workaround I was using in my AiiDA installation here to preserve the aiida-loglevel :)

Cheers

[sphuber]

Anyone else want to have a look at these changes? @unkcpz @ramirezfranciscof @ltalirz ?

[unkcpz]

Thanks @sphuber, it is still not very clear to me the loglevel hierarchy. I assume there are following different levels of the logger,

1. the -v or --verbosity which will override all other loglevel (or vise versa it will be override?)
2. the loglevel defined in config, e.g logging.aiida_loglevel ..
3. The sub-level e.g aiida.cmdline.
4. The loglevel for specific modules or thirdparty packages.

Can you give me a brief overview of which loglevel goes first and how they will override each other?

[unkcpz]

Can you check the docstring of function set_log_level? I am a bit confused since it is not fully conformed with the PR description. If I understand correctly, this method is related only to verdi_loglevel solely and became the most base log_level can be override by other log_level defined for other modules?

[sphuber]

Yes, it is incorrect currently, I will update it.

[unkcpz]

Thanks! clear.

[sphuber]

Can you give me a brief overview of which loglevel goes first and how they will override each other?

The base configuration defines a number of loggers (aiida, verdi, plumpy, etc.) each of which has the loglevel defined by the logging.{logger}_loglevel configuration option. For each logger, we define a single handler (named console), which simply redirects all messages to stdout using the logging.StreamHandler handler. This essentially ensures that logging ends up in the console when using the Python API in a script or interactive shell. The configuration is loaded by calling the aiida.common.log.configure_logging which is automatically done when a profile is loaded (and when a profile storage is backend, such that the dblog handler is properly configured).

Now all these loggers are independent, because each logger has its own "root" namespace. So all these loglevels are also independent and don't affect one another. If Python code does:

logger = logging.getLogger('aiida')
logger.warning('warning)

The loglevel of the aiida logger applies.

Now, when a verdi command is called, the --verbosity option callback set_log_level is called. Since all verdi commands automatically have the option attached (through the VerdiCommandGroup class) it is always called when verdi is used. The set_log_level sets the aiida.common.log.CLI_ACTIVE to True and calls configure_logging. This causes the handlers for the aiida and verdi loggers to be changed to aiida.cmdline.utils.log.CliHandler, which takes care that log messages are formatted in the style of verdi. Note that the aiida.cmdline.utils.echo functions essentially log to the verdi logger.

The one open question is whether we should simply override the handler for all loggers, and not just aiida and verdi. To be honest, I only did for the latter two, since I am not even sure if the other loggers are even hit. I know that there are loglevel options for them, but I am wondering if we should be adding these. I mean, should we be adding them for any dependency that can log? It is almost guaranteed that we don't have them all. But then again, I might as well override all of them to be consistent. If we provide a loglevel, I think their logging should be consistent across all loggers when running a CLI command.

The final step is when a user actually explicitly defines a value for --verbosity when calling verdi. In this case, the set_log_level also sets the aiida.common.log.CLI_LOG_LEVEL global which causes configure_logging to set the loglevel of the aiida and verdi loggers, overriding the logging.aiida_loglevel and logging.verdi_loglevel options.

This is the behavior that we want. When using verdi:

• All logging is formatted the same way, no matter the logger
• Default loglevel for messages from verdi commands themselves (i.e. from the echo functions) is REPORT
• If --verbosity is not specified, loglevels are defined by logging.{logger}_levelname options
• If --verbosity is specified, all loglevels are overridden with this value

While typing this, I think I should simply update the PR to have the option affect all loggers, and not just aiida, verdi as there is no good justification to limit it to just those.

[unkcpz]

The one open question is whether we should simply override the handler for all loggers, and not just aiida and verdi.

I don't have a strong opinion on this. But from my experience long ago debugging things of plumpy, what I expect is the loglevel of plumpy is only controlled by verdi config. To me using --verbose only for refering aiida and verdi makes more sense.

EDIT: it seems you already change it to affect all loggers. No problem with this, I'll have a look.

[unkcpz]

@sphuber thanks, just a minor request. All good from my side.

[unkcpz]

Thanks! clear.

[unkcpz]

It was INFO level, but in new code it seems the default level REPORT is used?

[sphuber]

Yeah, the INFO level was not necessary, because all the messages that are being tested for are anyway logged on the REPORT level, so we can use the default. That's why the test also simply pass even after removing the caplog.at_level line

[unkcpz]

Can you add a test to show the handler of aiida logger is set to cli?

[sphuber]

Added in last commit