Improved checking for sensitive properties in logs

The following sensitive data is now blanked out that was not blanked out before:

In the HTTP operation logging:
  - "Create SSO Server Definition" operation:
    - `client-secret` request field - OIDC client secret for the SSO server

In the API call logging:
  - SSOServerDefinitionManager.create():
    - `client-secret` property - OIDC client secret for the SSO server

Note that the support for SSO server definitions is new and has not yet
been released. So this is not an externally documented fix.

Details:

* Changed the approach for blanking out sensitive properties in logs for
  API calls and return values: Instead of using the blanked_properties
  argument of the logged_api_call decorator to point to specific properties,
  the blanking out is now done when the string representation of the
  argument or return value has been created, by matching certain
  property names using a regexp in the repr() string of the arguments or
  return values.

  The blanked_properties argument in the logged_api_call decorator still
  exists in case it is needed in the future for additional properties, but
  it is not currently used.

* Changed the approach for blanking out sensitive properties in logs for
  HTTP requests and responses: Instead of checking for a set of specific
  sensitive property names in the dict representation of the request and
  response bodies, the sensitive properties are now detected by matching
  certain property names using a regexp in the JSON string of the body.

* In the test_logging.py unit test module, changed the use of .msg for
  accessing the expanded log message to using .getMessage(). It is not
  clear why that worked before, but getMessage() is the official way to
  get at the expanded log message.

* Improved performance in _log_http_request() and _log_http_response()
  by not executing the code when debug logging is disabled.

Signed-off-by: Andreas Maier <maiera@de.ibm.com>

Author: andy-maier

changes/noissue.24.feature.rst

@@ -0,0 +1,2 @@
+Improved checking for sensitive properties in logs to reduce maintenance
+effort.

tests/unit/zhmcclient/test_logging.py

@@ -162,7 +162,7 @@ def assert_log_capture(
     enter_record = log_capture.records[0]
     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)
+    assert re.match(_EXP_LOG_MSG_ENTER_PATTERN, enter_record.getMessage())
     func_str, args_str, kwargs_str = enter_record.args
     if func_pattern:
         assert re.search(func_pattern, func_str)
@@ -174,7 +174,7 @@ def assert_log_capture(
     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)
+    assert re.match(_EXP_LOG_MSG_LEAVE_PATTERN, leave_record.getMessage())
     func_str, return_str = leave_record.args
     if func_pattern:
         assert re.search(func_pattern, func_str)

zhmcclient/_activation_profile.py

@@ -225,8 +225,7 @@ def list(self, full_properties=False, filter_args=None,
             list_uri, result_prop, full_properties, filter_args,
             additional_properties)
 
-    @logged_api_call(blanked_properties=['ssc-master-pw', 'zaware-master-pw'],
-                     properties_pos=1)
+    @logged_api_call
     def create(self, properties):
         """
         Create and configure an Activation Profiles on this CPC, of the profile
@@ -346,8 +345,7 @@ def delete(self):
             self.get_properties_local(self.manager._name_prop, None))
         self.cease_existence_local()
 
-    @logged_api_call(blanked_properties=['ssc-master-pw', 'zaware-master-pw'],
-                     properties_pos=1)
+    @logged_api_call
     def update_properties(self, properties):
         """
         Update writeable properties of this Activation Profile.

zhmcclient/_constants.py

