Bug 2115254

Mark, I'd swear we talked about this one but I can't find an open BZ on it.

Either way it is just extra output on stderr and does not impact operation.

(In reply to Rob Crittenden from comment #1)
> Mark, I'd swear we talked about this one but I can't find an open BZ on it.
> 
> Either way it is just extra output on stderr and does not impact operation.

Hmm, yeah I recall this topic as well.  We don't have changelog5 anymore in 8.7 (or 8.6 maybe not in 8.5) so let me look into this.  I hope we didn't have some sort of merge commit that undid this change. :-(

Changing component since this message appears to originate in the lib389 checks.

*** Bug 2109958 has been marked as a duplicate of this bug. ***

I can reproduce this issue using ipa-healthcheck.  But on the same system calling DS's "dsctl healthcheck" I do not see these errors.

Looking at DS lint code used by our healthcheck we catch the error 32 and just ignore it:

        try:
            # Check if replication is enabled
            replicas.get(suffix)
            # Check the changelog
            cl = Changelog5(self._instance)
            if cl.get_attr_val_utf8('nsslapd-changelogmaxentries') is None and \
               cl.get_attr_val_utf8('nsslapd-changelogmaxage') is None:
                report = copy.deepcopy(DSCLLE0001)
                report['fix'] = report['fix'].replace('YOUR_INSTANCE', self._instance.serverid)
                report['check'] = f'backends:{bename}::cl_trimming'
                yield report
        except:
            # Suffix is not replicated
            self._log.debug(f"_lint_cl_trimming - backend ({suffix}) is not replicated")
            pass


I forget how IPA uses DS healthchecks from lib389, Rob can you refresh my memory on how it gets pulled into ipa-healthcheck?

The DSPlugin class is the bridge between the DS checks and the healthchecks, https://github.com/freeipa/freeipa-healthcheck/blob/master/src/ipahealthcheck/ds/plugin.py#L29

This is the base class for the checks in the other files which take the form of, for example:

@registry
class DSECheck(DSPlugin):
    """
    Check the dse.ldif/cn=config for obvious issues
    """
    check_class = DSEldif

The DSPlugin catches the check() call from healthcheck and calls the 389-ds equivalent, then transforms the result into something healthcheck can understand.

This is beyond my python skills.  I can absolutely confirm that the DS code is catching the exception and properly handling it, but the healthcheck code is somehow detecting the exception and capturing and reporting the exception message.  I don't know what I could do differently in the DS code to prevent this from happening.

Moving back to ipa-healthcheck because I see nothing wrong in the DS code (try/except/pass is working), or no way to prevent the calling code from detecting that an exception was caught.

Mark, the error appears to originate in python-ldap. The call to _search_ext_s() produces this output:

args=({'msgtype': 101, 'msgid': 3, 'result': 32, 'desc': 'No such object', 'ctrls': [], 'ldap_request': "search_ext_s(('cn=changelog5,cn=config', 0, '(objectClass=*)'),{'attrlist': ['nsslapd-changelogmaxentries'], 'serverctrls': None, 'clientctrls': None, 'escapehatch': 'i am sure'}) on instance EXAMPLE-TEST"},)
Traceback (most recent call last):

I can't tell why it only outputs on this specific call.

The message first appears in the healthcheck output in 389-ds-base-1.4.3.30-3.module+el8.7.0+15600+347cafc6.x86_64

It does not appear prior to that.

The problem is this logging statement in the roll-up patch:

++++ b/src/lib389/lib389/_mapped_object.py
...
++# Define wrappers around the ldap operation to have a clear diagnostic
++def _ldap_op_s(inst, f, fname, *args, **kwargs):
++    # f.__name__ says 'inner' so the wanted name is provided as argument
++    try:
++        return f(*args, **kwargs)
++    except ldap.LDAPError as e:
++        new_desc = f"{fname}({args},{kwargs}) on instance {inst.serverid}";
++        if len(e.args) >= 1:
++            e.args[0]['ldap_request'] = new_desc
++            logging.getLogger().error(f"args={e.args}")
              ^^^ here

I commented that out and no more message.

Re-assigning product to 389-ds-base.

(In reply to Rob Crittenden from comment #10)
> The message first appears in the healthcheck output in
> 389-ds-base-1.4.3.30-3.module+el8.7.0+15600+347cafc6.x86_64
> 
> It does not appear prior to that.
> 
> The problem is this logging statement in the roll-up patch:
> 
> ++++ b/src/lib389/lib389/_mapped_object.py
> ...
> ++# Define wrappers around the ldap operation to have a clear diagnostic
> ++def _ldap_op_s(inst, f, fname, *args, **kwargs):
> ++    # f.__name__ says 'inner' so the wanted name is provided as argument
> ++    try:
> ++        return f(*args, **kwargs)
> ++    except ldap.LDAPError as e:
> ++        new_desc = f"{fname}({args},{kwargs}) on instance {inst.serverid}";
> ++        if len(e.args) >= 1:
> ++            e.args[0]['ldap_request'] = new_desc
> ++            logging.getLogger().error(f"args={e.args}")
>               ^^^ here
> 
> I commented that out and no more message.

I don't think we should remove that code...

I think I don't see this issue when I run our healthcheck tool is because we explicitly set the logger to stdout.  I could be wrong, but it seems that the logger is the only difference between our tools:

    logger = logging.getLogger()
    log_handler = logging.StreamHandler(sys.stdout)
    logger.addHandler(log_handler)

I am curious to see if this code fixes the issue in ipa healthcheck tool (not sure where it should be added though).  I'll try and work on it next week...

Adding that logging change actually makes the message print twice. smh.  Assigning to Simon to continue investigation...

Actually, looks like you've fixed it already, Mark!

As Rob pointed out, the issue happens precisely because of this line in src/lib389/lib389/_mapped_object.py:

    logging.getLogger().error(f"args={e.args}")

It reports to 'error' and the IPA tool reports it (as everything in 'error' level is reported).
If we change it to:

    logging.getLogger().debug(f"args={e.args}")

The issue is fixed.
The commit https://github.com/389ds/389-ds-base/commit/01a3d566babb746beb03fba84cad186cbaf7af68 is already in 1.4.3 upstream.
We just need to create a build with the change in Downstream.

I've made a scratch build with the commit and it fixed the issue for me. Feel free to check it, in a meanwhile:
http://brew-task-repos.usersys.redhat.com/repos/scratch/spichugi/389-ds-base/1.4.3.30/6ipahlthcheck.el8_7/

(In reply to Simon Pichugin from comment #13)
> Actually, looks like you've fixed it already, Mark!
> 

So I did ;-)  It is in the current 8.8 build, moving bug to modified

As per comment #c20, marking as VERIFIED.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (389-ds:1.4 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:2811