Improves Logging for for rpc method timeouts

This patch moves the traceback for an rpc timeout from inside an
iterator, which gave a useless traceback, into the main flow of the
program.

It also adds the rpc method being called and the topic used to the
exception's message.

When the caller logs the message higher up the stack, the log
information and traceback will be more useful.

Finally it removes the timeout logging in the amqp.py module, in the
spirit of bug #1137994 and https://review.openstack.org/#/c/23295/

Works towards: bug #1148516

Change-Id: I29a3b1b97c6114c4479e2b71c1257c4d72131535

3 files changed, 35 insertions, 8 deletions

diff --git a/openstack/common/rpc/amqp.py b/openstack/common/rpc/amqp.py
index 2dcb12b..bb8d863 100644
--- a/openstack/common/rpc/amqp.py
+++ b/openstack/common/rpc/amqp.py
@@ -495,7 +495,6 @@ class MulticallProxyWaiter(object):
                 data = self._dataqueue.get(timeout=self._timeout)
                 result = self._process_data(data)
             except queue.Empty:
-                LOG.exception(_('Timed out waiting for RPC response.'))
                 self.done()
                 raise rpc_common.Timeout()
             except Exception:
diff --git a/openstack/common/rpc/common.py b/openstack/common/rpc/common.py
index 5661bef..090bf5c 100644
--- a/openstack/common/rpc/common.py
+++ b/openstack/common/rpc/common.py
@@ -122,7 +122,25 @@ class Timeout(RPCException):
     This exception is raised if the rpc_response_timeout is reached while
     waiting for a response from the remote side.
     """
-    message = _("Timeout while waiting on RPC response.")
+    message = _('Timeout while waiting on RPC response - '
+                'topic: "%(topic)s", RPC method: "%(method)s" '
+                'info: "%(info)s"')
+
+    def __init__(self, info=None, topic=None, method=None):
+        """
+        :param info: Extra info to convey to the user
+        :param topic: The topic that the rpc call was sent to
+        :param rpc_method_name: The name of the rpc method being
+                                called
+        """
+        self.info = info
+        self.topic = topic
+        self.method = method
+        super(Timeout, self).__init__(
+            None,
+            info=info or _('<unknown>'),
+            topic=topic or _('<unknown>'),
+            method=method or _('<unknown>'))
 
 
 class DuplicateMessageError(RPCException):
diff --git a/openstack/common/rpc/proxy.py b/openstack/common/rpc/proxy.py
index fc09116..822248d 100644
--- a/openstack/common/rpc/proxy.py
+++ b/openstack/common/rpc/proxy.py
@@ -68,16 +68,21 @@ class RpcProxy(object):
         :param context: The request context
         :param msg: The message to send, including the method and args.
         :param topic: Override the topic for this message.
+        :param version: (Optional) Override the requested API version in this
+               message.
         :param timeout: (Optional) A timeout to use when waiting for the
                response.  If no timeout is specified, a default timeout will be
                used that is usually sufficient.
-        :param version: (Optional) Override the requested API version in this
-               message.
 
         :returns: The return value from the remote method.
         """
         self._set_version(msg, version)
-        return rpc.call(context, self._get_topic(topic), msg, timeout)
+        real_topic = self._get_topic(topic)
+        try:
+            return rpc.call(context, real_topic, msg, timeout)
+        except rpc.common.Timeout as exc:
+            raise rpc.common.Timeout(
+                exc.info, real_topic, msg.get('method'))
 
     def multicall(self, context, msg, topic=None, version=None, timeout=None):
         """rpc.multicall() a remote method.
@@ -85,17 +90,22 @@ class RpcProxy(object):
         :param context: The request context
         :param msg: The message to send, including the method and args.
         :param topic: Override the topic for this message.
+        :param version: (Optional) Override the requested API version in this
+               message.
         :param timeout: (Optional) A timeout to use when waiting for the
                response.  If no timeout is specified, a default timeout will be
                used that is usually sufficient.
-        :param version: (Optional) Override the requested API version in this
-               message.
 
         :returns: An iterator that lets you process each of the returned values
                   from the remote method as they arrive.
         """
         self._set_version(msg, version)
-        return rpc.multicall(context, self._get_topic(topic), msg, timeout)
+        real_topic = self._get_topic(topic)
+        try:
+            return rpc.multicall(context, real_topic, msg, timeout)
+        except rpc.common.Timeout as exc:
+            raise rpc.common.Timeout(
+                exc.info, real_topic, msg.get('method'))
 
     def cast(self, context, msg, topic=None, version=None):
         """rpc.cast() a remote method.