backup/restore broken after bdb txn log rotation

[mreynolds389]

Issue Description

Unable to restore a backup using a build made from the main branch using "bdb"

Reproduce:

• Create DS instance using BDB
• Setup replication and do some mods --> not sure if this is necessary
• Stop the server
• Take a backup: dsctl INSTANCE db2bak my_backup
• Start server and run cleanallruv task --> not sure if this is necessary
• Stop the server
• Restore the backup: dsctl INSTANCE bak2db my_backup
• Fails:

...
...
[29/Oct/2024:08:32:44.705446704 -0400] - INFO - bdb_copy_directory - Restoring file 15 (/var/lib/dirsrv/slapd-localhost/db/userroot/entryUUID.db)
[29/Oct/2024:08:32:44.711564524 -0400] - INFO - bdb_copyfile - Copying /var/lib/dirsrv/slapd-localhost/bak/clean_changelog/userroot/entryUUID.db to /var/lib/dirsrv/slapd-localhost/db/userroot/entryUUID.db
[29/Oct/2024:08:32:44.717787591 -0400] - INFO - bdb_copy_directory - Restoring file 16 (/var/lib/dirsrv/slapd-localhost/db/userroot/replication_changelog.db)
[29/Oct/2024:08:32:44.723992505 -0400] - INFO - bdb_copyfile - Copying /var/lib/dirsrv/slapd-localhost/bak/clean_changelog/userroot/replication_changelog.db to /var/lib/dirsrv/slapd-localhost/db/userroot/replication_changelog.db
[29/Oct/2024:08:32:44.971451666 -0400] - INFO - bdb_restore - Restoring file 17 (/var/lib/dirsrv/slapd-localhost/db/log.0000000431)
[29/Oct/2024:08:32:44.987012298 -0400] - INFO - bdb_copyfile - Copying /var/lib/dirsrv/slapd-localhost/bak/clean_changelog/log.0000000431 to /var/lib/dirsrv/slapd-localhost/db/log.0000000431
[29/Oct/2024:08:32:44.997596558 -0400] - INFO - bdb_restore - Restoring file 18 (/dev/shm/slapd-localhost/DBVERSION)
[29/Oct/2024:08:32:45.004125465 -0400] - INFO - bdb_copyfile - Copying /var/lib/dirsrv/slapd-localhost/bak/clean_changelog/DBVERSION to /dev/shm/slapd-localhost/DBVERSION
[29/Oct/2024:08:32:45.713041942 -0400] - ERR - libdb - BDB1522 Log file corrupt at LSN: [84][753434]
[29/Oct/2024:08:32:45.720632303 -0400] - ERR - libdb - BDB0061 PANIC: Invalid argument
[29/Oct/2024:08:32:45.764186629 -0400] - ERR - libdb - BDB1546 unable to join the environment
[29/Oct/2024:08:32:45.879122840 -0400] - CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30973: Unexpected dbimpl error code
[29/Oct/2024:08:32:45.894651467 -0400] - CRIT - bdb_start - Please make sure there is enough disk space for dbcache (1610612736 bytes) and db region files
[29/Oct/2024:08:32:45.901162398 -0400] - ERR - bdb_restore - Failed to init database
[29/Oct/2024:08:32:45.907390365 -0400] - ERR - ldbm_back_archive2ldbm - Failed to read backup file set. Either the directory specified doesn't exist, or it exists but doesn't contain a valid backup set, or file permissions prevent the server reading the backup set.  error=-30973 (Unexpected dbimpl error code)

[progier389]

A bit surprising as the described test looks very similar to tests/suites/backups/backup_test.py::test_replication nightly CI test.
One of the difference is the restart after the backup. It may creates a new txn log files that is not removed during the restore and cause trouble ... ==> restore should remove the environment files (txn log included) before copying the restored files

[mreynolds389]

A bit surprising as the described test looks very similar to tests/suites/backups/backup_test.py::test_replication nightly CI test. One of the difference is the restart after the backup. It may creates a new txn log files that is not removed during the restore and cause trouble ... ==> restore should remove the environment files (txn log included) before copying the restored files

Yeah I was very surprised as well, but I tried it over and over again with fresh installs and the restore always failed. I don't know if replication played a part or not.

[progier389]

