CLI: ensure all loggers have a custom formatter

So far, the utility functions of the `aiida.cmdline.utils.echo` module
have been rerouted through the `CMDLINE_LOGGER` which properly formats
the log message with just the message itself. However, the loggers of
any other modules will inherit the formatter of the parent `AIIDA_LOGGER`
which will prefix the message with verbose content such as the
timestamp, name of the logger and more, which is not what we want for
output generated by CLI commands.

The solution is to define a custom formatter, `CliFormatter`, which is
added to the new module `aiida.cmdline.utils.log`, and which is
configured by default for the `CMDLINE_LOGGER`. The `configure_logging`
function is updated to now take a keyword argument `cli`, which when set
to `True`, will configure this new formatter for all loggers. By calling
this method with `cli=True` in the callback of the `VERBOSITY` option,
all loggers should be correctly configured to only print the message
with the log level prefixed, when invoked through the CLI.

There is one peculiarity where the `load_backend_if_not_loaded`
decorator utility also needs to call the `configure_logging` function.
The reason is that this function loads the database backend, which
indirectly calls the `configure_logging` to add the database log
handler, but this does not pass `cli=True`. This means that the CLI
specific configuration is undone.

aiida/cmdline/params/options/main.py

@@ -123,7 +123,7 @@ def set_log_level(ctx, __, value):
     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()
+        configure_logging(cli=True)
 
     return log_level
 

aiida/cmdline/utils/decorators.py

@@ -37,6 +37,7 @@ 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
 
@@ -46,6 +47,10 @@ 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/cmdline/utils/echo.py

@@ -46,7 +46,7 @@ class ExitCode(enum.IntEnum):
 def echo(message: str, fg: str = None, bold: bool = False, nl: bool = True, err: bool = False) -> None:
     """Log a message to the cmdline logger.
 
-    .. note:: The message will be logged at the ``REPORT`` level.
+    .. note:: The message will be logged at the ``REPORT`` level but always without the log level prefix.
 
     :param message: the message to log.
     :param fg: if provided this will become the foreground color.
@@ -55,95 +55,89 @@ def echo(message: str, fg: str = None, bold: bool = False, nl: bool = True, err:
     :param err: whether to log to stderr.
     """
     message = click.style(message, fg=fg, bold=bold)
