Allow exceptions to pass over RPC silently

When one service performs an operation on behalf of another, the
act of passing back an exception (even a known one) causes a lot
of scary log messages about the (presumed to be) error case. This
patch adds a client_exceptions decorator common/rpc/common.py,
which allows RPC services to declare the list of expected exceptions
for each method. If such an exception is raised during the RPC
dispatch, it is wrapped in a ClientException so that the RPC layer
can gracefully pass it back without overly-verbose logging.

This will allow us to fix nova bug 1084707

Change-Id: I4e7b19dc730342091fd70a717065741d56da4555

5 files changed, 111 insertions, 7 deletions

diff --git a/openstack/common/rpc/amqp.py b/openstack/common/rpc/amqp.py
index b247106..193b621 100644
--- a/openstack/common/rpc/amqp.py
+++ b/openstack/common/rpc/amqp.py
@@ -150,7 +150,7 @@ class ConnectionContext(rpc_common.Connection):
 
 
 def msg_reply(conf, msg_id, connection_pool, reply=None, failure=None,
-              ending=False):
+              ending=False, log_failure=True):
     """Sends a reply or an error on the channel signified by msg_id.
 
     Failure should be a sys.exc_info() tuple.
@@ -158,7 +158,8 @@ def msg_reply(conf, msg_id, connection_pool, reply=None, failure=None,
     """
     with ConnectionContext(conf, connection_pool) as conn:
         if failure:
-            failure = rpc_common.serialize_remote_exception(failure)
+            failure = rpc_common.serialize_remote_exception(failure,
+                                                            log_failure)
 
         try:
             msg = {'result': reply, 'failure': failure}
@@ -185,10 +186,10 @@ class RpcContext(rpc_common.CommonRpcContext):
         return self.__class__(**values)
 
     def reply(self, reply=None, failure=None, ending=False,
-              connection_pool=None):
+              connection_pool=None, log_failure=True):
         if self.msg_id:
             msg_reply(self.conf, self.msg_id, connection_pool, reply, failure,
-                      ending)
+                      ending, log_failure)
             if ending:
                 self.msg_id = None
 
@@ -282,6 +283,12 @@ class ProxyCallback(object):
                 ctxt.reply(rval, None, connection_pool=self.connection_pool)
             # This final None tells multicall that it is done.
             ctxt.reply(ending=True, connection_pool=self.connection_pool)
