CLI: Only configure logging in set_log_level callback once (#6493)

All `verdi` commands automatically have the `-v/--verbosity` option
added. This option has a callback `set_log_level` that is invoked for
each subcommand. The callback is supposed to call `configure_logging` to
setup the logging configuration.

Besides it being unnecessary to call it multiple times for each
subcommand, it would actually cause a bug in that once the profile
storage would have been loaded (through the callback of the profile
option), which would have called `configure_logging` with `with_orm=True`
to make sure the `DbLogHandler` was properly configured, another call to
`set_log_level` would call `configure_logging` with the default values
(where `with_orm=False`) and so the `DbLogHandler` would be removed.
This would result in process log messages not being persisted in the
database. This would be manifested when running an AiiDA process through
a script invoked through `verdi` or any other CLI that uses the
verbosity option provided by `aiida-core`.

Since the `set_log_level` only has to make sure that the logging is
configured at least once, a guard is added to skip the configuration
once the `aiida.common.log.CLI_ACTIVE` global has been set by a previous
invocation.

src/aiida/cmdline/params/options/main.py

@@ -175,7 +175,7 @@ def decorator(command):
     return decorator
 
 
-def set_log_level(_ctx, _param, value):
+def set_log_level(ctx, _param, value):
     """Configure the logging for the CLI command being executed.
 
     Note that we cannot use the most obvious approach of directly setting the level on the various loggers. The reason
@@ -192,12 +192,15 @@ def set_log_level(_ctx, _param, value):
     """
     from aiida.common import log
 
+    if log.CLI_ACTIVE:
+        return value
+
     log.CLI_ACTIVE = True
 
     # If the value is ``None``, it means the option was not specified, but we still configure logging for the CLI
     # However, we skip this when we are in a tab-completion context.
     if value is None:
-        if not _ctx.resilient_parsing:
+        if not ctx.resilient_parsing:
             configure_logging()
         return None
 

tests/cmdline/params/options/test_verbosity.py

@@ -14,7 +14,7 @@
 import pytest
 from aiida.cmdline.commands.cmd_verdi import verdi
 from aiida.cmdline.utils import echo
-from aiida.common.log import AIIDA_LOGGER, LOG_LEVELS
+from aiida.common import log
 
 
 @pytest.fixture
@@ -29,10 +29,10 @@ def cmd():
 
     The messages to the ``verdi`` are performed indirect through the utilities of the ``echo`` module.
     """
-    assert 'cli' in [handler.name for handler in AIIDA_LOGGER.handlers]
+    assert 'cli' in [handler.name for handler in log.AIIDA_LOGGER.handlers]
 
-    for log_level in LOG_LEVELS.values():
-        AIIDA_LOGGER.log(log_level, 'aiida')
+    for log_level in log.LOG_LEVELS.values():
+        log.AIIDA_LOGGER.log(log_level, 'aiida')
 
     echo.echo_debug('verdi')
     echo.echo_info('verdi')
@@ -49,7 +49,7 @@ def verify_log_output(output: str, log_level_aiida: int, log_level_verdi: int):
     :param log_level_aiida: The expected log level of the ``aiida`` logger.
     :param log_level_verdi: The expected log level of the ``verdi`` logger.
     """
-    for log_level_name, log_level in LOG_LEVELS.items():
+    for log_level_name, log_level in log.LOG_LEVELS.items():
         prefix = log_level_name.capitalize()
 
         if log_level >= log_level_aiida:
@@ -73,7 +73,7 @@ def test_default(run_cli_command):
     verify_log_output(result.output, logging.REPORT, logging.REPORT)
 
 
-@pytest.mark.parametrize('option_log_level', [level for level in LOG_LEVELS.values() if level != logging.NOTSET])
+@pytest.mark.parametrize('option_log_level', [level for level in log.LOG_LEVELS.values() if level != logging.NOTSET])
 @pytest.mark.usefixtures('reset_log_level')
 def test_explicit(run_cli_command, option_log_level):
     """Test explicitly settings a verbosity"""
@@ -92,6 +92,9 @@ def test_config_option_override(run_cli_command, isolated_config):
     result = run_cli_command(cmd, raises=True, use_subprocess=False)
     verify_log_output(result.output, logging.ERROR, logging.WARNING)
 
+    # Manually reset the ``aiida.common.log.CLI_ACTIVE`` global otherwise the verbosity callback is a no-op
+    log.CLI_ACTIVE = None
+
     # If ``--verbosity`` is explicitly defined, it override both both config options.
     result = run_cli_command(cmd, ['--verbosity', 'INFO'], raises=True, use_subprocess=False)
     verify_log_output(result.output, logging.INFO, logging.INFO)