Minimize json-rpc client logging

The json-rpc debug logging can be... very... verbose. And that
verbosity when including all of the data crossing the RPC bus
provides limited value when your just focused on addressing
a performance issue.

The key is much more "when did I send a request" and what
was the ID, and similarly "when did I get a response".

By default, if there is a request ID when we're in debug
logging mode, we will keep the entire result to a brief
result.

Assisted-By: Claude Code - Claude Sonnet 4
Change-Id: Ib6e4db0e8689ed2081f29b1d1d22a7f01a0e1221
Signed-off-by: Julia Kreger <juliaashleykreger@gmail.com>

ironic/common/json_rpc/client.py

@@ -146,6 +146,38 @@ class _CallContext(object):
             raise importutils.import_object(cls, message,
                                             code=error.get('code', 500))
 
+    def _debug_log_rpc(self, method, url, params, body=None,
+                       result_text=None, exception=None):
+        """Helper to log RPC calls with optional request_id-only logging."""
+        request_id = None
+        if CONF.json_rpc.debug_log_request_id_only:
+            request_id = params.get('context', {}).get('request_id')
+
+        if exception:
+            # Log failure
+            if request_id:
+                LOG.debug('RPC %s to %s with request_id %s failed with %s',
+                          method, url, request_id, exception)
+            else:
+                LOG.debug('RPC %s to %s failed with %s', method, url,
+                          exception)
+        elif result_text is not None:
+            # Log success response
+            if request_id:
+                LOG.debug('RPC %s to %s with request_id %s completed '
+                          'successfully', method, url, request_id)
+            else:
+                LOG.debug('RPC %s to %s returned %s', method, url,
+                          strutils.mask_password(result_text or '<None>'))
+        else:
+            # Log request
+            if request_id:
+                LOG.debug("RPC %s to %s with request_id %s", method, url,
+                          request_id)
+            else:
+                LOG.debug("RPC %s to %s with %s", method, url,
+                          strutils.mask_dict_password(body))
+
     def call(self, context, method, version=None, **kwargs):
         """Call conductor RPC.
 
@@ -211,15 +243,15 @@ class _CallContext(object):
         url = '%s://%s:%d' % (scheme,
                               netutils.escape_ipv6(self.host),
                               self.port)
-        LOG.debug("RPC %s to %s with %s", method, url,
+        self._debug_log_rpc(method, url, params, body=body)
-                  strutils.mask_dict_password(body))
+
         try:
             result = _get_session().post(url, json=body)
         except Exception as exc:
-            LOG.debug('RPC %s to %s failed with %s', method, url, exc)
+            self._debug_log_rpc(method, url, params, exception=exc)
             raise
-        LOG.debug('RPC %s to %s returned %s', method, url,
+
-                  strutils.mask_password(result.text or '<None>'))
+        self._debug_log_rpc(method, url, params, result_text=result.text)
         if not cast:
             result = result.json()
             self._handle_error(result.get('error'))

ironic/conf/json_rpc.py

@@ -73,6 +73,14 @@ opts = [
     cfg.Opt('unix_socket_mode', type=Octal(),
             help=_('File mode (an octal number) of the unix socket to '
                    'listen on. Ignored if unix_socket is not set.')),
+    cfg.BoolOpt('debug_log_request_id_only',
+                mutable=True,
+                default=True,
+                help=_('When debug logging is enabled, log only the request '
+                       'ID instead of the full request and response for JSON '
+                       'RPC calls. This reduces log verbosity while still '
+                       'providing some traceability for performance '
+                       'analysis.')),
 ]
 
 

ironic/tests/unit/common/test_json_rpc.py

@@ -665,6 +665,123 @@ class TestClient(TestCase):
         resp_text = mock_log.call_args_list[1][0][3]
         self.assertEqual(body.replace('passw0rd', '***'), resp_text)
 
+    @mock.patch.object(client.LOG, 'debug', autospec=True)
+    def test_debug_log_request_id_only_with_request_id(self, mock_log,
+                                                       mock_session):
+        response = mock_session.return_value.post.return_value
+        response.json.return_value = {
+            'jsonrpc': '2.0',
+            'result': 42
+        }
+        self.context.request_id = 'req-1234'
+        cctx = self.client.prepare('foo.example.com')
+        result = cctx.call(self.context, 'do_something', answer=42)
+        self.assertEqual(42, result)
+
+        # Check that only request_id is logged, not full request/response
+        self.assertEqual(2, mock_log.call_count)
+
+        # First call should log the request with request_id only
+        first_call_args = mock_log.call_args_list[0][0]
+        self.assertIn('request_id', first_call_args[0])
+        self.assertEqual('do_something', first_call_args[1])
+        self.assertIn('example.com:8089', first_call_args[2])
+        self.assertEqual(self.context.request_id, first_call_args[3])
+
+        # Second call should log successful completion with request_id
+        second_call_args = mock_log.call_args_list[1][0]
+        self.assertIn('completed successfully', second_call_args[0])
+        self.assertEqual('do_something', second_call_args[1])
+        self.assertIn('example.com:8089', second_call_args[2])
+        self.assertEqual(self.context.request_id, second_call_args[3])
+
+    @mock.patch.object(client.LOG, 'debug', autospec=True)
+    def test_debug_log_request_id_only_without_request_id(self, mock_log,
+                                                          mock_session):
+        self.config(debug_log_request_id_only=True, group='json_rpc')
+        # Create context without request_id
+        context_without_id = FakeContext({'user_name': 'admin'})
+        context_without_id.request_id = None
+        context_without_id.to_dict()
+
+        response = mock_session.return_value.post.return_value
+        response.json.return_value = {
+            'jsonrpc': '2.0',
+            'result': 42
+        }
+        response.text = '{"jsonrpc": "2.0", "result": 42}'
+
+        cctx = self.client.prepare('foo.example.com')
+        result = cctx.call(context_without_id, 'do_something', answer=42)
+        self.assertEqual(42, result)
+
+        # Check that full request/response is logged when no request_id
+        self.assertEqual(2, mock_log.call_count)
+
+        # First call should log full request body since no request_id
+        first_call_args = mock_log.call_args_list[0][0]
+        self.assertIn('RPC', first_call_args[0])
+        self.assertIn('with', first_call_args[0])
+        # Should contain the masked request body
+        logged_body = first_call_args[3]
+        self.assertIn('do_something', str(logged_body))
+        self.assertIn('answer', str(logged_body))
+
+        # Second call should log full response since no request_id
+        second_call_args = mock_log.call_args_list[1][0]
+        self.assertIn('returned', second_call_args[0])
+
+    @mock.patch.object(client.LOG, 'debug', autospec=True)
+    def test_debug_log_request_id_only_disabled(self, mock_log, mock_session):
+        self.config(debug_log_request_id_only=False, group='json_rpc')
+        response = mock_session.return_value.post.return_value
+        response.json.return_value = {
+            'jsonrpc': '2.0',
+            'result': 42
+        }
+        response.text = '{"jsonrpc": "2.0", "result": 42}'
+
+        cctx = self.client.prepare('foo.example.com')
+        result = cctx.call(self.context, 'do_something', answer=42)
+        self.assertEqual(42, result)
+
+        # Check that full request/response is logged when option is disabled
+        self.assertEqual(2, mock_log.call_count)
+
+        # Should always log full request/response when disabled
+        first_call_args = mock_log.call_args_list[0][0]
+        self.assertIn('RPC', first_call_args[0])
+        self.assertIn('with', first_call_args[0])
+        logged_body = first_call_args[3]
+        self.assertIn('do_something', str(logged_body))
+
+        second_call_args = mock_log.call_args_list[1][0]
+        self.assertIn('returned', second_call_args[0])
+
+    @mock.patch.object(client.LOG, 'debug', autospec=True)
+    def test_debug_log_request_id_only_with_exception(self, mock_log,
+                                                      mock_session):
+        self.config(debug_log_request_id_only=True, group='json_rpc')
+        mock_session.return_value.post.side_effect = RuntimeError(
+            'Connection failed')
+        self.context.request_id = 'req-1234'
+        cctx = self.client.prepare('foo.example.com')
+        self.assertRaises(RuntimeError, cctx.call, self.context,
+                          'do_something', answer=42)
+
+        # Check that exception logging uses request_id only format
+        self.assertEqual(2, mock_log.call_count)
+
+        # First call should log the request with request_id
+        first_call_args = mock_log.call_args_list[0][0]
+        self.assertIn('request_id', first_call_args[0])
+
+        # Second call should log the failure with request_id
+        second_call_args = mock_log.call_args_list[1][0]
+        self.assertIn('failed', second_call_args[0])
+        self.assertIn('request_id', second_call_args[0])
+        self.assertEqual(self.context.request_id, second_call_args[3])
+
 
 @mock.patch('ironic.common.json_rpc.client.keystone', autospec=True)
 class TestSession(TestCase):

releasenotes/notes/reduce-json-rpc-logging-1a719cc235a02c74.yaml

@@ -0,0 +1,7 @@
+---
+fixes:
+  - |
+    Fixes excessive logging of JSON-RPC transactions by reducing the logging
+    of these transactions to the minimally needful, the request ID value.
+    This behavior can be disabled, and the prior pattern of verbose logging can
+    be enabled by setting ``[json_rpc]debug_log_request_id_only`` to False.