What version of IPA on what distribution?

Up to date IPA from Fedora 39...rawhide c9s, c10s. We use https://quay.io/organization/sssd ci-ipa container which is rebuilt weekly for all active distros. This particular log is from f39.

From the iprestore.log we see: IPA version 4.12.1-1.fc39

The source code is creating an entry for the import task, similar to
dn: cn=import_$date,cn=import,cn=tasks,cn=config
changetype: add
objectClass: top
objectClass: extensibleObject
cn: import_$date
nsfilename: /var/lib/dirsrv/slapd-IPA-TEST/ldif/IPA-TEST-userRoot.ldif
nsuseonefile: true
nsinstance: userRoot

but either the connection or the ldap add of this entry is failing.
Do you have directory server access logs and audit logs? It would help check if the bind or the op is failing.

Those are empty. Only the errors log is populated.

We need the DS access log from this failure. There is log buffering for the access log, so you need to wait 30 seconds after the issue happens before the log information is written to disk.

Ok, I will get new logs. Is there anything else that you might require or any debug level set somewhere?

Also the DS error log was truncated/clipped. We need to see the logging prior to the error message. If it's not to large just provide the whole log, or at least provide a clip that shows the entire restore process

As for logging levels you can increase the access logging to record what plugins are doing.

# dsconf slapd-IPA-TEST config replace nsslapd-plugin-logging=on nsslapd-accesslog-level=260

Again you need to for for access log buffering to flush the data.

After the issue is reproduced you can turn these settings off:

# dsconf slapd-IPA-TEST config replace nsslapd-plugin-logging=off nsslapd-accesslog-level=256

Thanks!

Also the DS error log was truncated/clipped. We need to see the logging prior to the error message.

You got logs from this run: https://github.com/pbrezina/sssd-test-framework/blob/citest/sssd_test_framework/hosts/ipa.py#L177-L208

All logs are truncated, ipa-restore is called, and logs are printed.

Also the DS error log was truncated/clipped. We need to see the logging prior to the error message.

You got logs from this run: https://github.com/pbrezina/sssd-test-framework/blob/citest/sssd_test_framework/hosts/ipa.py#L177-L208

All logs are truncated, ipa-restore is called, and logs are printed.

Can you add this change:

diff --git a/sssd_test_framework/hosts/ipa.py b/sssd_test_framework/hosts/ipa.py
index f592c3a..256aff3 100644
--- a/sssd_test_framework/hosts/ipa.py
+++ b/sssd_test_framework/hosts/ipa.py
@@ -9,6 +9,7 @@ from pytest_mh.conn import ProcessLogLevel
 from ..misc.ssh import retry_command
 from .base import BaseDomainHost, BaseLinuxHost