-    CMDLINE_LOGGER.report(message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.report(message, extra=dict(nl=nl, err=err, prefix=False))
 
 
 def echo_debug(message: str, bold: bool = False, nl: bool = True, err: bool = False, prefix: bool = True) -> None:
-    """Log a debug message to the cmdline logger, prefixed with 'Debug:'
+    """Log a debug message to the cmdline logger.
 
     :param message: the message to log.
     :param bold: whether to format the message in bold.
     :param nl: whether to add a newline at the end of the message.
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Debug: ', fg=COLORS['debug'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.debug(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.debug(message, extra=dict(nl=nl, err=err, prefix=prefix))
 
 
 def echo_info(message: str, bold: bool = False, nl: bool = True, err: bool = False, prefix: bool = True) -> None:
-    """Log an info message to the cmdline logger, prefixed with 'Info:'
+    """Log an info message to the cmdline logger.
 
     :param message: the message to log.
     :param bold: whether to format the message in bold.
     :param nl: whether to add a newline at the end of the message.
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Info: ', fg=COLORS['info'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.info(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.info(message, extra=dict(nl=nl, err=err, prefix=prefix))
 
 
 def echo_report(message: str, bold: bool = False, nl: bool = True, err: bool = False, prefix: bool = True) -> None:
-    """Log an report message to the cmdline logger, prefixed with 'Report:'
+    """Log an report message to the cmdline logger.
 
     :param message: the message to log.
     :param bold: whether to format the message in bold.
     :param nl: whether to add a newline at the end of the message.
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Report: ', fg=COLORS['report'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.report(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.report(message, extra=dict(nl=nl, err=err, prefix=prefix))
 
 
 def echo_success(message: str, bold: bool = False, nl: bool = True, err: bool = False, prefix: bool = True) -> None:
-    """Log a success message to the cmdline logger, prefixed with 'Success:'
+    """Log a success message to the cmdline logger.
 
     :param message: the message to log.
     :param bold: whether to format the message in bold.
     :param nl: whether to add a newline at the end of the message.
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Success: ', fg=COLORS['success'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.report(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.report(message, extra=dict(nl=nl, err=err, prefix=prefix))
 
 
 def echo_warning(message: str, bold: bool = False, nl: bool = True, err: bool = False, prefix: bool = True) -> None:
-    """Log a warning message to the cmdline logger, prefixed with 'Warning:'
+    """Log a warning message to the cmdline logger.
 
     :param message: the message to log.
     :param bold: whether to format the message in bold.
     :param nl: whether to add a newline at the end of the message.
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Warning: ', fg=COLORS['warning'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.warning(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.warning(message, extra=dict(nl=nl, err=err, prefix=prefix))
 
 
 def echo_error(message: str, bold: bool = False, nl: bool = True, err: bool = True, prefix: bool = True) -> None:
-    """Log an error message to the cmdline logger, prefixed with 'Error:'
+    """Log an error message to the cmdline logger.
 
     :param message: the message to log.
     :param bold: whether to format the message in bold.
     :param nl: whether to add a newline at the end of the message.
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Error: ', fg=COLORS['error'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.error(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.error(message, extra=dict(nl=nl, err=err, prefix=prefix))
 
 
 def echo_critical(message: str, bold: bool = False, nl: bool = True, err: bool = True, prefix: bool = True) -> None:
-    """Log a critical error message to the cmdline logger, prefixed with 'Critical:' and exit with ``exit_status``.
+    """Log a critical error message to the cmdline logger and exit with ``exit_status``.
 
     This should be used to print messages for errors that cannot be recovered from and so the script should be directly
     terminated with a non-zero exit status to indicate that the command failed.
@@ -154,9 +148,8 @@ def echo_critical(message: str, bold: bool = False, nl: bool = True, err: bool =
     :param err: whether to log to stderr.
     :param prefix: whether the message should be prefixed with a colored version of the log level.
     """
-    prefix = click.style('Critical: ', fg=COLORS['critical'], bold=True) if prefix else ''
     message = click.style(message, bold=bold)
-    CMDLINE_LOGGER.critical(prefix + message, extra=dict(nl=nl, err=err))
+    CMDLINE_LOGGER.critical(message, extra=dict(nl=nl, err=err, prefix=prefix))
     sys.exit(ExitCode.CRITICAL)
 
 

aiida/cmdline/utils/log.py

@@ -0,0 +1,57 @@
+# -*- coding: utf-8 -*-
+"""Utilities for logging in the command line interface context."""
+import logging
+
+import click
+
+from .echo import COLORS
+
+
+class CliHandler(logging.Handler):
+    """Handler for writing to the console using click."""
+
+    def emit(self, record):
+        """Emit log record via click.
+
+        Can make use of special attributes 'nl' (whether to add newline) and 'err' (whether to print to stderr), which
+        can be set via the 'extra' dictionary parameter of the logging methods.
+        """
+        try:
+            nl = record.nl
+        except AttributeError:
+            nl = True
+
+        try:
+            err = record.err
+        except AttributeError:
+            err = False
+
+        try:
+            prefix = record.prefix
+        except AttributeError:
+            prefix = True
+
+        record.prefix = prefix
+
+        try:
+            msg = self.format(record)
+            click.echo(msg, err=err, nl=nl)
+        except Exception:  # pylint: disable=broad-except
+            self.handleError(record)
+
+
+class CliFormatter(logging.Formatter):
+    """Formatter that automatically prefixes log messages with a colored version of the log level."""
+
+    @staticmethod
+    def format(record):
+        """Format the record using the style required for the command line interface."""
+        try:
+            fg = COLORS[record.levelname.lower()]
+        except KeyError:
+            fg = 'white'
+
+        if record.prefix:
+            return f'{click.style(record.levelname.capitalize(), fg=fg, bold=True)}: {record.msg % record.args}'
+
+        return f'{record.msg % record.args}'

aiida/common/log.py

@@ -48,30 +48,6 @@ def report(self, msg, *args, **kwargs):
 AIIDA_LOGGER = logging.getLogger('aiida')
 
 
-class ClickHandler(logging.Handler):
-    """Handler for writing to the console using click."""
-
-    def emit(self, record):
-        """Emit log record via click.
-        Can make use of special attributes 'nl' (whether to add newline) and 'err' (whether to print to stderr), which
-        can be set via the 'extra' dictionary parameter of the logging methods.
-        """
-        import click
-        try:
-            msg = self.format(record)
-            try:
-                nl = record.nl
-            except AttributeError:
-                nl = True
-            try:
-                err = record.err
-            except AttributeError:
-                err = False
-            click.echo(msg, err=err, nl=nl)
-        except Exception:  # pylint: disable=broad-except
-            self.handleError(record)
-
-
 # The default logging dictionary for AiiDA that can be used in conjunction
 # with the config.dictConfig method of python's logging module
 def get_logging_config():
@@ -89,14 +65,18 @@ def get_logging_config():
                 'format': '%(asctime)s <%(process)d> %(name)s: [%(levelname)s] %(message)s',
                 'datefmt': '%m/%d/%Y %I:%M:%S %p',
             },
+            'cli': {
+                'class': 'aiida.cmdline.utils.log.CliFormatter'
+            }
         },
         'handlers': {
             'console': {
                 'class': 'logging.StreamHandler',
                 'formatter': 'halfverbose',
             },
-            'click': {
-                'class': 'aiida.common.log.ClickHandler',
+            'cli': {
+                'class': 'aiida.cmdline.utils.log.CliHandler',
+                'formatter': 'cli',
             }
         },
         'loggers': {
@@ -106,7 +86,7 @@ def get_logging_config():
                 'propagate': False,
             },
             'aiida.cmdline': {
-                'handlers': ['click'],
+                'handlers': ['cli'],
                 'propagate': False,
             },
             'plumpy': {
@@ -167,7 +147,7 @@ def evaluate_logging_configuration(dictionary):
     return result
 
 
-def configure_logging(with_orm=False, daemon=False, daemon_log_file=None):
+def configure_logging(with_orm=False, daemon=False, daemon_log_file=None, cli=False):
     """
     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
@@ -216,6 +196,10 @@ def configure_logging(with_orm=False, daemon=False, daemon_log_file=None):
             except ValueError:
                 pass
 
+    if cli is True:
+        for logger in config['loggers'].values():
+            logger['handlers'] = ['cli']
+
     # Add the `DbLogHandler` if `with_orm` is `True`
     if with_orm: