Do not supply logging arguments as tuple.

Logging format arguments are not supposed to be tuples, but
are rather to be supplied separately - i.e., use
   LOG.debug('%s is %s', arg1, arg2)
instead of
   LOG.debug('%s is %s', (arg1, arg2))

Rid the manila codebase of this logging format error and
add a hacking check for this.  The hacking check will not
catch all corner cases but should help prevent this error
in most cases.

Change-Id: Ibea39f1f90c0444eae5cfcd6090b2a00d84ab923
Closes-Bug: #1585394

HACKING.rst

@@ -9,6 +9,7 @@ Manila Style Commandments
 Manila Specific Commandments
 ----------------------------
 
+- [M310] Check for improper use of logging format arguments.
 - [M312] Use assertIsNone(...) instead of assertEqual(None, ...).
 - [M313] Use assertTrue(...) rather than assertEqual(True, ...).
 - [M319] Validate that debug level logs are not translated.

manila/hacking/checks.py

@@ -15,6 +15,7 @@
 
 import ast
 import re
+import six
 
 import pep8
 
@@ -122,6 +123,71 @@ def no_translate_debug_logs(logical_line, filename):
         yield(0, "M319 Don't translate debug level logs")
 
 
+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 = 'M310 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, physical_line, filename):
     # Translations are not required in the test and tempest
     # directories.
@@ -279,8 +345,9 @@ def validate_assertIsNone(logical_line):
 def factory(register):
     register(validate_log_translations)
     register(check_explicit_underscore_import)
-    register(CheckForStrUnicodeExc)
     register(no_translate_debug_logs)
+    register(CheckForStrUnicodeExc)
+    register(CheckLoggingFormatArgs)
     register(CheckForTransAdd)
     register(check_oslo_namespace_imports)
     register(dict_constructor_with_list_copy)

manila/share/drivers/ibm/gpfs.py

@@ -396,8 +396,9 @@ class GPFSShareDriver(driver.ExecuteMixin, driver.GaneshaMixin,
         sharename = snapshot['share_name']
         snapshotname = snapshot['name']
         fsdev = self._get_gpfs_device()
-        LOG.debug("sharename = %s, snapshotname = %s, fsdev = %s",
-                  (sharename, snapshotname, fsdev))
+        LOG.debug("sharename = %{share}s, snapshotname = %{snap}s, "
+                  "fsdev = %{dev}s",
+                  {'share': sharename, 'snap': snapshotname, 'dev': fsdev})
 
         try:
             self._gpfs_execute('mmcrsnapshot', fsdev, snapshot['name'],

manila/tests/test_hacking.py

@@ -15,6 +15,7 @@
 import sys
 import textwrap
 
+import ddt
 import mock
 import pep8
 
@@ -22,6 +23,7 @@ from manila.hacking import checks
 from manila import test
 
 
+@ddt.ddt
 class HackingTestCase(test.TestCase):
     """Hacking test cases
 
@@ -127,6 +129,30 @@ 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_no_tuple_arguments(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)
+
+    @ddt.data(*checks.CheckLoggingFormatArgs.LOG_METHODS)
+    def test_logging_with_tuple_argument(self, log_method):
+        checker = checks.CheckLoggingFormatArgs
+        code = """
+               import logging
+               LOG = logging.getLogger()
+               LOG.{0}("Volume %s caught fire and is at %d degrees C and "
+                      "climbing.", ('volume1', 500))
+               """
+        self._assert_has_errors(code.format(log_method), checker,
+                                expected_errors=[(4, 21, 'M310')])
+
     def test_str_on_exception(self):
 
         checker = checks.CheckForStrUnicodeExc