I suspect that it is the issue that Kazushige Yoneyama investigated and discussed in ldap-devel-list@redhat.com:
If that is the case:

• removing the db env files (especially the log files) before the restore will work-around the issue
• replicatiom/cleanruv is not involved but restarting the server creates a new txn log file that should be removed during the restore (but it is not and we ends up mixing up txn log files of the restored database and the one of the last start)

[progier389]

Hum, I tried to reproduce with following test case but the test always PASS, do you have an idea of what may differ with your test ?

def test_issue_6386(topo_m2):
    S1 = topo_m2.ms["supplier1"]
    S2 = topo_m2.ms["supplier2"]
    repl = ReplicationManager(DEFAULT_SUFFIX)
    agmts = Agreements(S1).list()

    with tempfile.TemporaryDirectory(dir=S1.ds_paths.backup_dir) as backup_dir:
        # repl.wait_for_replication perform some changes and wait until they get replicated
        repl.wait_for_replication(S2, S1)
        repl.wait_for_replication(S1, S2)
        S1.stop()
        assert S1.db2bak(backup_dir)
        S1.start()
        for agmt in agmts:
            agmt.pause()
        S2.stop()
        S1.tasks.cleanAllRUV(suffix=DEFAULT_SUFFIX, replicaid='2',
                             force=True, args={TASK_WAIT: True})

        S1.stop()
        assert S1.bak2db(backup_dir)
        S1.start()
        S2.start()
        repl.wait_for_replication(S2, S1)
        for agmt in agmts:
            agmt.resume()
        repl.wait_for_replication(S1, S2)

[mreynolds389]

Hum, I tried to reproduce with following test case but the test always PASS, do you have an idea of what may differ with your test ?

I was using bdb

[progier389]

So do I:
[13/Nov/2024:17:04:55.787672040 +0100] - INFO - bdb_restore - Restoring file 1 (/home/progier/sb/i6386/tst/ci-install/var/lib/dirsrv/slapd-supplier1/db/DBVERSION)

[mreynolds389]

So do I: [13/Nov/2024:17:04:55.787672040 +0100] - INFO - bdb_restore - Restoring file 1 (/home/progier/sb/i6386/tst/ci-install/var/lib/dirsrv/slapd-supplier1/db/DBVERSION)

Just checking. Well I can not reproduce it on a fresh install. I was originally working with a very large changelog at the time, and the error was related to a txn log. I'll have to try that setup again and get back to you...

[mreynolds389]

So do I: [13/Nov/2024:17:04:55.787672040 +0100] - INFO - bdb_restore - Restoring file 1 (/home/progier/sb/i6386/tst/ci-install/var/lib/dirsrv/slapd-supplier1/db/DBVERSION)

Just checking. Well I can not reproduce it on a fresh install. I was originally working with a very large changelog at the time, and the error was related to a txn log. I'll have to try that setup again and get back to you...

Hmmm previously I did say I was able to reproduce it with a fresh install. Perhaps there was something off in my environment at the time? I recently installed OS updates and rebooted, but who knows. I guess lets close this for now...

[progier389]

My suspicion is than we need to have several txn log files to trigger the bug and big changelog and the changelog purge triggered by cleanruv may generate lots and db writes and creates new db log files.
I will try to run ldctlt before restoring the db to see if I reproduce a similar error ...

[mreynolds389]

My suspicion is than we need to have several txn log files to trigger the bug and big changelog and the changelog purge triggered by cleanruv may generate lots and db writes and creates new db log files. I will try to run ldctlt before restoring the db to see if I reproduce a similar error ...

I do have a FS backup that does show what you are suspecting:

mareynol@fedora:~/customer/backup/slapd-localhost/db$ sudo ls -l 
total 30388
-rw-------. 1 dirsrv dirsrv       52 Oct 30 15:32 guardian
-rw-------. 1 dirsrv dirsrv 10485760 Oct 28 15:40 log.0000000084
-rw-------. 1 dirsrv dirsrv 10485760 Oct 29 08:32 log.0000000431
-rw-------. 1 dirsrv dirsrv 10485760 Oct 30 15:32 log.0000002211
drwx------. 1 dirsrv dirsrv      540 Oct 29 13:30 userroot

