Mask secrets when logging in json_rpc

Otherwise passwords are displayed in plain text in the DEBUG logs.

Change-Id: I4210492bc7cb42b205d2b93a018bfaa25bfe5752
Story: #2006744
Task: #37216

ironic/common/json_rpc/client.py

@@ -18,6 +18,7 @@ This client is compatible with any JSON RPC 2.0 implementation, including ours.
 from oslo_config import cfg
 from oslo_log import log
 from oslo_utils import importutils
+from oslo_utils import strutils
 from oslo_utils import uuidutils
 
 from ironic.common import exception
@@ -151,10 +152,11 @@ class _CallContext(object):
         if not cast:
             body['id'] = context.request_id or uuidutils.generate_uuid()
 
-        LOG.debug("RPC %s with %s", method, body)
+        LOG.debug("RPC %s with %s", method, strutils.mask_dict_password(body))
         url = 'http://%s:%d' % (self.host, CONF.json_rpc.port)
         result = _get_session().post(url, json=body)
-        LOG.debug('RPC %s returned %s', method, result.text or '<None>')
+        LOG.debug('RPC %s returned %s', method,
+                  strutils.mask_password(result.text or '<None>'))
 
         if not cast:
             result = result.json()

ironic/common/json_rpc/server.py

@@ -27,6 +27,7 @@ from oslo_log import log
 import oslo_messaging
 from oslo_service import service
 from oslo_service import wsgi
+from oslo_utils import strutils
 import webob
 
 from ironic.common import context as ir_context
@@ -222,6 +223,7 @@ class WSGIService(service.Service):
         """
         # TODO(dtantsur): server-side version check?
         params.pop('rpc.version', None)
+        logged_params = strutils.mask_dict_password(params)
 
         try:
             context = params.pop('context')
@@ -238,7 +240,7 @@ class WSGIService(service.Service):
                       for key, value in params.items()}
             params['context'] = context
 
-        LOG.debug('RPC %s with %s', name, params)
+        LOG.debug('RPC %s with %s', name, logged_params)
         try:
             result = func(**params)
         # FIXME(dtantsur): we could use the inspect module, but
@@ -251,7 +253,9 @@ class WSGIService(service.Service):
             # Currently it seems that we can serialize even with invalid
             # context, but I'm not sure it's guaranteed to be the case.
             result = self.serializer.serialize_entity(context, result)
-        LOG.debug('RPC %s returned %s', name, result)
+        LOG.debug('RPC %s returned %s', name,
+                  strutils.mask_dict_password(result)
+                  if isinstance(result, dict) else result)
         return result
 
     def start(self):

ironic/tests/unit/common/test_json_rpc.py

@@ -22,6 +22,7 @@ from ironic.common.json_rpc import server
 from ironic import objects
 from ironic.objects import base as objects_base
 from ironic.tests import base as test_base
+from ironic.tests.unit.db import utils as db_utils
 from ironic.tests.unit.objects import utils as obj_utils
 
 
@@ -266,6 +267,22 @@ class TestService(test_base.TestCase):
         self._request('success', {'context': self.ctx, 'x': 42},
                       expected_error=403)
 
+    @mock.patch.object(server.LOG, 'debug', autospec=True)
+    def test_mask_secrets(self, mock_log):
+        node = obj_utils.get_test_node(
+            self.context, driver_info=db_utils.get_test_ipmi_info())
+        node = self.serializer.serialize_entity(self.context, node)
+        body = self._request('with_node', {'context': self.ctx, 'node': node})
+        node = self.serializer.deserialize_entity(self.context, body['result'])
+        logged_params = mock_log.call_args_list[0][0][2]
+        logged_node = logged_params['node']['ironic_object.data']
+        self.assertEqual('***', logged_node['driver_info']['ipmi_password'])
+        logged_resp = mock_log.call_args_list[1][0][2]
+        logged_node = logged_resp['ironic_object.data']
+        self.assertEqual('***', logged_node['driver_info']['ipmi_password'])
+        # The result is not affected, only logging
+        self.assertEqual(db_utils.get_test_ipmi_info(), node.driver_info)
+
 
 @mock.patch.object(client, '_get_session', autospec=True)
 class TestClient(test_base.TestCase):
@@ -493,3 +510,34 @@ class TestClient(test_base.TestCase):
                                cctx.call, self.context, 'do_something',
                                answer=42)
         self.assertFalse(mock_session.return_value.post.called)
+
+    @mock.patch.object(client.LOG, 'debug', autospec=True)
+    def test_mask_secrets(self, mock_log, mock_session):
+        request = {
+            'redfish_username': 'admin',
+            'redfish_password': 'passw0rd'
+        }
+        body = """{
+            "jsonrpc": "2.0",
+            "result": {
+                "driver_info": {
+                    "ipmi_username": "admin",
+                    "ipmi_password": "passw0rd"
+                }
+            }
+        }"""
+        response = mock_session.return_value.post.return_value
+        response.text = body
+        cctx = self.client.prepare('foo.example.com')
+        cctx.cast(self.context, 'do_something', node=request)
+        mock_session.return_value.post.assert_called_once_with(
+            'http://example.com:8089',
+            json={'jsonrpc': '2.0',
+                  'method': 'do_something',
+                  'params': {'node': request, 'context': self.ctx_json}})
+        self.assertEqual(2, mock_log.call_count)
+        node = mock_log.call_args_list[0][0][2]['params']['node']
+        self.assertEqual(node, {'redfish_username': 'admin',
+                                'redfish_password': '***'})
+        resp_text = mock_log.call_args_list[1][0][2]
+        self.assertEqual(body.replace('passw0rd', '***'), resp_text)

releasenotes/notes/jsonrpc-logging-21670015bb845182.yaml

@@ -0,0 +1,5 @@
+---
+security:
+  - |
+    Node secrets (such as BMC credentials) are no longer logged when JSON RPC
+    is used and DEBUG logging is enabled.