CLI: rework the logging verbosity implementation

The intended behavior of logging of the system when invoked through the
command line interface `verdi` is as follows:

 * The verbosity of output produced by invoked CLI commands can be
   controlled through a single `-v/--verbosity` option that is accepted
   by the CLI at every command level.
 * It takes the values of the log levels of Python's logging system,
   including AiiDA's custom `REPORT` level.
 * The verbosity level should be applied to all logging messages, so not
   just those messages that are logged directly by the command itself,
   but also any messages logged by module code that is indirectly called
   in the stack.

Given that the implementation is built on top of the logging system, the
log level set by the verbosity option has to be added to the logging
configuration somehow. The logging is configured by invoking the method
`aiida.common.log.configure_logging` which consumes a dictionary with
the logging configuration that has certain fields that are dynamically
determined from the loaded profile. Unfortunately, this method can be
called by module code as well, therefore, the verbosity option can not
rely on using this method to configure the logging. Because once the
callback is finished, any other code invoked by the command that calls
this same method, will undo the changes of the verbosity option.

The original implementation attempted to solve this problem by storing
the selected log level through the verbosity option, in the profile
instance loaded in memory. Since the log level would be read dynamically
from the profile in the `configure_logging` method, even when it would
be recalled, the correct log level would be configured.

This approach had various disadvantages, however. It tied the option
closely to the concept of a profile. Even though all `verdi` commands
have the profile option added by default and therefore this does not
really pose a problem, it made the verbosity option useless in any other
context. The tight coupling also made the logic more difficult to
understand. Finally, even though the change of the profile setting was
only made in memory and so in principle the change should be temporary
within the scope of the CLI command, if the command decided to store the
profile, which can for example happen in commands that are designed to
change the profile, the change in log level option would also be written
to disk, causing an undesirable side effect of this implementation.

Here, we change the implementation by fully decoupling the verbosity
option from the profile and simply having the callback write the
selected log level to a global constant in the `aiida.common.log` module
called `CLI_LOG_LEVEL`. The `configure_logging` module will check this
constant and when set, will configure all loggers with the `cli` handler
with the correspondig log level. This design still has a downside in
that it hard-couples the generic `aiida.common.log` module to the more
specific `aiida.cmdline` module, but it is not obvious to get the CLI
dependent log level injected into this module some other way.

Finally, the original implementation allowed a default value for the
verbosity option to be configured through the config by setting the
`logging.aiida_loglevel` option. However, since that also determines the
log level for AiiDA when not run through the CLI, i.e. during normal
operations, this could have undesirable side-effects. For example, if
the option was set to `WARNING` to temporarily limit the number of logs
from processes when being run, certain CLI commands would also no longer
report any output.

aiida/cmdline/commands/cmd_profile.py

@@ -26,7 +26,6 @@ def verdi_profile():
 @verdi_profile.command('list')
 def profile_list():
     """Display a list of all available profiles."""
-
     try:
         config = get_config()
     except (exceptions.MissingConfigurationError, exceptions.ConfigurationError) as exception:

aiida/cmdline/commands/cmd_verdi.py

@@ -104,25 +104,10 @@ def group(self, *args, **kwargs):
 
 
 @click.command(cls=VerdiCommandGroup, context_settings={'help_option_names': ['--help']})
-@options.PROFILE(type=types.ProfileParamType(load_profile=True))
-@options.VERBOSITY(expose_value=True)
+@options.PROFILE(type=types.ProfileParamType(load_profile=True), expose_value=False)
+@options.VERBOSITY()
 # Note, __version__ should always be passed explicitly here,
 # because click does not retrieve a dynamic version when installed in editable mode
 @click.version_option(__version__, '--version', message='AiiDA version %(version)s')
-@click.pass_context
-def verdi(ctx, profile, verbosity):
+def verdi():
     """The command line interface of AiiDA."""
-    from aiida.common import extendeddicts
-    from aiida.manage.configuration import get_config
-
-    if ctx.obj is None:
-        ctx.obj = extendeddicts.AttributeDict()
-
-    ctx.obj.config = get_config()
-    ctx.obj.profile = profile
-
-    # Manually set the log level on the profile if both are defined. Normally this is done automatically by the callback
-    # of the verbosity option, but for the top level `verdi` command, when the callback is invoked, the profile has not
-    # been parsed and set yet.
-    if profile is not None and verbosity is not None:
-        ctx.obj.profile.set_option('logging.aiida_loglevel', verbosity)

