From 66a2dcedd0a9428b5b2218b8c82bad9c9aff4956 Mon Sep 17 00:00:00 2001 From: Sebastiaan Huber Date: Fri, 28 Jun 2024 16:48:00 +0200 Subject: [PATCH] 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 | 7 +++++-- tests/cmdline/params/options/test_verbosity.py | 15 +++++++++------ 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/src/aiida/cmdline/params/options/main.py b/src/aiida/cmdline/params/options/main.py index aa86a1f0dd..f5eb2d551f 100644 --- a/src/aiida/cmdline/params/options/main.py +++ b/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 diff --git a/tests/cmdline/params/options/test_verbosity.py b/tests/cmdline/params/options/test_verbosity.py index 3544962b38..3573edd54f 100644 --- a/tests/cmdline/params/options/test_verbosity.py +++ b/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)