+import time
 __all__ = [
     "IPAHost",
@@ -179,6 +180,7 @@ class IPAHost(BaseDomainHost, BaseLinuxHost):
         self.conn.run("truncate --size 0 /var/log/dirsrv/slapd-IPA-TEST/audit")
         self.conn.run("truncate --size 0 /var/log/dirsrv/slapd-IPA-TEST/security")
         self.conn.run("truncate --size 0 /var/log/iparestore.log")
+        time.sleep(1)  # Probably not needed but for debugging its ok
         self.conn.run(
             f"""
             set -ex
@@ -201,6 +203,7 @@ class IPAHost(BaseDomainHost, BaseLinuxHost):
             """,
             log_level=ProcessLogLevel.Error,
         )
+        time.sleep(31)  # access log buffering needs to flush
         self.conn.run("cat /var/log/iparestore.log")
         self.conn.run("cat /var/log/dirsrv/slapd-IPA-TEST/errors")
         self.conn.run("cat /var/log/dirsrv/slapd-IPA-TEST/access")

Actually here a diff that sets the logging levels (warning - I did not test this code)

diff --git a/sssd_test_framework/hosts/ipa.py b/sssd_test_framework/hosts/ipa.py
index f592c3a..c1ad0ed 100644
--- a/sssd_test_framework/hosts/ipa.py
+++ b/sssd_test_framework/hosts/ipa.py
@@ -9,6 +9,7 @@ from pytest_mh.conn import ProcessLogLevel
 from ..misc.ssh import retry_command
 from .base import BaseDomainHost, BaseLinuxHost
+import time
 __all__ = [
     "IPAHost",
@@ -179,6 +180,7 @@ class IPAHost(BaseDomainHost, BaseLinuxHost):
         self.conn.run("truncate --size 0 /var/log/dirsrv/slapd-IPA-TEST/audit")
         self.conn.run("truncate --size 0 /var/log/dirsrv/slapd-IPA-TEST/security")
         self.conn.run("truncate --size 0 /var/log/iparestore.log")
+        time.sleep(1)  # Probably not needed but for debugging its ok
         self.conn.run(
             f"""
             set -ex
@@ -190,6 +192,8 @@ class IPAHost(BaseDomainHost, BaseLinuxHost):
                 fi
             }}
+            dsconf slapd-IPA-TEST config replace nsslapd-plugin-logging=on nsslapd-accesslog-level=260
+
             ipa-restore --unattended --password "{self.adminpw}" --data --online "{backup_path}/ipa"
             rm --force --recursive /etc/sssd /var/lib/sss /var/log/sssd
@@ -198,9 +202,12 @@ class IPAHost(BaseDomainHost, BaseLinuxHost):
             restore "{backup_path}/config" /etc/sssd
             restore "{backup_path}/logs" /var/log/sssd
             restore "{backup_path}/lib" /var/lib/sss
+
+            dsconf slapd-IPA-TEST config replace nsslapd-plugin-logging=off nsslapd-accesslog-level=256
             """,
             log_level=ProcessLogLevel.Error,
         )
+        time.sleep(31)  # access log buffering needs to flush
         self.conn.run("cat /var/log/iparestore.log")
         self.conn.run("cat /var/log/dirsrv/slapd-IPA-TEST/errors")
         self.conn.run("cat /var/log/dirsrv/slapd-IPA-TEST/access")

Ok, I think I know what is going on. In DS if there is an operation in progress the online import will abort. It's actually a very rare condition, but it can happen.

I think DS should internally retry the import a few times when there is a pending operation. Waiting to hear back from the DS team on that.

In the meantime lets try and reproduce it with the diff I have above, but remove the one "time.sleep(1)" code as that might actually make it harder to reproduce the issue. Note - please keep the last sleep(31) so the logs fully flush. Thanks!

Opened a DS issue to improve DS online import robustness:

https://github.com/389ds/389-ds-base/issues/6343

Opened a DS issue to improve DS online import robustness:

https://github.com/389ds/389-ds-base/issues/6343

Filed PR to fix issue:

https://github.com/389ds/389-ds-base/pull/6350

Thank you. I was not able to get new logs yet, it looks like the additional log level actually made it harder to reproduce.

Thank you. I was not able to get new logs yet, it looks like the additional log level actually made it harder to reproduce.

Yeah I believe it. At this point I wouldn't worry about it too much. So there are two options:

[1] Wait for the DS to approve and merge my PR and get it built into all upcoming releases. This will take time though.

[2] In the meantime, maybe adding a sleep for a second or two before issuing the restore command might help workaround the problem. I'd also say to try and build in a "retry", but if the restore command is returning success then that's probably not an option.

Thank you. I was not able to get new logs yet, it looks like the additional log level actually made it harder to reproduce.

Yeah I believe it. At this point I wouldn't worry about it too much. So there are two options:

[1] Wait for the DS to approve and merge my PR and get it built into all upcoming releases. This will take time though.

[2] In the meantime, maybe adding a sleep for a second or two before issuing the restore command might help workaround the problem. I'd also say to try and build in a "retry", but if the restore command is returning success then that's probably not an option.

Yeah, we are retrying it now if the error message is in output: https://github.com/SSSD/sssd-test-framework/blob/master/sssd_test_framework/hosts/ipa.py#L175

Yeah, we are retrying it now if the error message is in output: https://github.com/SSSD/sssd-test-framework/blob/master/sssd_test_framework/hosts/ipa.py#L175

Nice!

The DS fix was merged upstream. Eventually It will land in fedora >=37).

Can this be closed?

@mreynolds PR was merged so I think this can be closed from SSSD's POV.