CLI: rework the logging verbosity implementation

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