Add RPC incoming and reply log

Typically a simple log will not narrow down the
performance, but give us more information about
the service status.

Change-Id: I51c8f2743dd39cccd3d1d021d3c50dc09f70cd97
Closes-Bug: #1847747

oslo_messaging/_drivers/impl_fake.py

@@ -16,6 +16,7 @@
 import copy
 import threading
 import time
+import uuid
 
 from oslo_serialization import jsonutils
 from six import moves
@@ -29,6 +30,7 @@ class FakeIncomingMessage(base.RpcIncomingMessage):
         super(FakeIncomingMessage, self).__init__(ctxt, message)
         self.requeue_callback = requeue
         self._reply_q = reply_q
+        self.msg_id = str(uuid.uuid4())
 
     def reply(self, reply=None, failure=None):
         if self._reply_q:

oslo_messaging/rpc/server.py

@@ -122,6 +122,7 @@ A simple example of an RPC server with multiple endpoints might be::
 
 import logging
 import sys
+import time
 
 from oslo_messaging import exceptions
 from oslo_messaging.rpc import dispatcher as rpc_dispatcher
@@ -151,6 +152,12 @@ class RPCServer(msg_server.MessageHandlingServer):
 
     def _process_incoming(self, incoming):
         message = incoming[0]
+        rpc_method = message.message.get('method')
+        start = time.time()
+        LOG.debug("Receive incoming message with id %(msg_id)s and "
+                  "method: %(method)s.",
+                  {"msg_id": message.msg_id,
+                   "method": rpc_method})
 
         # TODO(sileht): We should remove that at some point and do
         # this directly in the driver
@@ -176,8 +183,19 @@ class RPCServer(msg_server.MessageHandlingServer):
         try:
             if failure is None:
                 message.reply(res)
+                LOG.debug("Replied success message with id %(msg_id)s and "
+                          "method: %(method)s. Time elapsed: %(elapsed).3f",
+                          {"msg_id": message.msg_id,
+                           "method": rpc_method,
+                           "elapsed": (time.time() - start)})
             else:
                 message.reply(failure=failure)
+                LOG.debug("Replied failure for incoming message with "
+                          "id %(msg_id)s and method: %(method)s. "
+                          "Time elapsed: %(elapsed).3f",
+                          {"msg_id": message.msg_id,
+                           "method": rpc_method,
+                           "elapsed": (time.time() - start)})
         except exceptions.MessageUndeliverable as e:
             LOG.exception(
                 "MessageUndeliverable error, "

oslo_messaging/tests/rpc/test_server.py

@@ -400,7 +400,7 @@ class TestRPCServer(test_utils.BaseTestCase, ServerSetupMixin):
         except Exception as ex:
             self.assertIsInstance(ex, ValueError)
             self.assertEqual('dsfoo', str(ex))
-            self.assertTrue(len(debugs) == 0)
+            self.assertTrue(len(debugs) == 2)
             self.assertGreater(len(errors), 0)
         else:
             self.assertTrue(False)