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

…#5925)

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 all loggers to the `cli` handler.`

Finally, a new config option `logging.verdi_loglevel` is introduced.
This is necessary because since the default for `--verbosity` 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.

aiida/cmdline/params/options/main.py

@@ -91,19 +91,29 @@ def decorator(command):
 
 
 def set_log_level(_ctx, _param, value):
-    """Fix the log level for all loggers from the cli.
+    """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 ``AIIDA_LOGGER``. The reason
+    Note that we cannot use the most obvious approach of directly setting the level on the various loggers. The reason
     is that after this callback is finished, the :meth:`aiida.common.log.configure_logging` method can be called again,
-    for example when the database backend is loaded, and this will undo this change. So instead, we change the value of
-    the `aiida.common.log.CLI_LOG_LEVEL` constant. When the logging is reconfigured, that value is no longer ``None``
-    which will ensure that the ``cli`` handler is configured for all handlers with the level of ``CLI_LOG_LEVEL``. This
-    approach tighly couples the generic :mod:`aiida.common.log` module to the :mod:`aiida.cmdline` module, which is not
-    the cleanest, but given that other module code can undo the logging configuration by calling that method, there
-    seems no easy way around this approach.
+    for example when the database backend is loaded, and this will undo this change. So instead, we set to globals in
+    the :mod:`aiida.common.log` module: ``CLI_ACTIVE`` and ``CLI_LOG_LEVEL``. The ``CLI_ACTIVE`` global is always set to
+    ``True``. The ``configure_logging`` function will interpret this as the code being executed through a ``verdi``
+    call. The ``CLI_LOG_LEVEL`` global is only set if an explicit value is set for the ``--verbosity`` option. In this
+    case, it is set to the specified log level and ``configure_logging`` will then set this log level for all loggers.
+
+    This approach tightly couples the generic :mod:`aiida.common.log` module to the :mod:`aiida.cmdline` module, which
+    is not the cleanest, but given that other module code can undo the logging configuration by calling that method,
+    there seems no easy way around this approach.
     """
     from aiida.common import log
 
+    log.CLI_ACTIVE = True
+
+    # If the value is ``None``, it means the option was not specified, but we still configure logging for the CLI
+    if value is None:
+        configure_logging()
+        return None
+
     try:
         log_level = value.upper()
     except AttributeError:
@@ -124,7 +134,6 @@ def set_log_level(_ctx, _param, value):
     '-v',
     '--verbosity',
     type=click.Choice(tuple(map(str.lower, LOG_LEVELS.keys())), case_sensitive=False),
-    default='REPORT',
     callback=set_log_level,
     expose_value=False,  # Ensures that the option is not actually passed to the command, because it doesn't need it
     help='Set the verbosity of the output.'

aiida/cmdline/utils/echo.py

@@ -11,15 +11,14 @@
 import collections
 import enum
 import json
+import logging
 import sys
 from typing import Any, Optional
 
 import click
 import yaml
 
-from aiida.common.log import AIIDA_LOGGER
-
-CMDLINE_LOGGER = AIIDA_LOGGER.getChild('cmdline')
+CMDLINE_LOGGER = logging.getLogger('verdi')
 
 __all__ = ('echo_report', 'echo_info', 'echo_success', 'echo_warning', 'echo_error', 'echo_critical', 'echo_dictionary')
 

aiida/common/log.py

@@ -8,6 +8,8 @@
 # For further information please visit http://www.aiida.net               #
 ###########################################################################
 """Module for all logging methods/classes that don't need the ORM."""
+from __future__ import annotations
+
 import collections
 import contextlib
 import logging
@@ -51,7 +53,12 @@ def report(self, msg: str, *args, **kwargs) -> None:
 }
 
 AIIDA_LOGGER = cast(AiidaLoggerType, logging.getLogger('aiida'))
-CLI_LOG_LEVEL = None
+
+CLI_ACTIVE: bool | None = None
+"""Flag that is set to ``True`` if the module is imported by ``verdi`` being called."""
+
+CLI_LOG_LEVEL: str | None = None
+"""Set if ``verdi`` is called with ``--verbosity`` flag specified, and is set to corresponding log level."""
 
 
 # The default logging dictionary for AiiDA that can be used in conjunction
@@ -82,18 +89,19 @@ def get_logging_config():
             },
             'cli': {
                 'class': 'aiida.cmdline.utils.log.CliHandler',
-                'formatter': 'cli',
-            }
+                'formatter': 'cli'
+            },
         },
         'loggers': {
             'aiida': {
                 'handlers': ['console'],
                 'level': lambda: get_config_option('logging.aiida_loglevel'),
                 'propagate': True,
             },
-            'aiida.cmdline': {
+            'verdi': {
                 'handlers': ['cli'],
-                'propagate': False,
+                'level': lambda: get_config_option('logging.verdi_loglevel'),
+                'propagate': True,
             },
             'plumpy': {
                 'handlers': ['console'],
@@ -169,8 +177,6 @@ def configure_logging(with_orm=False, daemon=False, daemon_log_file=None):
     """
     from logging.config import dictConfig
 
-    from aiida.manage.configuration import get_config_option
-
     # Evaluate the `LOGGING` configuration to resolve the lambdas that will retrieve the correct values based on the
     # currently configured profile.
     config = evaluate_logging_configuration(get_logging_config())
@@ -204,20 +210,29 @@ def configure_logging(with_orm=False, daemon=False, daemon_log_file=None):
             except ValueError:
                 pass
 
+    # If the ``CLI_ACTIVE`` is set, a ``verdi`` command is being executed, so we replace the ``console`` handler with
+    # the ``cli`` one for all loggers.
+    if CLI_ACTIVE is True:
+        for logger in config['loggers'].values():
+            handlers = logger['handlers']
+            if 'console' in handlers:
+                handlers.remove('console')
+            handlers.append('cli')
+
+    # If ``CLI_LOG_LEVEL`` is set, a ``verdi`` command is being executed with the ``--verbosity`` option. In this case
+    # we override the log levels of all loggers with the specified log level.
     if CLI_LOG_LEVEL is not None:
-        config['loggers']['aiida']['handlers'] = ['cli']
-        config['loggers']['aiida']['level'] = CLI_LOG_LEVEL
+        for logger in config['loggers'].values():
+            logger['level'] = CLI_LOG_LEVEL
 
     # Add the `DbLogHandler` if `with_orm` is `True`
     if with_orm:
-
-        handler_dblogger = 'dblogger'
-
-        config['handlers'][handler_dblogger] = {
+        from aiida.manage.configuration import get_config_option
+        config['handlers']['db_logger'] = {
             'level': get_config_option('logging.db_loglevel'),
-            'class': 'aiida.orm.utils.log.DBLogHandler',
+            'class': 'aiida.orm.utils.log.DBLogHandler'
         }
-        config['loggers']['aiida']['handlers'].append(handler_dblogger)
+        config['loggers']['aiida']['handlers'].append('db_logger')
 
     dictConfig(config)
 

aiida/manage/configuration/schema/config-v9.schema.json

@@ -47,6 +47,12 @@
           "default": "REPORT",
           "description": "Minimum level to log to daemon log and the `DbLog` table for the `aiida` logger"
         },
+        "logging.verdi_loglevel": {
+          "type": "string",
+          "enum": ["CRITICAL", "ERROR", "WARNING", "REPORT", "INFO", "DEBUG"],
+          "default": "REPORT",
+          "description": "Minimum level to log to console when running a `verdi` command"
+        },
         "logging.db_loglevel": {
           "type": "string",
           "enum": ["CRITICAL", "ERROR", "WARNING", "REPORT", "INFO", "DEBUG"],

docs/source/topics/cli.rst

@@ -127,6 +127,7 @@ is identical to
     verdi --verbosity debug process list
 
 When the option is specified multiple times, only the last value will be considered.
+If the `--verbosity` option is specified, it overrides the log level of all the loggers configured by AiiDA, e.g. `logging.aiida_loglevel`.
 
 
 .. _topics:cli:identifiers:

tests/cmdline/commands/test_storage.py

@@ -114,10 +114,9 @@ def mocked_migrate(self):  # pylint: disable=no-self-use
     assert 'passed error message' in result.output
 
 
-def tests_storage_maintain_logging(run_cli_command, monkeypatch, caplog):
+def tests_storage_maintain_logging(run_cli_command, monkeypatch):
     """Test all the information and cases of the storage maintain command."""
-    import logging
-
+    from aiida.common.log import AIIDA_LOGGER
     from aiida.manage import get_manager
     storage = get_manager().get_profile_storage()
 
@@ -133,56 +132,45 @@ def mock_maintain(*args, **kwargs):
         for key, val in kwargs.items():
             log_message += f' > {key}: {val}\n'
 
-        logging.info(log_message)
+        AIIDA_LOGGER.report(log_message)
 
     monkeypatch.setattr(storage, 'maintain', mock_maintain)
 
-    # Not passing user input Y or `--force` should causing the command to exit without executing `storage.mantain`
-    # Checking that no logs are produced in the with caplog context
-    with caplog.at_level(logging.INFO):
-        _ = run_cli_command(cmd_storage.storage_maintain, use_subprocess=False)
-
-    assert len(caplog.records) == 0
+    # Not passing user input should cause the command to exit without executing `storage.mantain` and so the last
+    # message should be the prompt to continue or not.
+    result = run_cli_command(cmd_storage.storage_maintain, use_subprocess=False)
+    message_list = result.output_lines
+    assert message_list[-1] == 'Are you sure you want continue in this mode? [y/N]: '
 
     # Test `storage.mantain` with `--force`
-    with caplog.at_level(logging.INFO):
-        _ = run_cli_command(cmd_storage.storage_maintain, parameters=['--force'], use_subprocess=False)
-
-    message_list = caplog.records[0].msg.splitlines()
+    result = run_cli_command(cmd_storage.storage_maintain, parameters=['--force'], use_subprocess=False)
+    message_list = result.output_lines
     assert ' > full: False' in message_list
     assert ' > dry_run: False' in message_list
 
     # Test `storage.mantain` with user input Y
-    with caplog.at_level(logging.INFO):
-        _ = run_cli_command(cmd_storage.storage_maintain, user_input='Y', use_subprocess=False)
-
-    message_list = caplog.records[1].msg.splitlines()
+    result = run_cli_command(cmd_storage.storage_maintain, user_input='Y', use_subprocess=False)
+    message_list = result.output_lines
     assert ' > full: False' in message_list
     assert ' > dry_run: False' in message_list
 
     # Test `storage.mantain` with `--dry-run`
-    with caplog.at_level(logging.INFO):
-        _ = run_cli_command(cmd_storage.storage_maintain, parameters=['--dry-run'], use_subprocess=False)
-
-    message_list = caplog.records[2].msg.splitlines()
+    result = run_cli_command(cmd_storage.storage_maintain, parameters=['--dry-run'], use_subprocess=False)
+    message_list = result.output_lines
     assert ' > full: False' in message_list
     assert ' > dry_run: True' in message_list
 
     # Test `storage.mantain` with `--full`
-    with caplog.at_level(logging.INFO):
-        run_cli_command(cmd_storage.storage_maintain, parameters=['--full'], user_input='Y', use_subprocess=False)
-
-    message_list = caplog.records[3].msg.splitlines()
+    result = run_cli_command(cmd_storage.storage_maintain, parameters=['--full'], user_input='Y', use_subprocess=False)
+    message_list = result.output_lines
     assert ' > full: True' in message_list
     assert ' > dry_run: False' in message_list
 
     # Test `storage.mantain` with `--full` and `--no-repack`
-    with caplog.at_level(logging.INFO):
-        run_cli_command(
-            cmd_storage.storage_maintain, parameters=['--full', '--no-repack'], user_input='Y', use_subprocess=False
-        )
-
-    message_list = caplog.records[4].msg.splitlines()
+    result = run_cli_command(
+        cmd_storage.storage_maintain, parameters=['--full', '--no-repack'], user_input='Y', use_subprocess=False
+    )
+    message_list = result.output_lines
     assert ' > full: True' in message_list
     assert ' > do_repack: False' in message_list
     assert ' > dry_run: False' in message_list

tests/cmdline/params/options/test_verbosity.py

@@ -12,10 +12,9 @@
 import functools
 import logging
 
-import click
 import pytest
 
-from aiida.cmdline.params import options
+from aiida.cmdline.commands.cmd_verdi import verdi
 from aiida.cmdline.utils import echo
 from aiida.common.log import AIIDA_LOGGER, LOG_LEVELS
 
@@ -26,13 +25,14 @@ def run_cli_command(run_cli_command):
     return functools.partial(run_cli_command, use_subprocess=False)
 
 
-@click.command()
-@options.VERBOSITY()
+@verdi.command('test')
 def cmd():
-    """Test command prints messages through the ``AIIDA_LOGGER`` and the ``CMDLINE_LOGGER``.
+    """Test command prints messages through the ``aiida`` and the ``verdi``.
 
-    The messages to the ``CMDLINE_LOGGER`` are performed indirect through the utilities of the ``echo`` module.
+    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]
+
     for log_level in LOG_LEVELS.values():
         AIIDA_LOGGER.log(log_level, 'aiida')
 
@@ -44,21 +44,35 @@ def cmd():
     echo.echo_critical('verdi')
 
 
+def verify_log_output(output: str, log_level_aiida: int, log_level_verdi: int):
+    """Verify that the expected log messages are in the output for the given log levels
+
+    :param output: The output written to stdout by the command.
+    :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():
+        prefix = log_level_name.capitalize()
+
+        if log_level >= log_level_aiida:
+            assert f'{prefix}: aiida' in output
+        else:
+            assert f'{prefix}: aiida' not in output
+
+        if log_level >= log_level_verdi:
+            assert f'{prefix}: verdi' in output
+        else:
+            assert f'{prefix}: verdi' not in output
+
+
 @pytest.mark.usefixtures('reset_log_level')
 def test_default(run_cli_command):
     """Test the command without explicitly specifying the verbosity.
 
     The default log level is ``REPORT`` so its messages and everything above should show and the rest not.
     """
     result = run_cli_command(cmd, raises=True)
-
-    for log_level_name, log_level in LOG_LEVELS.items():
-        if log_level >= logging.REPORT:  # pylint: disable=no-member
-            assert f'{log_level_name.capitalize()}: verdi' in result.output
-            assert f'{log_level_name.capitalize()}: aiida' in result.output
-        else:
-            assert f'{log_level_name.capitalize()}: verdi' not in result.output
-            assert f'{log_level_name.capitalize()}: aiida' not in result.output
+    verify_log_output(result.output, logging.REPORT, logging.REPORT)  # pylint: disable=no-member
 
 
 @pytest.mark.parametrize('option_log_level', [level for level in LOG_LEVELS.values() if level != logging.NOTSET])
@@ -67,42 +81,19 @@ def test_explicit(run_cli_command, option_log_level):
     """Test explicitly settings a verbosity"""
     log_level_name = logging.getLevelName(option_log_level)
     result = run_cli_command(cmd, ['--verbosity', log_level_name], raises=True)
+    verify_log_output(result.output, option_log_level, option_log_level)
 
-    for log_level_name, log_level in LOG_LEVELS.items():
-        if log_level >= option_log_level:
-            assert f'{log_level_name.capitalize()}: verdi' in result.output
-            assert f'{log_level_name.capitalize()}: aiida' in result.output
-        else:
-            assert f'{log_level_name.capitalize()}: verdi' not in result.output
-            assert f'{log_level_name.capitalize()}: aiida' not in result.output
-
-
-@pytest.mark.usefixtures('reset_log_level', 'override_logging')
-def test_config_aiida_loglevel(run_cli_command, caplog):
-    """Test the behavior of the ``--verbosity`` option when the ``logging.aiida_loglevel`` config option is set.
-
-    Even though the ``CMDLINE_LOGGER`` is technically a child of the ``AIIDA_LOGLEVEL`` and so normally the former
-    should not override the latter, that is actually the desired behavior. The option should ensure that it overrides
-    the value of the ``AIIDA_LOGGER`` that may be specified on the profile config.
-    """
-    # First log a ``DEBUG`` message to the ``AIIDA_LOGGER`` and capture it to see the logger is properly configured.
-    message = 'debug test message'
 
-    with caplog.at_level(logging.DEBUG):
-        AIIDA_LOGGER.debug(message)
-
-    assert message in caplog.text
-
-    # Now we invoke the command while passing a verbosity level that is higher than is configured for the
-    # ``AIIDA_LOGGER``. The explicit verbosity value should override the value configured on the profile.
-    option_log_level = logging.WARNING
-    option_log_level_name = logging.getLevelName(option_log_level)
-    result = run_cli_command(cmd, ['--verbosity', option_log_level_name], raises=True)
-
-    for log_level_name, log_level in LOG_LEVELS.items():
-        if log_level >= option_log_level:
-            assert f'{log_level_name.capitalize()}: verdi' in result.output
-            assert f'{log_level_name.capitalize()}: aiida' in result.output
-        else:
-            assert f'{log_level_name.capitalize()}: verdi' not in result.output
-            assert f'{log_level_name.capitalize()}: aiida' not in result.output
+@pytest.mark.usefixtures('reset_log_level')
+def test_config_option_override(run_cli_command, isolated_config):
+    """Test that config log levels are only overridden if the ``--verbosity`` is explicitly passed."""
+    isolated_config.set_option('logging.aiida_loglevel', 'ERROR', scope=None)
+    isolated_config.set_option('logging.verdi_loglevel', 'WARNING', scope=None)
+
+    # If ``--verbosity`` is not explicitly defined, values from the config options should be used.
+    result = run_cli_command(cmd, raises=True, use_subprocess=False)
+    verify_log_output(result.output, logging.ERROR, logging.WARNING)
+
+    # 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)