Make NovaException format errors fatal for tests

Recently, as part of the centralize-config-options work, functionality
that detects errors in NovaException formats was removed [1] because
the config option controlling it was solely being used for testing.

We have had to do a bug fixes like [2] where a testing exception format
error in a mock decorator caused gorpy output to the console during
unit test runs.

To help prevent future bugs, this restores the error detecting
functionality by patching the exception handling to reraise format
error exceptions, only for tests. The _log_exception() function has to
be patched at import time in order to catch exception KeyErrors that
are in mock decorators because those evaluate at test listing time,
before tests actually run.

[1] https://review.openstack.org/#/c/397823
[2] https://review.openstack.org/#/c/411502

Change-Id: I680fd46d029ff58bd3b72ef7c7903c2271b26549

nova/exception.py

@@ -86,17 +86,21 @@ class NovaException(Exception):
                 message = self.msg_fmt % kwargs
 
             except Exception:
-                # kwargs doesn't match a variable in the message
-                # log the issue and the kwargs
-                LOG.exception(_LE('Exception in string format operation'))
-                for name, value in kwargs.items():
-                    LOG.error("%s: %s" % (name, value))  # noqa
-
+                # NOTE(melwitt): This is done in a separate method so it can be
+                # monkey-patched during testing to make it a hard failure.
+                self._log_exception()
                 message = self.msg_fmt
 
         self.message = message
         super(NovaException, self).__init__(message)
 
+    def _log_exception(self):
+        # kwargs doesn't match a variable in the message
+        # log the issue and the kwargs
+        LOG.exception(_LE('Exception in string format operation'))
+        for name, value in self.kwargs.items():
+            LOG.error("%s: %s" % (name, value))  # noqa
+
     def format_message(self):
         # NOTE(mrodden): use the first argument to the python Exception object
         # which should be our full NovaException message, (see __init__)

nova/test.py

@@ -30,6 +30,7 @@ import datetime
 import inspect
 import os
 import pprint
+import sys
 
 import fixtures
 import mock
@@ -48,6 +49,7 @@ import testtools
 
 from nova import context
 from nova import db
+from nova import exception
 from nova.network import manager as network_manager
 from nova.network.security_group import openstack_driver
 from nova import objects
@@ -168,6 +170,26 @@ def _patch_mock_to_raise_for_invalid_assert_calls():
 _patch_mock_to_raise_for_invalid_assert_calls()
 
 
+class NovaExceptionReraiseFormatError(object):
+    real_log_exception = exception.NovaException._log_exception
+
+    @classmethod
+    def patch(cls):
+        exception.NovaException._log_exception = cls._wrap_log_exception
+
+    @staticmethod
+    def _wrap_log_exception(self):
+        exc_info = sys.exc_info()
+        NovaExceptionReraiseFormatError.real_log_exception(self)
+        six.reraise(*exc_info)
+
+
+# NOTE(melwitt) This needs to be done at import time in order to also catch
+# NovaException format errors that are in mock decorators. In these cases, the
+# errors will be raised during test listing, before tests actually run.
+NovaExceptionReraiseFormatError.patch()
+
+
 class TestCase(testtools.TestCase):
     """Test case base class for all unit tests.
 

nova/tests/unit/test_exception.py

@@ -16,6 +16,7 @@
 
 import inspect
 
+import fixtures
 import mock
 import six
 from webob.util import status_reasons
@@ -211,6 +212,13 @@ class NovaExceptionTestCase(test.NoDBTestCase):
         self.assertEqual("some message", exc.format_message())
 
     def test_format_message_remote_error(self):
+        # NOTE(melwitt): This test checks that errors are formatted as expected
+        # in a real environment where format errors are caught and not
+        # reraised, so we patch in the real implementation.
+        self.useFixture(fixtures.MonkeyPatch(
+            'nova.exception.NovaException._log_exception',
+            test.NovaExceptionReraiseFormatError.real_log_exception))
+
         class FakeNovaException_Remote(exception.NovaException):
             msg_fmt = "some message %(somearg)s"
 

nova/tests/unit/test_test.py

@@ -21,6 +21,7 @@ import oslo_messaging as messaging
 import six
 
 import nova.conf
+from nova import exception
 from nova import rpc
 from nova import test
 from nova.tests import fixtures
@@ -283,3 +284,20 @@ class ContainKeyValueTestCase(test.NoDBTestCase):
         # Raise KeyError
         self.assertNotEqual(matcher, {1: 2, '3': 4, 5: '6'})
         self.assertNotEqual(matcher, {'bar': 'foo'})
+
+
+class NovaExceptionReraiseFormatErrorTestCase(test.NoDBTestCase):
+    """Test that format errors are reraised in tests."""
+    def test_format_error_in_nova_exception(self):
+        class FakeImageException(exception.NovaException):
+            msg_fmt = 'Image %(image_id)s has wrong type %(type)s.'
+        # wrong kwarg
+        ex = self.assertRaises(KeyError, FakeImageException,
+                               bogus='wrongkwarg')
+        self.assertIn('image_id', six.text_type(ex))
+        # no kwarg
+        ex = self.assertRaises(KeyError, FakeImageException)
+        self.assertIn('image_id', six.text_type(ex))
+        # not enough kwargs
+        ex = self.assertRaises(KeyError, FakeImageException, image_id='image')
+        self.assertIn('type', six.text_type(ex))