Fixed clear-text logging of all password-like properties in API/HMC log

Details:

* Reworked the @logged_api_call decorator to get optional parameters
  for specifying properties ot be blanked out in the API logging.
  This required significant reimplementation of that decorator and
  the functions it calls.

* Fixed the clear-text logging of all password-like properties in the API
  logging by using this new capability of the @logged_api_call decorator.

* Fixed the clear-text logging of all password-like properties in the HMC
  logging by blanking them out in the Session.post() method.

* Added unit test cases for the blanked-out API logging, in the
  test_logging.py module.

* Added unit test cases for the blanked-out API logging, in all test
  modules for those resources that have blanked-out properties.

* Improved the checking in the unit test cases for API logging, to check
  the function name, args, kwargs and return value in the log messages.

Signed-off-by: Andreas Maier <[email protected]>

changes/noissue.1.feature.rst

@@ -0,0 +1,3 @@
+Dev: Enhanced the zhmcclient API logging code so that in the debugger,
+zhmcclient API functions now have less logging steps to go through until the
+actual API function is reached.

changes/noissue.4.fix.rst

@@ -0,0 +1,4 @@
+Fixed that all password-like properties are no longer written in clear text to
+the Python loggers "zhmcclient.api" and "zhmcclient.hmc", but are now blanked
+out. Previously, that was done only for the "zhmcclient.hmc" logger for creation
+and update of HMC users.

tests/unit/zhmcclient/test_activation_profile.py

@@ -19,9 +19,10 @@
 
 import copy
 import re
+import logging
 import pytest
 
-from zhmcclient import Client, ActivationProfile
+from zhmcclient import Client, ActivationProfile, BLANKED_OUT_STRING
 from zhmcclient_mock import FakedSession
 from tests.common.utils import assert_resources
 
@@ -338,11 +339,15 @@ def test_profile_repr(self):
             }},
             {'group-profile-uri': None},
             {'zaware-gateway-info': None},
+            {'ssc-master-pw': 'bla', 'zaware-master-pw': 'bla'},
         ]
     )
-    def test_profile_update_properties(self, input_props, profile_type):
+    def test_profile_update_properties(self, caplog, input_props, profile_type):
         """Test ActivationProfile.update_properties()."""
 
+        logger_name = "zhmcclient.api"
+        caplog.set_level(logging.DEBUG, logger=logger_name)
+
         mgr_attr = profile_type + '_activation_profiles'
         profile_mgr = getattr(self.cpc, mgr_attr)
 
@@ -354,6 +359,9 @@ def test_profile_update_properties(self, input_props, profile_type):
         # Execute the code to be tested
         profile.update_properties(properties=input_props)
 
+        # Get its API call log record
+        call_record = caplog.records[-2]
+
         # Verify that the resource object already reflects the property
         # updates.
         for prop_name in saved_properties:
@@ -376,3 +384,11 @@ def test_profile_update_properties(self, input_props, profile_type):
             assert prop_name in profile.properties
             prop_value = profile.properties[prop_name]
             assert prop_value == exp_prop_value
+
+        # Verify the API call log record for blanked-out properties.
+        if 'ssc-master-pw' in input_props:
+            exp_str = f"'ssc-master-pw': '{BLANKED_OUT_STRING}'"
+            assert call_record.message.find(exp_str) > 0
+        if 'zaware-master-pw' in input_props:
+            exp_str = f"'zaware-master-pw': '{BLANKED_OUT_STRING}'"
+            assert call_record.message.find(exp_str) > 0

tests/unit/zhmcclient/test_ldap_server_definition.py

@@ -19,9 +19,11 @@
 
 import re
 import copy
+import logging
 import pytest
 
-from zhmcclient import Client, HTTPError, NotFound, LdapServerDefinition
+from zhmcclient import Client, HTTPError, NotFound, LdapServerDefinition, \
+    BLANKED_OUT_STRING
 from zhmcclient_mock import FakedSession
 from tests.common.utils import assert_resources
 
@@ -149,12 +151,21 @@ def test_ldap_srv_def_manager_list(
               'search-distinguished-name': 'test{0}'},
              ['element-uri', 'name', 'description'],
              None),
+            ({'name': 'a',
+              'primary-hostname-ipaddr': '10.11.12.13',
+              'search-distinguished-name': 'test{0}',
+              'bind-password': 'bla'},
+             ['element-uri', 'name', 'bind-password'],
+             None),
         ]
     )
     def test_ldap_srv_def_manager_create(
-            self, input_props, exp_prop_names, exp_exc):
+            self, caplog, input_props, exp_prop_names, exp_exc):
         """Test LdapServerDefinitionManager.create()."""
 
+        logger_name = "zhmcclient.api"
+        caplog.set_level(logging.DEBUG, logger=logger_name)
+
         ldap_srv_def_mgr = self.console.ldap_server_definitions
 
         if exp_exc is not None:
