#50551 Issue 50550 - DS installer debug messages leaking to ipa-server-install
Closed 3 years ago by spichugi. Opened 4 years ago by spichugi.
spichugi/389-ds-base fix_logging_info  into  master

@@ -463,7 +463,7 @@ 

          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 @@ 

          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?

@@ -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 @@ 

      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 @@ 

  

      # Done!

      _log.debug("Complete")

- 

@@ -8,6 +8,7 @@ 

  # --- END COPYRIGHT BLOCK ---

  

  import os

+ import logging

  import sys

  import shutil

  import pwd
@@ -639,7 +640,9 @@ 

          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 @@ 

          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 @@ 

          # 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 @@ 

  

          # Bind sockets to our type?

  

- 

          # Create certdb in sysconfidir

          self.log.debug("ACTION: Creating certificate database is %s", slapd['cert_dir'])

  

file modified
+35 -27
@@ -197,13 +197,6 @@ 

          # 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 @@ 

          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 @@ 

          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 @@ 

      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 @@ 

      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

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: ?

rebased onto 449840557709df06bddef3c31a935291340c4102

4 years ago

This should stay as info to ALWAYS indicate clearly that no action is taken on dry run.

This doesn't look like a logging change ;)

Why are we changing stderr here? That seems incorrect ....

This change concerns me because the whole point of this logging was so that in the case of a failure we had the logs in ipa's install log still. So ... why are we removing this? It seems like "clean logs" matters less than "we have all the info needed to solve a problem".

1 new commit added

  • Fix an issue reported by William. NOOP = debug -> info
4 years ago

This should stay as info to ALWAYS indicate clearly that no action is taken on dry run.
Why are we changing stderr here? That seems incorrect ....

Right. I was a bit harsh there... Setting it back.

This doesn't look like a logging change ;)

As I mentioned in the PR/Commit message, it is done because sepolicy has verbose output that appears on import (I've seen it only during ipa-server-install though...). Instead of developing a tricky workaround, direct semange call was used (it is still workaround but it is a straight forward one :) ).

This change concerns me because the whole point of this logging was so that in the case of a failure we had the logs in ipa's install log still. So ... why are we removing this? It seems like "clean logs" matters less than "we have all the info needed to solve a problem".

In case of a failure, we still have logging that is put to a separate file in IPA installation.
Also, I really see no benefit in systemctl enable/disable output on every (even non-verbose) run. The same is true for useless sepolicy import output (we have a separate check for selinux anyway).

2 new commits added

  • Fix issues reported by William. NOOP = debug -> info, semanage stderr
  • Issue 50550 - DS installer debug messages leaking to ipa-server-install
4 years ago

I'm worried about you removing these - these are important to detect and avoid selinux calls on systems without selinux (ie suse :) ). If there is an issue with the log message, just change it to log.warn instead? But this needs to stay.

After these two comments I think it's okay :) but those blocks shouldn't be removed.

I'm worried about you removing these - these are important to detect and avoid selinux calls on systems without selinux (ie suse :) ). If there is an issue with the log message, just change it to log.warn instead? But this needs to stay.

As I said previously, we have a check for selinux already...
It is done by import selinux; if selinux.is_selinux_enabled():

sepolicy is used only for acquiring labeled ports so we can relabel them.
And I can't set the logging to warn because it happens during import sepolicy and shown only during ipa-server-install (not sure why, some wierd logger setting?). I spent an hour trying to suppress the message and it already had become a weird workaround... So I decided to make a straight forward workaround. :)

Let's remove the initial newline from the text string, thanks

1 new commit added

  • Remove a new line character
4 years ago

Let's remove the initial newline from the text string, thanks

Fixed

I also see this seem annoying behavior from systemd every time I create an instance

# dscreate from-file /data/dssetup.inf 

Starting installation...
Created symlink /etc/systemd/system/multi-user.target.wants/dirsrv@localhost.service → /usr/lib/systemd/system/dirsrv@.service.
Completed installation for localhost

I originally moved that message to DEVNULL as well but that change was rejected by William I think :-p I personally want to see these messages removed from STDOUT by whatever means possible. :-)

Sorry just a side comment that's partially related to this issue

Gosh that William kid, just causing trouble for everyone, sheesh ;) Who even let that person be on the team anyway ....

There is a difficult balance here - between too much detail when not needed, and not enough info when it is needed. My greatest concern is "when something breaks, can the admin resolve it with the information we provided?". This is why I always err to "too much detail" because in the good case, we wasted some terminal space. If we remove that detail, we now have people who can't solve their issues, have a negative experience and can't supply the needed details to us to fix their issues.

I think that the current setup of the log system in lib389 is all focused around stdout/stderr. What we need is a way to also have it write as debug level to a location and then we can have a lower level in the stdout/stderr levels.

So instead of directing these to devnull, we should direct them to a python buffer via subprocess, then we should write these buffers to the log.debug. From there we can have the log code setup the file back and stderr/stdout handlers.

Thoughts?

Also what about the selinux bits?

rebased onto 462f9cdbf70d031b627559e702d213e1a79f8f39

4 years ago

I also see this seem annoying behavior from systemd every time I create an instance
dscreate from-file /data/dssetup.inf

I moved it to debug level so it won't be bagging during the non-verbose installation.

So instead of directing these to devnull, we should direct them to a python buffer via subprocess, then we should write these buffers to the log.debug. From there we can have the log code setup the file back and stderr/stdout handlers.
Thoughts?

Fully agree.
I've moved it to the debug and we can add a FileHandler option for logging in a separate issue (and it will be more of a new feature, I guess).

Anyway, this issue is ready for review. :)

selinux comments? you haven't addressed these ....

Ahhh you refactored it and I missed it.
Ack from me then.

rebased onto aa17a8f

4 years ago

Pull-Request has been merged by spichugi

4 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/3607

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.

Pull-Request has been closed by spichugi

3 years ago