mareynol@fedora:~/customer/backup/slapd-localhost/db$ sudo ls -l userroot/
total 4619332
-rw-------. 1 dirsrv dirsrv      16384 Oct 29 08:32 aci.db
-rw-------. 1 dirsrv dirsrv     524288 Oct 30 15:32 ancestorid.db
-rw-------. 1 dirsrv dirsrv   46874624 Oct 30 15:32 cn.db
-rw-------. 1 dirsrv dirsrv         51 Oct 30 01:40 DBVERSION
-rw-------. 1 dirsrv dirsrv  115851264 Oct 30 15:32 entryrdn.db
-rw-------. 1 dirsrv dirsrv    4702208 Oct 30 15:32 entryUUID.db
-rw-------. 1 dirsrv dirsrv      16384 Oct 29 08:32 gidnumber.db
-rw-------. 1 dirsrv dirsrv   23494656 Oct 30 15:32 givenName.db
-rw-------. 1 dirsrv dirsrv 1420509184 Oct 30 15:32 id2entry.db
-rw-------. 1 dirsrv dirsrv   20520960 Oct 30 15:32 mail.db
-rw-------. 1 dirsrv dirsrv    5734400 Oct 30 08:47 nscpEntryDN.db
-rw-------. 1 dirsrv dirsrv      16384 Oct 29 13:30 nsds5ReplConflict.db
-rw-------. 1 dirsrv dirsrv    6094848 Oct 30 08:47 nsTombstoneCSN.db
-rw-------. 1 dirsrv dirsrv   17801216 Oct 30 15:32 nsuniqueid.db
-rw-------. 1 dirsrv dirsrv      16384 Oct 30 15:32 numsubordinates.db
-rw-------. 1 dirsrv dirsrv    3637248 Oct 30 15:32 objectclass.db
-rw-------. 1 dirsrv dirsrv    1769472 Oct 30 15:32 parentid.db
-rw-------. 1 dirsrv dirsrv 3021856768 Oct 30 15:32 replication_changelog.db
-rw-------. 1 dirsrv dirsrv   23527424 Oct 30 15:32 sn.db
-rw-------. 1 dirsrv dirsrv   15589376 Oct 30 15:32 telephoneNumber.db
-rw-------. 1 dirsrv dirsrv    1622016 Oct 30 15:32 uid.db
-rw-------. 1 dirsrv dirsrv      16384 Oct 29 08:32 uidnumber.db

And this backup fails with:

[14/Nov/2024:07:37:02.271316524 -0500] - INFO - bdb_restore - Restoring file 27 (/var/lib/dirsrv/slapd-localhost/db/log.0000002211)
[14/Nov/2024:07:37:02.281866765 -0500] - INFO - bdb_copyfile - Copying /var/lib/dirsrv/slapd-localhost/bak/mark5/log.0000002211 to /var/lib/dirsrv/slapd-localhost/db/log.0000002211
[14/Nov/2024:07:37:02.301802063 -0500] - INFO - bdb_restore - Restoring file 28 (/dev/shm/slapd-localhost/guardian)
[14/Nov/2024:07:37:02.311674613 -0500] - INFO - bdb_copyfile - Copying /var/lib/dirsrv/slapd-localhost/bak/mark5/guardian to /dev/shm/slapd-localhost/guardian
[14/Nov/2024:07:37:03.030270729 -0500] - ERR - libdb - BDB1522 Log file corrupt at LSN: [1][399915]
[14/Nov/2024:07:37:03.050327605 -0500] - ERR - libdb - BDB0061 PANIC: Invalid argument
[14/Nov/2024:07:37:03.091108970 -0500] - ERR - libdb - BDB1546 unable to join the environment
[14/Nov/2024:07:37:03.213620122 -0500] - CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30973: Unexpected dbimpl error code
[14/Nov/2024:07:37:03.224575151 -0500] - CRIT - bdb_start - Please make sure there is enough disk space for dbcache (1610612736 bytes) and db region files
[14/Nov/2024:07:37:03.230758942 -0500] - ERR - bdb_restore - Failed to init database
[14/Nov/2024:07:37:03.236926301 -0500] - ERR - ldbm_back_archive2ldbm - Failed to read backup file set. Either the directory specified doesn't exist, or it exists but doesn't contain a valid backup set, or file permissions prevent the server reading the backup set.  error=-30973 (Unexpected dbimpl error code)