@@ -174,6 +185,9 @@ def test_ldap_srv_def_manager_create(
             # Execute the code to be tested.
             ldap_srv_def = ldap_srv_def_mgr.create(properties=input_props)
 
+            # Get its API call log record
+            call_record = caplog.records[-2]
+
             # Check the resource for consistency within itself
             assert isinstance(ldap_srv_def, LdapServerDefinition)
             ldap_srv_def_name = ldap_srv_def.name
@@ -191,6 +205,11 @@ def test_ldap_srv_def_manager_create(
                     exp_value = input_props[prop_name]
                     assert value == exp_value
 
+            # Verify the API call log record for blanked-out properties.
+            if 'bind-password' in input_props:
+                exp_str = f"'bind-password': '{BLANKED_OUT_STRING}'"
+                assert call_record.message.find(exp_str) > 0
+
     def test_ldap_srv_def_repr(self):
         """Test LdapServerDefinition.__repr__()."""
 
@@ -287,11 +306,15 @@ def test_ldap_delete_create_same(self):
         "input_props", [
             {},
             {'description': 'New LDAP Server Definition description'},
+            {'bind-password': 'bla'},
         ]
     )
-    def test_ldap_srv_def_update_properties(self, input_props):
+    def test_ldap_srv_def_update_properties(self, caplog, input_props):
         """Test LdapServerDefinition.update_properties()."""
 
+        logger_name = "zhmcclient.api"
+        caplog.set_level(logging.DEBUG, logger=logger_name)
+
         ldap_srv_def_name = 'faked_a'
 
         # Add the LDAP Server Definition to be tested
@@ -306,6 +329,9 @@ def test_ldap_srv_def_update_properties(self, input_props):
         # Execute the code to be tested
         ldap_srv_def.update_properties(properties=input_props)
 
+        # Get its API call log record
+        call_record = caplog.records[-2]
+
         # Verify that the resource object already reflects the property
         # updates.
         for prop_name in saved_properties:
@@ -329,3 +355,8 @@ def test_ldap_srv_def_update_properties(self, input_props):
             assert prop_name in ldap_srv_def.properties
             prop_value = ldap_srv_def.properties[prop_name]
             assert prop_value == exp_prop_value
+
+        # Verify the API call log record for blanked-out properties.
+        if 'bind-password' in input_props:
+            exp_str = f"'bind-password': '{BLANKED_OUT_STRING}'"
+            assert call_record.message.find(exp_str) > 0

tests/unit/zhmcclient/test_logging.py

@@ -23,18 +23,26 @@
 from testfixtures import LogCapture
 
 from zhmcclient._logging import logged_api_call, get_logger
-
+from zhmcclient._constants import BLANKED_OUT_STRING
 
 #
 # Various uses of the @logged_api_call decorator
 #
 
+
 @logged_api_call
 def decorated_global_function():
     """A decorated function at the global (module) level."""
     pass
 
 
+@logged_api_call(blanked_properties=['hideme'], properties_pos=0)
+def decorated_global_props_function(properties):
+    """A decorated function with properties at the global (module) level,
+    where the 'hideme' property is blanked out in the API log."""
+    return properties
+
+
 def global1_function():
     """An undecorated function at the global (module) level."""
 
@@ -136,8 +144,8 @@ def call_from_global(func, *args, **kwargs):
 # Some expected values that are constant
 _EXP_LOGGER_NAME = 'zhmcclient.api'
 _EXP_LOG_LEVEL = 'DEBUG'
-_EXP_LOG_MSG_ENTER_PATTERN = "Called: .*, args: .*, kwargs: .*"
-_EXP_LOG_MSG_LEAVE_PATTERN = "Return: .*, result: .*"
+_EXP_LOG_MSG_ENTER_PATTERN = "Called: (.*), args: (.*), kwargs: (.*)"
+_EXP_LOG_MSG_LEAVE_PATTERN = "Return: (.*), result: (.*)"
 
 
 @pytest.fixture()
@@ -155,9 +163,9 @@ def capture():
 # Test cases
 #
 
-def assert_log_capture(log_capture, exp_apifunc):
-    # pylint: disable=unused-argument
-    # Note: exp_apifunc is shown when pytest displays a traceback.
+def assert_log_capture(
+        log_capture, *, func_pattern=None, args_pattern=None,
+        kwargs_pattern=None, return_pattern=None):
     """
     Assert that the log capture is as expected.
     """
@@ -167,13 +175,23 @@ def assert_log_capture(log_capture, exp_apifunc):
     assert enter_record.name == _EXP_LOGGER_NAME
     assert enter_record.levelname == _EXP_LOG_LEVEL
     assert re.match(_EXP_LOG_MSG_ENTER_PATTERN, enter_record.msg)
-    # We don't check the function name and its pos and kw args
+    func_str, args_str, kwargs_str = enter_record.args
+    if func_pattern:
+        assert re.search(func_pattern, func_str)
+    if args_pattern:
+        assert re.search(args_pattern, args_str)
+    if kwargs_pattern:
+        assert re.search(kwargs_pattern, kwargs_str)
 
     leave_record = log_capture.records[1]
     assert leave_record.name == _EXP_LOGGER_NAME
     assert leave_record.levelname == _EXP_LOG_LEVEL
     assert re.match(_EXP_LOG_MSG_LEAVE_PATTERN, leave_record.msg)
-    # We don't check the function name and its pos and kw args
+    func_str, return_str = leave_record.args
+    if func_pattern:
+        assert re.search(func_pattern, func_str)
+    if return_pattern:
+        assert re.search(return_pattern, return_str)
 
 
 def test_1a_global_from_global(capture):
@@ -183,7 +201,8 @@ def test_1a_global_from_global(capture):
 
     call_from_global(decorated_global_function)
 
-    assert_log_capture(capture, 'decorated_global_function()')
+    assert_log_capture(
+        capture, func_pattern='decorated_global_function')
 
 
 def test_1b_global_from_method(capture):
@@ -192,7 +211,40 @@ def test_1b_global_from_method(capture):
 
     CallerClass().call_from_method(decorated_global_function)
 
-    assert_log_capture(capture, 'decorated_global_function()')
+    assert_log_capture(
+        capture, func_pattern='decorated_global_function')
+
+
+def test_1c_global_props_args_from_global(capture):
+    # pylint: disable=redefined-outer-name
+    """Simple test calling a decorated global function with properties as args,
+    from a global function."""
+    props = {
+        'prop1': 'value1',
+        'hideme': 'secret',
+    }
+    blanked_props = {
+        'prop1': 'value1',
+        'hideme': BLANKED_OUT_STRING,
+    }
+    call_from_global(decorated_global_props_function, props)
+
+    assert_log_capture(
+        capture, func_pattern='decorated_global_props_function',
+        args_pattern=re.escape(str(blanked_props)),
+        return_pattern=re.escape(str(props)))
+
+
+def test_1c_global_props_kwargs_from_global(capture):
+    # pylint: disable=redefined-outer-name
+    """Simple test calling a decorated global function with properties as
+    kwargs, from a global function."""
+
+    call_from_global(decorated_global_props_function,
+                     properties={'prop1': 'value1'})
+
+    assert_log_capture(
+        capture, func_pattern='decorated_global_props_function')
 
 
 def test_2a_global_inner1_from_global(capture):
@@ -204,7 +256,8 @@ def test_2a_global_inner1_from_global(capture):
 
     call_from_global(decorated_inner1_function)
 
-    assert_log_capture(capture, 'global1_function.decorated_inner1_function()')
+    assert_log_capture(
+        capture, func_pattern='global1_function.decorated_inner1_function')
 
 
 def test_2b_global_inner1_from_method(capture):
@@ -216,7 +269,8 @@ def test_2b_global_inner1_from_method(capture):
 
     CallerClass().call_from_method(decorated_inner1_function)
 
-    assert_log_capture(capture, 'global1_function.decorated_inner1_function()')
+    assert_log_capture(
+        capture, func_pattern='global1_function.decorated_inner1_function')
 
 
 def test_3a_global_inner2_from_global(capture):
@@ -228,7 +282,8 @@ def test_3a_global_inner2_from_global(capture):
 
     call_from_global(decorated_inner2_function)
 
-    assert_log_capture(capture, 'inner1_function.decorated_inner2_function()')
+    assert_log_capture(
+        capture, func_pattern='inner1_function.decorated_inner2_function')
 
 
 def test_3b_global_inner1_from_method(capture):
@@ -240,7 +295,8 @@ def test_3b_global_inner1_from_method(capture):
 
     CallerClass().call_from_method(decorated_inner2_function)
 
-    assert_log_capture(capture, 'inner1_function.decorated_inner2_function()')
+    assert_log_capture(
+        capture, func_pattern='inner1_function.decorated_inner2_function')
 
 
 def test_4a_method_from_global(capture):
@@ -252,7 +308,8 @@ def test_4a_method_from_global(capture):
 
     call_from_global(decorated_method, d)
 
-    assert_log_capture(capture, 'Decorator1Class.decorated_method()')
+    assert_log_capture(
+        capture, func_pattern='Decorator1Class.decorated_method')
 
 
 def test_4b_method_from_method(capture):
@@ -264,7 +321,8 @@ def test_4b_method_from_method(capture):
 
     CallerClass().call_from_method(decorated_method, d)
 
-    assert_log_capture(capture, 'Decorator1Class.decorated_method()')
+    assert_log_capture(
+        capture, func_pattern='Decorator1Class.decorated_method')
 
 
 def test_5a_method_from_global(capture):
@@ -277,7 +335,8 @@ def test_5a_method_from_global(capture):
 
     call_from_global(decorated_inner_function)
 
-    assert_log_capture(capture, 'method.decorated_inner_function()')
+    assert_log_capture(
+        capture, func_pattern='method.decorated_inner_function')
 
 
 def test_5b_method_from_method(capture):
@@ -290,7 +349,8 @@ def test_5b_method_from_method(capture):
 
     CallerClass().call_from_method(decorated_inner_function)
 
-    assert_log_capture(capture, 'method.decorated_inner_function()')
+    assert_log_capture(
+        capture, func_pattern='method.decorated_inner_function')
 
 
 def test_decorated_class():