openstack/ironic
Code Issues Proposed changes

Merge "Minimize json-rpc client logging"

Browse Source
This commit is contained in:
Zuul
2025-11-24 20:42:30 +00:00
committed by Gerrit Code Review
parent c5fba422f4 8c9ad92c1e
commit 35e46cb95c
4 changed files with 169 additions and 5 deletions
Download Patch File Download Diff File Expand all files Collapse all files

42
ironic/common/json_rpc/client.py
View File

@@ -150,6 +150,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.
@@ -216,15 +248,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(self.conf_group).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'))

8
ironic/conf/json_rpc.py
View File

@@ -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.')),
]

117
ironic/tests/unit/common/test_json_rpc.py
View File

@@ -696,6 +696,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):

7
releasenotes/notes/reduce-json-rpc-logging-1a719cc235a02c74.yaml Normal file
View File

@@ -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.