RPCSession: introduce log_me member

aiorpcx/session.py

@@ -514,6 +514,7 @@ class RPCSession(SessionBase):
     # this many seconds, recalibrating every recalibrate_count requests
     target_response_time = 3.0
     recalibrate_count = 30
+    log_me = False
 
     def __init__(self, *, framer=None, loop=None, connection=None):
         super().__init__(framer=framer, loop=loop)
@@ -544,6 +545,8 @@ async def _receive_messages(self):
 
             self.last_recv = time.time()
             self.recv_count += 1
+            if self.log_me:
+                self.logger.info(f'processing {message}')
 
             try:
                 requests = self.connection.receive_message(message)

tests/test_session.py

@@ -75,6 +75,10 @@ def in_caplog(caplog, message):
     return any(message in record.message for record in caplog.records)
 
 
+def caplog_count(caplog, message):
+    return sum(message in record.message for record in caplog.records)
+
+
 # This runs all the tests one with plain asyncio, then again with uvloop
 @pytest.fixture(scope="session", autouse=True, params=(False, True))
 def use_uvloop(request):
@@ -545,6 +549,20 @@ async def test_send_batch_throttling(self, server):
             current = client._outgoing_concurrency.max_concurrent
             assert prior * 1.2 > current > prior
 
+    @pytest.mark.asyncio
+    async def test_log_me(self, server, caplog):
+        async with Connector(RPCSession, 'localhost', server.port) as client:
+            server = await MyServerSession.current_server()
+
+            with caplog.at_level(logging.INFO):
+                assert server.log_me is False
+                await client.send_request('echo', ['ping'])
+                assert caplog_count(caplog, '"method": "echo"') == 0
+
+                server.log_me = True
+                await client.send_request('echo', ['ping'])
+                assert caplog_count(caplog, '"method": "echo"') == 1
+
 
 class RPCClient(RPCSession):
     # For tests of wire messages