Hacking log format arg check

Added hacking check for log lines that accidently pass a tuple as the
second argument when providing format arguments.

Change-Id: Ifba23948f9fb49e9f6a1ee7e743aba0cd864c827
Closes-Bug: 1415241

HACKING.rst

@@ -26,6 +26,7 @@ Cinder Specific Commandments
 - [C307] LOG.warn is deprecated. Enforce use of LOG.warning.
 - [C308] timeutils.isotime() must not be used (deprecated).
 - [C309] Unit tests should not perform logging.
+- [C310] Check for improper use of logging format arguments.
 
 General
 -------

cinder/hacking/checks.py

@@ -14,6 +14,7 @@
 
 import ast
 import re
+import six
 
 """
 Guidelines for writing new hacking checks
@@ -202,6 +203,71 @@ class CheckForStrUnicodeExc(BaseASTChecker):
         super(CheckForStrUnicodeExc, self).generic_visit(node)
 
 
+class CheckLoggingFormatArgs(BaseASTChecker):
+    """Check for improper use of logging format arguments.
+
+    LOG.debug("Volume %s caught fire and is at %d degrees C and climbing.",
+              ('volume1', 500))
+
+    The format arguments should not be a tuple as it is easy to miss.
+
+    """
+
+    CHECK_DESC = 'C310 Log method arguments should not be a tuple.'
+    LOG_METHODS = [
+        'debug', 'info',
+        'warn', 'warning',
+        'error', 'exception',
+        'critical', 'fatal',
+        'trace', 'log'
+    ]
+
+    def _find_name(self, node):
+        """Return the fully qualified name or a Name or Attribute."""
+        if isinstance(node, ast.Name):
+            return node.id
+        elif (isinstance(node, ast.Attribute)
+                and isinstance(node.value, (ast.Name, ast.Attribute))):
+            method_name = node.attr
+            obj_name = self._find_name(node.value)
+            if obj_name is None:
+                return None
+            return obj_name + '.' + method_name
+        elif isinstance(node, six.string_types):
+            return node
+        else:  # could be Subscript, Call or many more
+            return None
+
+    def visit_Call(self, node):
+        """Look for the 'LOG.*' calls."""
+        # extract the obj_name and method_name
+        if isinstance(node.func, ast.Attribute):
+            obj_name = self._find_name(node.func.value)
+            if isinstance(node.func.value, ast.Name):
+                method_name = node.func.attr
+            elif isinstance(node.func.value, ast.Attribute):
+                obj_name = self._find_name(node.func.value)
+                method_name = node.func.attr
+            else:  # could be Subscript, Call or many more
+                return super(CheckLoggingFormatArgs, self).generic_visit(node)
+
+            # obj must be a logger instance and method must be a log helper
+            if (obj_name != 'LOG'
+                    or method_name not in self.LOG_METHODS):
+                return super(CheckLoggingFormatArgs, self).generic_visit(node)
+
+            # the call must have arguments
+            if not len(node.args):
+                return super(CheckLoggingFormatArgs, self).generic_visit(node)
+
+            # any argument should not be a tuple
+            for arg in node.args:
+                if isinstance(arg, ast.Tuple):
+                    self.add_error(arg)
+
+        return super(CheckLoggingFormatArgs, self).generic_visit(node)
+
+
 def validate_log_translations(logical_line, filename):
     # Translations are not required in the test directory.
     # This will not catch all instances of violations, just direct
@@ -326,6 +392,7 @@ def factory(register):
     register(no_mutable_default_args)
     register(check_explicit_underscore_import)
     register(CheckForStrUnicodeExc)
+    register(CheckLoggingFormatArgs)
     register(check_oslo_namespace_imports)
     register(check_datetime_now)
     register(check_timeutils_strtime)

cinder/tests/unit/test_hacking.py

@@ -144,6 +144,37 @@ class HackingTestCase(test.TestCase):
     def _assert_has_no_errors(self, code, checker, filename=None):
         self._assert_has_errors(code, checker, filename=filename)
 
+    def test_logging_format_args(self):
+        checker = checks.CheckLoggingFormatArgs
+        code = """
+               import logging
+               LOG = logging.getLogger()
+               LOG.info("Message without a second argument.")
+               LOG.critical("Message with %s arguments.", 'two')
+               LOG.debug("Volume %s caught fire and is at %d degrees C and"
+                         " climbing.", 'volume1', 500)
+               """
+        self._assert_has_no_errors(code, checker)
+
+        code = """
+               import logging
+               LOG = logging.getLogger()
+               LOG.{0}("Volume %s caught fire and is at %d degrees C and "
+                      "climbing.", ('volume1', 500))
+               """
+        for method in checker.LOG_METHODS:
+            self._assert_has_errors(code.format(method), checker,
+                                    expected_errors=[(4, 21, 'C310')])
+
+        code = """
+               import logging
+               LOG = logging.getLogger()
+               LOG.log(logging.DEBUG, "Volume %s caught fire and is at %d"
+                       " degrees C and climbing.", ('volume1', 500))
+               """
+        self._assert_has_errors(code, checker,
+                                expected_errors=[(4, 37, 'C310')])
+
     def test_str_unicode_exception(self):
 
         checker = checks.CheckForStrUnicodeExc

cinder/volume/drivers/netapp/eseries/library.py

@@ -1182,8 +1182,8 @@ class NetAppESeriesLibrary(object):
                     try:
                         self._client.delete_volume(vol['volumeRef'])
                     except exception.NetAppDriverException as e:
-                        LOG.debug("Error deleting vol with label %s: %s",
-                                  (label, e))
+                        LOG.debug("Error deleting vol with label %(label)s:"
+                                  " %(error)s.", {'label': label, 'error': e})
         finally:
             na_utils.set_safe_attr(self, 'clean_job_running', False)