+        except rpc_common.ClientException as e:
+            LOG.debug(_('Expected exception during message handling (%s)') %
+                      e._exc_info[1])
+            ctxt.reply(None, e._exc_info,
+                       connection_pool=self.connection_pool,
+                       log_failure=False)
         except Exception:
             LOG.exception(_('Exception during message handling'))
             ctxt.reply(None, sys.exc_info(),
diff --git a/openstack/common/rpc/common.py b/openstack/common/rpc/common.py
index c56c9a6..efdf26f 100644
--- a/openstack/common/rpc/common.py
+++ b/openstack/common/rpc/common.py
@@ -18,6 +18,7 @@
 #    under the License.
 
 import copy
+import sys
 import traceback
 
 from openstack.common.gettextutils import _
@@ -195,7 +196,7 @@ def _safe_log(log_func, msg, msg_data):
     return log_func(msg, msg_data)
 
 
-def serialize_remote_exception(failure_info):
+def serialize_remote_exception(failure_info, log_failure=True):
     """Prepares exception data to be sent over rpc.
 
     Failure_info should be a sys.exc_info() tuple.
@@ -203,8 +204,9 @@ def serialize_remote_exception(failure_info):
     """
     tb = traceback.format_exception(*failure_info)
     failure = failure_info[1]
-    LOG.error(_("Returning exception %s to caller"), unicode(failure))
-    LOG.error(tb)
+    if log_failure:
+        LOG.error(_("Returning exception %s to caller"), unicode(failure))
+        LOG.error(tb)
 
     kwargs = {}
     if hasattr(failure, 'kwargs'):
@@ -309,3 +311,36 @@ class CommonRpcContext(object):
             context.values['read_deleted'] = read_deleted
 
         return context
+
+
+class ClientException(Exception):
+    """This encapsulates some actual exception that is expected to be
+    hit by an RPC proxy object. Merely instantiating it records the
+    current exception information, which will be passed back to the
+    RPC client without exceptional logging."""
+    def __init__(self):
+        self._exc_info = sys.exc_info()
+
+
+def catch_client_exception(exceptions, func, *args, **kwargs):
+    try:
+        return func(*args, **kwargs)
+    except Exception, e:
+        if type(e) in exceptions:
+            raise ClientException()
+        else:
+            raise
+
+
+def client_exceptions(*exceptions):
+    """Decorator for manager methods that raise expected exceptions.
+    Marking a Manager method with this decorator allows the declaration
+    of expected exceptions that the RPC layer should not consider fatal,
+    and not log as if they were generated in a real error scenario. Note
+    that this will cause listed exceptions to be wrapped in a
+    ClientException, which is used internally by the RPC layer."""
+    def outer(func):
+        def inner(*args, **kwargs):
+            return catch_client_exception(exceptions, func, *args, **kwargs)
+        return inner
+    return outer
diff --git a/openstack/common/rpc/impl_fake.py b/openstack/common/rpc/impl_fake.py
index 59f6fb3..d526a48 100644
--- a/openstack/common/rpc/impl_fake.py
+++ b/openstack/common/rpc/impl_fake.py
@@ -79,6 +79,8 @@ class Consumer(object):
                     else:
                         res.append(rval)
                 done.send(res)
+            except rpc_common.ClientException as e:
+                done.send_exception(e._exc_info[1])
             except Exception as e:
                 done.send_exception(e)
 
diff --git a/openstack/common/rpc/impl_zmq.py b/openstack/common/rpc/impl_zmq.py
index 9365eb2..33562b0 100644
--- a/openstack/common/rpc/impl_zmq.py
+++ b/openstack/common/rpc/impl_zmq.py
@@ -259,7 +259,14 @@ class InternalContext(object):
         except greenlet.GreenletExit:
             # ignore these since they are just from shutdowns
             pass
+        except rpc_common.ClientException, e:
+            LOG.debug(_("Expected exception during message handling (%s)") %
+                      e._exc_info[1])
+            return {'exc':
+                    rpc_common.serialize_remote_exception(e._exc_info,
+                                                          log_failure=False)}
         except Exception:
+            LOG.error(_("Exception during message handling"))
             return {'exc':
                     rpc_common.serialize_remote_exception(sys.exc_info())}
 
diff --git a/tests/unit/rpc/test_common.py b/tests/unit/rpc/test_common.py
index 37d4f25..7489a8f 100644
--- a/tests/unit/rpc/test_common.py
+++ b/tests/unit/rpc/test_common.py
@@ -169,3 +169,56 @@ class RpcCommonTestCase(test_utils.BaseTestCase):
     def test_queue_get_for(self):
         self.assertEqual(rpc.queue_get_for(None, 'a', 'b'), 'a.b')
         self.assertEqual(rpc.queue_get_for(None, 'a', None), 'a')
+
+    def test_client_exception(self):
+        e = None
+        try:
+            try:
+                raise ValueError()
+            except Exception:
+                raise rpc_common.ClientException()
+        except rpc_common.ClientException, e:
+            pass
+
+        self.assertTrue(isinstance(e, rpc_common.ClientException))
+        self.assertTrue(e._exc_info[1], ValueError)
+
+    def test_catch_client_exception(self):
+        def naughty(param):
+            int(param)
+
+        e = None
+        try:
+            rpc_common.catch_client_exception([ValueError], naughty, 'a')
+        except rpc_common.ClientException, e:
+            pass
+
+        self.assertTrue(isinstance(e, rpc_common.ClientException))
+        self.assertTrue(isinstance(e._exc_info[1], ValueError))
+
+    def test_catch_client_exception_other(self):
+        class FooException(Exception):
+            pass
+
+        def naughty():
+            raise FooException()
+
+        e = None
+        self.assertRaises(FooException,
+                          rpc_common.catch_client_exception,
+                          [ValueError], naughty)
+
+    def test_client_exceptions_decorator(self):
+        class FooException(Exception):
+            pass
+
+        @rpc_common.client_exceptions(FooException)
+        def naughty():
+            raise FooException()
+
+        @rpc_common.client_exceptions(FooException)
+        def really_naughty():
+            raise ValueError()
+
+        self.assertRaises(rpc_common.ClientException, naughty)
+        self.assertRaises(ValueError, really_naughty)