Ticket 50251 - clear text passwords visable in CLI verbose mode logging

Bug Description:  If you run any of the CLI tools using "-v", and set a password,
                  that password will be displayed in clear text in the console.

Fix Description:  Create an internal list of sensitive attributes to filter, and
                  mask them in the operation debug logging.  But still allow the
                  password to be seen if you set the env variable DEBUGGING=true

                  We also still print the root DN password if it is a container
                  installation.

https://pagure.io/389-ds-base/issue/50251

Reviewed by: spichugi, firstyear, and mhonek (Thanks!!!)

src/lib389/lib389/_constants.py

@@ -41,6 +41,12 @@ REPLICATION_BIND_METHOD = RA_METHOD
 REPLICATION_TRANSPORT = RA_TRANSPORT_PROT
 REPLICATION_TIMEOUT = RA_TIMEOUT
 
+# Attributes that should be masked from logging output
+SENSITIVE_ATTRS = ['userpassword',
+                   'nsslapd-rootpw',
+                   'nsds5replicacredentials',
+                   'nsmultiplexorcredentials']
+
 TRANS_STARTTLS = "starttls"
 TRANS_SECURE = "secure"
 TRANS_NORMAL = "normal"

src/lib389/lib389/_entry.py

@@ -6,7 +6,6 @@
 # See LICENSE for details.
 # --- END COPYRIGHT BLOCK ---
 
-import re
 import six
 import logging
 import ldif
@@ -17,12 +16,13 @@ import sys
 
 from lib389._constants import *
 from lib389.properties import *
-from lib389.utils import ensure_str, ensure_bytes, ensure_list_bytes
+from lib389.utils import (ensure_str, ensure_bytes, ensure_list_bytes, display_log_data)
 
 MAJOR, MINOR, _, _, _ = sys.version_info
 
 log = logging.getLogger(__name__)
 
+
 class FormatDict(cidict):
     def __getitem__(self, name):
         if name in self:
@@ -258,12 +258,13 @@ class Entry(object):
 
     def update(self, dct):
         """Update passthru to the data attribute."""
-        log.debug("update dn: %r with %r" % (self.dn, dct))
+        log.debug("updating dn: {}".format(self.dn))
         for k, v in list(dct.items()):
             if isinstance(v, list) or isinstance(v, tuple):
                 self.data[k] = v
             else:
                 self.data[k] = [v]
+        log.debug("updated dn: {} with {}".format(self.dn, display_log_data(dct)))
 
     def __repr__(self):
         """Convert the Entry to its LDIF representation"""

src/lib389/lib389/_mapped_object.py

@@ -7,18 +7,18 @@
 # See LICENSE for details.
 # --- END COPYRIGHT BLOCK ---
 
+import os
 import ldap
 import ldap.dn
 from ldap import filter as ldap_filter
 import logging
 import json
 from functools import partial
-
 from lib389._entry import Entry
 from lib389._constants import DIRSRV_STATE_ONLINE, SER_ROOT_DN, SER_ROOT_PW
 from lib389.utils import (
         ensure_bytes, ensure_str, ensure_int, ensure_list_bytes, ensure_list_str,
-        ensure_list_int
+        ensure_list_int, display_log_value, display_log_data
         )
 
 # This function filter and term generation provided thanks to
@@ -370,7 +370,7 @@ class DSLdapObject(DSLogging):
             action_txt = "UNKNOWN"
 
         if value is None or len(value) < 512:
-            self._log.debug("%s set %s: (%r, %r)" % (self._dn, action_txt, key, value))
+            self._log.debug("%s set %s: (%r, %r)" % (self._dn, action_txt, key, display_log_value(key, value)))
         else:
             self._log.debug("%s set %s: (%r, value too large)" % (self._dn, action_txt, key))
         if self._instance.state != DIRSRV_STATE_ONLINE:
@@ -827,11 +827,11 @@ class DSLdapObject(DSLogging):
         """
         assert(len(self._create_objectclasses) > 0)
         basedn = ensure_str(basedn)
-        self._log.debug('Checking "%s" under %s : %s' % (rdn, basedn, properties))
+        self._log.debug('Checking "%s" under %s : %s' % (rdn, basedn, display_log_data(properties)))
         # Add the objectClasses to the properties
         (dn, valid_props) = self._validate(rdn, properties, basedn)
         # Check if the entry exists or not? .add_s is going to error anyway ...
-        self._log.debug('Validated dn %s : valid_props %s' % (dn, valid_props))
+        self._log.debug('Validated dn {}'.format(dn))
 
         exists = False
 
@@ -863,8 +863,8 @@ class DSLdapObject(DSLogging):
             e.update({'objectclass': ensure_list_bytes(self._create_objectclasses)})
             e.update(valid_props)
             # We rely on exceptions here to indicate failure to the parent.
-            self._log.debug('Creating entry %s : %s' % (dn, e))
             self._instance.add_ext_s(e, serverctrls=self._server_controls, clientctrls=self._client_controls, escapehatch='i am sure')
+            self._log.debug('Created entry %s : %s' % (dn, display_log_data(e.data)))
             # If it worked, we need to fix our instance dn for the object's self reference. Because
             # we may not have a self reference yet (just created), it may have changed (someone
             # set dn, but validate altered it).

src/lib389/lib389/instance/setup.py

@@ -438,7 +438,7 @@ class SetupDs(object):
                     backend['suffix'] = val
                     break
                 else:
-                    print("The suffix \"{}\" is not a valid DN")
+                    print("The suffix \"{}\" is not a valid DN".format(val))
                     continue
             else:
                 backend['suffix'] = suffix
@@ -932,6 +932,10 @@ class SetupDs(object):
         # Change the root password finally
         ds_instance.config.set('nsslapd-rootpw', slapd['root_password'])
 
+        # We need to log the password when containerised
+        if self.containerised:
+            self.log.debug("Root DN password: {}".format(slapd['root_password']))
+
         # Complete.
         if general['start']:
             # Restart for changes to take effect - this could be removed later

src/lib389/lib389/tests/utils_test.py

@@ -134,6 +134,17 @@ def test_formatInfData_withconfigserver():
     log.info("content: %r" % ret)
 
 
[email protected]('data', [
+    ({'userpaSSwoRd': '1234', 'nsslaPd-rootpw': '5678', 'regularAttr': 'originalvalue'},
+     {'userpaSSwoRd': '********', 'nsslaPd-rootpw': '********', 'regularAttr': 'originalvalue'}),
+    ({'userpassword': ['1', '2', '3'], 'nsslapd-rootpw': ['x']},
+     {'userpassword': ['********', '********', '********'], 'nsslapd-rootpw': ['********']})
+])
+def test_get_log_data(data):
+    before, after = data
+    assert display_log_data(before) == after
+
+
 if __name__ == "__main__":
     CURRENT_FILE = os.path.realpath(__file__)
     pytest.main("-s -v %s" % CURRENT_FILE)

src/lib389/lib389/utils.py

@@ -46,7 +46,7 @@ from lib389.paths import Paths
 from lib389.dseldif import DSEldif
 from lib389._constants import (
         DEFAULT_USER, VALGRIND_WRAPPER, DN_CONFIG, CFGSUFFIX, LOCALHOST,
-        ReplicaRole, CONSUMER_REPLICAID
+        ReplicaRole, CONSUMER_REPLICAID, SENSITIVE_ATTRS
     )
 from lib389.properties import (
         SER_HOST, SER_USER_ID, SER_GROUP_ID, SER_STRICT_HOSTNAME_CHECKING, SER_PORT,
@@ -56,6 +56,8 @@ from lib389.properties import (
 
 MAJOR, MINOR, _, _, _ = sys.version_info
 
+DEBUGGING = os.getenv('DEBUGGING', default=False)
+
 log = logging.getLogger(__name__)
 
 #
@@ -1200,6 +1202,7 @@ def get_instance_list(prefix=None):
     insts.sort()
     return insts
 
+
 def get_user_is_ds_owner():
     # Check if we have permission to administer the DS instance. This is required
     # for some tasks such as installing, killing, or editing configs for the
@@ -1215,6 +1218,7 @@ def get_user_is_ds_owner():
         return True
     return False
 
+
 def get_user_is_root():
     cur_uid = os.getuid()
     if cur_uid == 0:
@@ -1222,9 +1226,26 @@ def get_user_is_root():
         return True
     return False
 
+
 def basedn_to_ldap_dns_uri(basedn):
-    #  ldap:///dc%3Dexample%2Cdc%3Dcom
+    # ldap:///dc%3Dexample%2Cdc%3Dcom
     return "ldaps:///" + basedn.replace("=", "%3D").replace(",", "%2C")
 
 
+def display_log_value(attr, value, hide_sensitive=True):
+    # Mask all the sensitive attribute values
+    if DEBUGGING or not hide_sensitive:
+        return value
+    else:
+        if attr.lower() in SENSITIVE_ATTRS:
+            if type(value) in (list, tuple):
+                return list(map(lambda _: '********', value))
+            else:
+                return '********'
+        else:
+            return value
+
 
+def display_log_data(data, hide_sensitive=True):
+    # Take a dict and mask all the sensitive data
+    return {a: display_log_value(a, v, hide_sensitive) for a, v in data.items()}