Issue 50550 - DS installer debug messages leaking to ipa-server-install

Bug Description:
DS installer debug messages are now leaked in the main ipa-server-install output.
This looks as a (very minor) regression, I did not see this text in the past.

Fix Description:
Clean up loging in lib389. Replace 'sepolicy' module with subprocess call
to 'semanage' tool. It is done because 'sepolicy' has verbose output that
appears on 'import'. Instead of developing a tricky workaround, direct
'semange' call was used.

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

Reviewed by: firstyear, mreynolds, mhonek (Thanks!)

src/lib389/lib389/__init__.py

@@ -463,7 +463,7 @@ def local_simple_allocate(self, serverid, ldapuri=None, binddn='cn=Directory Man
         self.binddn = binddn
         self.bindpw = password
         self.state = DIRSRV_STATE_ALLOCATED
-        self.log.info("Allocate local instance %s with %s", self.__class__, self.ldapuri)
+        self.log.debug("Allocate local instance %s with %s", self.__class__, self.ldapuri)
 
     def remote_simple_allocate(self, ldapuri, binddn='cn=Directory Manager', password=None):
         """Allocate an instance, and perform a simple bind. This instance is remote, so
@@ -494,7 +494,7 @@ def remote_simple_allocate(self, ldapuri, binddn='cn=Directory Manager', passwor
         self.binddn = binddn
         self.bindpw = password
         self.state = DIRSRV_STATE_ALLOCATED
-        self.log.info("Allocate %s with %s", self.__class__, self.ldapuri)
+        self.log.debug("Allocate %s with %s", self.__class__, self.ldapuri)
 
     # Should there be an extra boolean to this function to determine to use
     #  ldapi or not? Or does the settings presence indicate intent?

src/lib389/lib389/instance/remove.py

@@ -9,6 +9,7 @@
 import os
 import shutil
 import subprocess
+import logging
 from lib389.nss_ssl import NssSsl
 from lib389.utils import selinux_label_port, assert_c
 
@@ -98,7 +99,10 @@ def remove_ds_instance(dirsrv, force=False):
     if dirsrv.ds_paths.with_systemd:
         # Remove the systemd symlink
         _log.debug("Removing the systemd symlink")
-        subprocess.check_call(["systemctl", "disable", "dirsrv@{}".format(dirsrv.serverid)])
+
+        result = subprocess.run(["systemctl", "disable", "dirsrv@{}".format(dirsrv.serverid)],
+                                stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+        _log.debug(f"CMD: {' '.join(result.args)} ; STDOUT: {result.stdout} ; STDERR: {result.stderr}")
 
         _log.debug("Removing %s" % tmpfiles_d_path)
         shutil.rmtree(tmpfiles_d_path, ignore_errors=True)
@@ -147,4 +151,3 @@ def remove_ds_instance(dirsrv, force=False):
 
     # Done!
     _log.debug("Complete")
-

src/lib389/lib389/instance/setup.py

@@ -8,6 +8,7 @@
 # --- END COPYRIGHT BLOCK ---
 
 import os
+import logging
 import sys
 import shutil
 import pwd
@@ -639,7 +640,9 @@ def create_from_args(self, general, slapd, backends=[], extra=None):
         Actually does the setup. this is what you want to call as an api.
         """
 
-        self.log.info("\nStarting installation...")
+        self.log.debug("START: Starting installation...")
+        if not self.verbose:
+            self.log.info("Starting installation...")
 
         # Check we have privs to run
         self.log.debug("READY: Preparing installation for %s...", slapd['instance_name'])
@@ -669,6 +672,7 @@ def create_from_args(self, general, slapd, backends=[], extra=None):
         self.log.debug("FINISH: Completed installation for %s", slapd['instance_name'])
         if not self.verbose:
             self.log.info("Completed installation for %s", slapd['instance_name'])
+
         return True
 
     def _install_ds(self, general, slapd, backends):
@@ -784,9 +788,9 @@ def _install_ds(self, general, slapd, backends):
         # If we are on the correct platform settings, systemd
         if general['systemd']:
             # Should create the symlink we need, but without starting it.
-            subprocess.check_call(["systemctl",
-                                   "enable",
-                                   "dirsrv@%s" % slapd['instance_name']])
+            result = subprocess.run(["systemctl", "enable", "dirsrv@%s" % slapd['instance_name']],
+                                    stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+            self.log.debug(f"CMD: {' '.join(result.args)} ; STDOUT: {result.stdout} ; STDERR: {result.stderr}")
 
             # Setup tmpfiles_d
             tmpfile_d = ds_paths.tmpfiles_d + "/dirsrv-" + slapd['instance_name'] + ".conf"
@@ -801,7 +805,6 @@ def _install_ds(self, general, slapd, backends):
 
         # Bind sockets to our type?
 
-
         # Create certdb in sysconfidir
         self.log.debug("ACTION: Creating certificate database is %s", slapd['cert_dir'])
 

src/lib389/lib389/utils.py

@@ -197,13 +197,6 @@ def selinux_present():
         # No python module, so who knows what state we are in.
         log.error('selinux python module not found, will not relabel files.' )
 
-    try:
-        if status:
-            # Only if we know it's enabled, check if we can manage ports too.
-            import sepolicy
-    except ImportError:
-        log.error('sepolicy python module not found, will not relabel ports.' )
-
     return status
 
 
@@ -231,6 +224,30 @@ def selinux_restorecon(path):
         log.debug("Failed to run restorecon on: " + path)
 
 
+def _get_selinux_port_policies(port):
+    """Get a list of selinux port policies for the specified port, 'tcp' protocol and
+    excluding 'unreserved_port_t', 'reserved_port_t', 'ephemeral_port_t' labels"""
+
+    # [2:] - cut first lines containing the headers. [:-1] - empty line
+    policy_lines = subprocess.check_output(["semanage", "port", "-l"], encoding='utf-8').split("\n")[2:][:-1]
+    policies = []
+    for line in policy_lines:
+        data = line.split()
+        ports_list = []
+        for p in data[2:]:
+            if "," in p:
+                p = p[:-1]
+            if "-" in p:
+                p = range(int(p.split("-")[0]), int(p.split("-")[1]))
+            else:
+                p = [int(p)]
+            ports_list.extend(p)
+        if data[1] == 'tcp' and port in ports_list and \
+           data[0] not in ['unreserved_port_t', 'reserved_port_t', 'ephemeral_port_t']:
+            policies.append({'protocol': data[1], 'type': data[0], 'ports': ports_list})
+    return policies
+
+
 def selinux_label_port(port, remove_label=False):
     """
     Either set or remove an SELinux label(ldap_port_t) for a TCP port
@@ -247,12 +264,6 @@ def selinux_label_port(port, remove_label=False):
         log.debug('selinux python module not found, skipping port labeling.')
         return
 
-    try:
-        import sepolicy
-    except ImportError:
-        log.debug('sepolicy python module not found, skipping port labeling.')
-        return
-
     if not selinux.is_selinux_enabled():
         log.debug('selinux is disabled, skipping port relabel')
         return
@@ -264,23 +275,17 @@ def selinux_label_port(port, remove_label=False):
     if port in selinux_default_ports:
         log.debug('port {} already in {}, skipping port relabel'.format(port, selinux_default_ports))
         return
-
     label_set = False
     label_ex = None
 
-    policies = [p for p in sepolicy.info(sepolicy.PORT)
-                if p['protocol'] == 'tcp'
-                if port in range(p['low'], p['high'] + 1)
-                if p['type'] not in ['unreserved_port_t', 'reserved_port_t', 'ephemeral_port_t']]
+    policies = _get_selinux_port_policies(port)
 
     for policy in policies:
         if "ldap_port_t" == policy['type']:
             label_set = True  # Port already has our label
-            if policy['low'] != policy['high']:
-                # We have a range
-                if port in range(policy['low'], policy['high'] + 1):
-                    # The port is within the range, just return
-                    return
+            if port in policy['ports']:
+                # The port is within the range, just return
+                return
             break
         elif not remove_label:
             # Port belongs to someone else (bad)
@@ -290,10 +295,13 @@ def selinux_label_port(port, remove_label=False):
     if (remove_label and label_set) or (not remove_label and not label_set):
         for i in range(5):
             try:
-                subprocess.check_call(["semanage", "port",
-                                       "-d" if remove_label else "-a",
-                                       "-t", "ldap_port_t",
-                                       "-p", "tcp", str(port)])
+                result = subprocess.run(["semanage", "port",
+                                         "-d" if remove_label else "-a",
+                                         "-t", "ldap_port_t",
+                                         "-p", "tcp", str(port)],
+                                         stdout=subprocess.PIPE,
+                                         stderr=subprocess.PIPE)
+                log.debug(f"CMD: {' '.join(result.args)} ; STDOUT: {result.stdout} ; STDERR: {result.stderr}")
                 return
             except (OSError, subprocess.CalledProcessError) as e:
                 label_ex = e