@@ -23,6 +23,8 @@
 ``zhmcclient`` namespace and should be used from there.
 """
 
+import re
+
 __all__ = ['DEFAULT_CONNECT_TIMEOUT',
            'DEFAULT_CONNECT_RETRIES',
            'DEFAULT_HMC_PORT',
@@ -52,7 +54,9 @@
            'HTML_REASON_OTHER',
            'STOMP_MIN_CONNECTION_CHECK_TIME',
            'DEFAULT_WS_TIMEOUT',
-           'BLANKED_OUT_STRING']
+           'BLANKED_OUT_STRING',
+           'BLANKED_OUT_PROPERTY_PATTERN',
+           'BLANKED_OUT_PROPERTY_REPLACE']
 
 
 #: Default HMC port number
@@ -210,3 +214,14 @@
 #: Replacement string for blanked out sensitive values in log entries, such as
 #: passwords or session tokens.
 BLANKED_OUT_STRING = '********'
+
+#: Regexp pattern for properties in the JSON or dict representation string that
+#: contains sensitive data and will be blanked out in any logs.
+BLANKED_OUT_PROPERTY_PATTERN = re.compile(
+    r"""(['"])"""
+    r"""([^'"]*(authentication-code|credential|key|passcode|password|pw"""
+    r"""|secret|session))"""
+    r"""\1\s*:\s*('(?:[^'\\]|\\.)*'|"(?:[^"\\]|\\.)*"|None|null)""")
+
+#: The replacement string corresponding to the regexp pattern.
+BLANKED_OUT_PROPERTY_REPLACE = rf"\1\2\1: \1{BLANKED_OUT_STRING}\1"

zhmcclient/_ldap_server_definition.py

@@ -152,7 +152,7 @@ def list(self, full_properties=False, filter_args=None):
         return self._list_with_operation(
             list_uri, result_prop, full_properties, filter_args, None)
 
-    @logged_api_call(blanked_properties=['bind-password'], properties_pos=1)
+    @logged_api_call
     def create(self, properties):
         """
         Create a new LDAP Server Definition in this HMC.
@@ -258,7 +258,7 @@ def delete(self):
             self.get_properties_local(self.manager._name_prop, None))
         self.cease_existence_local()
 
-    @logged_api_call(blanked_properties=['bind-password'], properties_pos=1)
+    @logged_api_call
     def update_properties(self, properties):
         """
         Update writeable properties of this LDAP Server Definitions.

zhmcclient/_logging.py

@@ -73,12 +73,14 @@
       logging.basicConfig(format=format_string, level=logging.DEBUG)
 """
 
+import re
 import logging
 import inspect
 import functools
 from collections.abc import Mapping, Sequence
 
-from ._constants import API_LOGGER_NAME, BLANKED_OUT_STRING
+from ._constants import API_LOGGER_NAME, BLANKED_OUT_STRING, \
+    BLANKED_OUT_PROPERTY_PATTERN, BLANKED_OUT_PROPERTY_REPLACE
 
 __all__ = []
 
@@ -115,6 +117,8 @@ def logged_api_call(
     The logger's name is the dotted module name of the module defining the
     decorated function (e.g. 'zhmcclient._cpc').
 
+    The values of sensitive properties will be blanked out.
+
     Parameters:
 
       org_func (function object): The original function being decorated.
@@ -277,22 +281,43 @@ def blanked_args(args, kwargs):
                         blanked_dict(args[properties_pos])
             return tuple(logged_args), logged_kwargs
 
+        def log_repr(obj, name, trunc):
+            """
+            Return a Python repr() representation of the object, with
+            sensitive properties blanked out.
+            """
+            obj_str = log_escaped(repr(obj))
+            obj_str = re.sub(BLANKED_OUT_PROPERTY_PATTERN,
+                             BLANKED_OUT_PROPERTY_REPLACE, obj_str)
+            obj_len = len(obj_str)
+            if obj_len > trunc > 0:
+                obj_str = (f"{name} (first {trunc} B of {obj_len} B): "
+                           f"{obj_str[0:trunc]} ...(truncated)")
+            else:
+                obj_str = f"{name}: {obj_str}"
+            return obj_str
+
         def log_call(args, kwargs):
             """
             Log the call to the API function.
             """
-            logged_args, logged_kwargs = blanked_args(args, kwargs)
-            logger.debug("Called: %s, args: %.500s, kwargs: %.500s",
-                         apifunc_str,
-                         log_escaped(repr(logged_args)),
-                         log_escaped(repr(logged_kwargs)))
+            trunc = 500
+            # We are calling log_trunc() also on args, because their values
+            # (in theory) may contain dicts with sensitive properties.
+            _args, _kwargs = blanked_args(args, kwargs)
+            args_str = log_repr(_args, "args", trunc)
+            kwargs_str = log_repr(_kwargs, "kwargs", trunc)
+            logger.debug("Called: %s, %s, %s",
+                         apifunc_str, args_str, kwargs_str)
 
         def log_return(result):
             """
             Log the return from the API function.
             """
-            logger.debug("Return: %s, result: %.1000s",
-                         apifunc_str, log_escaped(repr(result)))
+            trunc = 1000
+            result_str = log_repr(result, "result", trunc)
+            logger.debug("Return: %s, %s",
+                         apifunc_str, result_str)
 
         @functools.wraps(func)
         def log_api_call(*args, **kwargs):

zhmcclient/_lpar.py

@@ -188,8 +188,7 @@ def __init__(self, manager, uri, name=None, properties=None):
             f"got {type(manager)}")
         super().__init__(manager, uri, name, properties)
 
-    @logged_api_call(blanked_properties=['ssc-master-pw', 'zaware-master-pw'],
-                     properties_pos=1)
+    @logged_api_call
     def update_properties(self, properties):
         """
         Update writeable properties of this LPAR.

zhmcclient/_mfa_server_definition.py

@@ -152,7 +152,7 @@ def list(self, full_properties=False, filter_args=None):
         return self._list_with_operation(
             list_uri, result_prop, full_properties, filter_args, None)
 
-    @logged_api_call(blanked_properties=['bind-password'], properties_pos=1)
+    @logged_api_call
     def create(self, properties):
         """
         Create a new MFA Server Definition in this HMC.
@@ -258,7 +258,7 @@ def delete(self):
             self.get_properties_local(self.manager._name_prop, None))
         self.cease_existence_local()
 
-    @logged_api_call(blanked_properties=['bind-password'], properties_pos=1)
+    @logged_api_call
     def update_properties(self, properties):
         """
         Update writeable properties of this MFA Server Definitions.

zhmcclient/_partition.py

@@ -178,8 +178,7 @@ def list(self, full_properties=False, filter_args=None,
             list_uri, result_prop, full_properties, filter_args,
             additional_properties)
 
-    @logged_api_call(blanked_properties=['boot-ftp-password', 'ssc-master-pw'],
-                     properties_pos=1)
+    @logged_api_call
     def create(self, properties):
         """
         Create and configure a Partition in this CPC.
@@ -703,8 +702,7 @@ def delete(self):
             self.get_properties_local(self.manager._name_prop, None))
         self.cease_existence_local()
 
-    @logged_api_call(blanked_properties=['boot-ftp-password', 'ssc-master-pw'],
-                     properties_pos=1)
+    @logged_api_call
     def update_properties(self, properties):
         """
         Update writeable properties of this Partition.