diff options
| author | LIU Yulong <i@liuyulong.me> | 2019-10-11 23:22:23 +0800 |
|---|---|---|
| committer | LIU Yulong <i@liuyulong.me> | 2019-10-21 22:32:07 +0800 |
| commit | b104f254ab43d5e2589e845eff84b1bd096cb42d (patch) | |
| tree | 8e31f64e8a9826d8e24f151864425733e5a87e35 | |
| parent | c01b03e87c66e964100d3d56d91b0f5f045e6190 (diff) | |
| download | oslo-messaging-b104f254ab43d5e2589e845eff84b1bd096cb42d.tar.gz | |
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
| -rw-r--r-- | oslo_messaging/_drivers/impl_fake.py | 2 | ||||
| -rw-r--r-- | oslo_messaging/rpc/server.py | 18 | ||||
| -rw-r--r-- | oslo_messaging/tests/rpc/test_server.py | 2 |
3 files changed, 21 insertions, 1 deletions
diff --git a/oslo_messaging/_drivers/impl_fake.py b/oslo_messaging/_drivers/impl_fake.py index c5476fd..dc6439d 100644 --- a/oslo_messaging/_drivers/impl_fake.py +++ b/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: diff --git a/oslo_messaging/rpc/server.py b/oslo_messaging/rpc/server.py index b16d77f..f1deff7 100644 --- a/oslo_messaging/rpc/server.py +++ b/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, " diff --git a/oslo_messaging/tests/rpc/test_server.py b/oslo_messaging/tests/rpc/test_server.py index 693e88a..cf2d4ba 100644 --- a/oslo_messaging/tests/rpc/test_server.py +++ b/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) |