diff --git a/ironic/common/json_rpc/client.py b/ironic/common/json_rpc/client.py index b90de1be33..ff1c2cc62f 100644 --- a/ironic/common/json_rpc/client.py +++ b/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 '')) + 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, - strutils.mask_dict_password(body)) + self._debug_log_rpc(method, url, params, body=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 '')) + + self._debug_log_rpc(method, url, params, result_text=result.text) if not cast: result = result.json() self._handle_error(result.get('error')) diff --git a/ironic/conf/json_rpc.py b/ironic/conf/json_rpc.py index b95947c639..8b209ebfc3 100644 --- a/ironic/conf/json_rpc.py +++ b/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.')), ] diff --git a/ironic/tests/unit/common/test_json_rpc.py b/ironic/tests/unit/common/test_json_rpc.py index cfb8dba7d2..2f664593b1 100644 --- a/ironic/tests/unit/common/test_json_rpc.py +++ b/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): diff --git a/releasenotes/notes/reduce-json-rpc-logging-1a719cc235a02c74.yaml b/releasenotes/notes/reduce-json-rpc-logging-1a719cc235a02c74.yaml new file mode 100644 index 0000000000..0346e184d9 --- /dev/null +++ b/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.