CLI: Fix error in aiida.cmdline.utils.log.CliFormatter (#5957)

The `CliFormatter` could raise an exception if the record message
contained named parameters, but the `args` is a tuple. An example is
when the `QueryBuilder` would log the prepared SQL statement, e.g.:

    SELECT t.pk FROM t WHERE t.pk = %(pk_1)s

The `%(pk_1)s` here is indeed a named parameter, but not intended to be
formatted for the log message itself, but to be kept as is. However, the
log formatter does not know this and would attempt to format it with the
given `args`, which would be the empty tuple. This would raise:

    TypeError: format requires a mapping

The `CliFormatter.format` didn't account for this case. Instead of
fixing it there, the class now just refers to the base `Formatter` class
to format the record, which does the right thing in this case, and the
`CliFormatter` simply adds the prefix to the formatted message if
necessary.

aiida/cmdline/utils/log.py

@@ -43,8 +43,7 @@ def emit(self, record):
 class CliFormatter(logging.Formatter):
     """Formatter that automatically prefixes log messages with a colored version of the log level."""
 
-    @staticmethod
-    def format(record):
+    def format(self, record):
         """Format the record using the style required for the command line interface."""
         try:
             fg = COLORS[record.levelname.lower()]
@@ -56,10 +55,9 @@ def format(record):
         except AttributeError:
             prefix = None
 
-        if prefix:
-            return f'{click.style(record.levelname.capitalize(), fg=fg, bold=True)}: {record.msg % record.args}'
+        formatted = super().format(record)
 
-        if record.args:
-            return f'{record.msg % record.args}'
+        if prefix:
+            return f'{click.style(record.levelname.capitalize(), fg=fg, bold=True)}: {formatted}'
 
-        return record.msg
+        return formatted

tests/cmdline/utils/test_log.py

@@ -19,25 +19,37 @@ def test_cli_formatter():
     Note that if it contains percentage signs but no arguments, it should not try to convert it.
     """
     message = 'message'
-    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, message, (), 'exc_info')
-    assert log.CliFormatter.format(record) == message
+    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, message, (), None)
+    assert log.CliFormatter().format(record) == message
 
 
 def test_cli_formatter_no_args():
     """Test the ``CliFormatter.format`` method for a message with percentage signs but no args."""
     message = 'PID    MEM %    CPU %  started'
-    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, message, (), 'exc_info')
-    assert log.CliFormatter.format(record) == message
+    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, message, (), None)
+    assert log.CliFormatter().format(record) == message
+
+
+def test_cli_formatter_named_parameters():
+    """Test the ``CliFormatter.format`` method for a message with named parameters but no args.
+
+    This can occur for example when logging prepared SQL queries. These contain named parameters, but are not actually
+    intended to be filled with arguments passed to the logging call but are supposed to be kept as is. When no arguments
+    are passed in the log record, this should not except.
+    """
+    message = 'SELECT t.pk FROM t WHERE t.pk = %(pk_1)s'
+    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, message, (), None)
+    assert log.CliFormatter().format(record) == message
 
 
 def test_cli_formatter_args():
     """Test the ``CliFormatter.format`` method for a message with a single argument."""
-    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, 'Some %s', ('value',), 'exc_info')
-    assert log.CliFormatter.format(record) == 'Some value'
+    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, 'Some %s', ('value',), None)
+    assert log.CliFormatter().format(record) == 'Some value'
 
 
 def test_cli_formatter_prefix():
     """Test the ``CliFormatter.format`` method for a message with a single argument."""
-    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, 'Some %s', ('value',), 'exc_info')
+    record = logging.LogRecord('name', logging.INFO, 'pathname', 0, 'Some %s', ('value',), None)
     record.prefix = True
-    assert log.CliFormatter.format(record) == '\x1b[34m\x1b[1mInfo\x1b[0m: Some value'
+    assert log.CliFormatter().format(record) == '\x1b[34m\x1b[1mInfo\x1b[0m: Some value'