aiida/cmdline/params/options/main.py

@@ -90,18 +90,19 @@ def decorator(command):
     return decorator
 
 
-def set_log_level(ctx, __, value):
-    """Set the log level for the global ``AIIDA_LOGGER``.
+def set_log_level(_ctx, _param, value):
+    """Fix the log level for all loggers from the cli.
 
     Note that we cannot use the most obvious approach of directly setting the level on the ``AIIDA_LOGGER``. 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 ``logging.aiida_loglevel`` option of the profile that is currently loaded, which is the profile that was
-    selected for this CLI call and is stored in memory. If the logging is reconfigured, the correct log level will be
-    retrieved from the current profile and set on the loggers.
+    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.
     """
-    if value is None:
-        return
+    from aiida.common import log
 
     try:
         log_level = value.upper()
@@ -111,19 +112,10 @@ def set_log_level(ctx, __, value):
     if log_level not in LOG_LEVELS:
         raise click.BadParameter(f'`{log_level}` is not a valid log level.')
 
-    try:
-        profile = ctx.obj.profile
-    except AttributeError:
-        # This can occur when the command is not invoked from the command line but directly, for example during testing,
-        # which won't go through the actual ``verdi`` command which is what initializes the ``obj`` attribute and sets
-        # the profile on it.
-        from aiida.manage.configuration import get_profile
-        profile = get_profile()
+    log.CLI_LOG_LEVEL = log_level
 
-    if profile is not None:
-        profile.set_option('logging.aiida_loglevel', log_level)
-        # Make sure the value is currently loaded, even if it may be undone in the future by another call to this method
-        configure_logging(cli=True)
+    # Make sure the logging is configured, even if it may be undone in the future by another call to this method.
+    configure_logging()
 
     return log_level
 
@@ -132,6 +124,7 @@ def set_log_level(ctx, __, 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/params/types/profile.py

@@ -30,6 +30,7 @@ def deconvert_default(value):
 
     def convert(self, value, param, ctx):
         """Attempt to match the given value to a valid profile."""
+        from aiida.common import extendeddicts
         from aiida.common.exceptions import MissingConfigurationError, ProfileConfigurationError
         from aiida.manage.configuration import get_config, load_profile, Profile
 
@@ -51,6 +52,12 @@ def convert(self, value, param, ctx):
         if self._load_profile:
             load_profile(profile.name)
 
+        if ctx.obj is None:
+            ctx.obj = extendeddicts.AttributeDict()
+
+        ctx.obj.config = config
+        ctx.obj.profile = profile
+
         return profile
 
     def complete(self, ctx, incomplete):  # pylint: disable=unused-argument,no-self-use

aiida/cmdline/utils/decorators.py

@@ -37,7 +37,6 @@ def load_backend_if_not_loaded():
     If no profile has been loaded yet, the default profile will be loaded first. A spinner will be shown during both
     actions to indicate that the function is working and has not crashed, since loading can take a second.
     """
-    from aiida.common.log import configure_logging
     from aiida.manage.configuration import get_profile, load_profile
     from aiida.manage.manager import get_manager
 
@@ -47,10 +46,6 @@ def load_backend_if_not_loaded():
         with spinner():
             load_profile()  # This will load the default profile if no profile has already been loaded
             manager.get_backend()  # This will load the backend of the loaded profile, if not already loaded
-            # Loading the backend will have reconfigured the logging (see ``Manager._load_backend`` which calls the
-            # ``aiida.common.log.configure_logging`` function but with the default ``cli=False``), so here we have to
-            # call it again to ensure that the correct CLI handlers and formatters are configured.
-            configure_logging(with_orm=True, cli=True)
 
 
 def with_dbenv():

aiida/common/log.py

@@ -44,6 +44,7 @@ def report(self, msg, *args, **kwargs):
 }
 
 AIIDA_LOGGER = logging.getLogger('aiida')
+CLI_LOG_LEVEL = None
 
 
 # The default logging dictionary for AiiDA that can be used in conjunction
@@ -81,7 +82,7 @@ def get_logging_config():
             'aiida': {
                 'handlers': ['console'],
                 'level': lambda: get_config_option('logging.aiida_loglevel'),
-                'propagate': False,
+                'propagate': True,
             },
             'aiida.cmdline': {
                 'handlers': ['cli'],
@@ -145,7 +146,7 @@ def evaluate_logging_configuration(dictionary):
     return result
 
 
-def configure_logging(with_orm=False, daemon=False, daemon_log_file=None, cli=False):
+def configure_logging(with_orm=False, daemon=False, daemon_log_file=None):
     """
     Setup the logging by retrieving the LOGGING dictionary from aiida and passing it to
     the python module logging.config.dictConfig. If the logging needs to be setup for the
@@ -194,9 +195,9 @@ def configure_logging(with_orm=False, daemon=False, daemon_log_file=None, cli=Fa
             except ValueError:
                 pass
 
-    if cli is True:
-        for logger in config['loggers'].values():
-            logger['handlers'] = ['cli']
+    if CLI_LOG_LEVEL is not None:
+        config['loggers']['aiida']['handlers'] = ['cli']
+        config['loggers']['aiida']['level'] = CLI_LOG_LEVEL
 
     # Add the `DbLogHandler` if `with_orm` is `True`
     if with_orm:

docs/source/topics/cli.rst

@@ -127,18 +127,6 @@ is identical to
     verdi --verbosity debug process list
 
 When the option is specified multiple times, only the last value will be considered.
-The default value for the logging level can be changed permanently through the configuration system.
-For example, to set the default log level to ``WARNING``,
-
-.. code:: console
-
-    verdi config set logging.aiida_loglevel WARNING
-
-This is identical to passing ``--verbosity WARNING`` manually to each invoked command.
-
-.. warning:: Setting the configuration option does not just affect the verbosity of the command line, but the logging for all of AiiDA.
-    For example, it also affects the verbosity of process reports, such as those of work chains.
-    If the log level is set above ``REPORT``, the reports of work chains will no longer be logged.
 
 
 .. _topics:cli:identifiers:

tests/cmdline/commands/test_run.py

@@ -16,6 +16,7 @@
 
 from aiida.backends.testbase import AiidaTestCase
 from aiida.cmdline.commands import cmd_run
+from aiida.common.log import override_log_level
 
 
 class TestVerdiRun(AiidaTestCase):
@@ -281,7 +282,8 @@ def test_autogroup_filter_class(self):  # pylint: disable=too-many-locals
                 fhandle.flush()
 
                 options = ['--auto-group'] + flags + ['--', fhandle.name, str(idx)]
-                result = self.cli_runner.invoke(cmd_run.run, options)
+                with override_log_level():
+                    result = self.cli_runner.invoke(cmd_run.run, options)
                 self.assertClickResultNoException(result)
 
                 pk1_str, pk2_str, pk3_str, pk4_str, pk5_str, pk6_str = result.output.split()

tests/cmdline/params/options/test_verbosity.py

@@ -0,0 +1,100 @@
+# -*- coding: utf-8 -*-
+###########################################################################
+# Copyright (c), The AiiDA team. All rights reserved.                     #
+# This file is part of the AiiDA code.                                    #
+#                                                                         #
+# The code is hosted on GitHub at https://github.com/aiidateam/aiida-core #
+# For further information on the license, see the LICENSE.txt file        #
+# For further information please visit http://www.aiida.net               #
+###########################################################################
+"""Tests for the :class:`~aiida.cmdline.params.options.main.VERBOSITY` option."""
+import logging
+
+import click
+import pytest
+
+from aiida.cmdline.utils import echo
+from aiida.cmdline.params import options
+from aiida.common.log import AIIDA_LOGGER, LOG_LEVELS
+
+
+@click.command()
+@options.VERBOSITY()
+def cmd():
+    """Test command prints messages through the ``AIIDA_LOGGER`` and the ``CMDLINE_LOGGER``.
+
+    The messages to the ``CMDLINE_LOGGER`` are performed indirect through the utilities of the ``echo`` module.
+    """
+    for log_level in LOG_LEVELS.values():
+        AIIDA_LOGGER.log(log_level, 'aiida')
+
+    echo.echo_debug('verdi')
+    echo.echo_info('verdi')
+    echo.echo_report('verdi')
+    echo.echo_warning('verdi')
+    echo.echo_error('verdi')
+    echo.echo_critical('verdi')
+
+
+@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
+
+
+@pytest.mark.parametrize('option_log_level', [level for level in 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"""
+    log_level_name = logging.getLevelName(option_log_level)
+    result = run_cli_command(cmd, ['--verbosity', 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', '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