389-ds-base

#51101 Ticket - 49562 integrate changelog database to main database
Closed by spichugi. Opened by lkrispen.
lkrispen/389-ds-base t49562  into  master

Download 51101.patch

PHASE 2 of backend redesign:
http://www.port389.org/docs/389ds/design/integrate-changelog-database-and-backend-database.html

this PR contains one change to tests, I wanted to send a separate PR for test modifications, but I missed this.

IPA installation failed at the first step.

Configuring directory server (dirsrv). Estimated time: 30 seconds
  [1/44]: creating directory server instance

[19/May/2020:15:59:02.246758965 -0400] - INFO - main - 389-Directory/1.4.4.2.20200519gitd04922cd1 B2020.140.1532 starting up
[19/May/2020:15:59:02.249503865 -0400] - INFO - main - Setting the maximum file descriptor limit to: 524288
[19/May/2020:15:59:03.035299779 -0400] - INFO - PBKDF2_SHA256 - Based on CPU performance, chose 2048 rounds
[19/May/2020:15:59:03.041956473 -0400] - INFO - bdb_config_upgrade_dse_info - create config entry from old config
[19/May/2020:15:59:03.048720725 -0400] - NOTICE - ldbm_back_start - found 2026512k physical memory
[19/May/2020:15:59:03.052037325 -0400] - NOTICE - ldbm_back_start - found 1644552k available
[19/May/2020:15:59:03.054866651 -0400] - NOTICE - ldbm_back_start - cache autosizing: db cache: 50662k
[19/May/2020:15:59:03.058057186 -0400] - NOTICE - ldbm_back_start - total cache size: 41502965 B; 
[19/May/2020:15:59:03.245540188 -0400] - ERR - NSMMReplicationPlugin - changelog program - _cl5AppInit - Failed to fetch backend dbenv
[19/May/2020:15:59:03.250576933 -0400] - ERR - NSMMReplicationPlugin - changelog program - cl5Open - Failed to open changelog
[19/May/2020:15:59:03.253521152 -0400] - ERR - NSMMReplicationPlugin - changelog program - changelog5_init: failed to start changelog
[19/May/2020:15:59:03.256291947 -0400] - ERR - plugin_dependency_startall - Failed to start object plugin Multimaster Replication Plugin
[19/May/2020:15:59:03.260906540 -0400] - ERR - NSMMReplicationPlugin - changelog program - _cl5AppInit - Failed to fetch backend dbenv
[19/May/2020:15:59:03.263982514 -0400] - ERR - NSMMReplicationPlugin - changelog program - cl5Open - Failed to open changelog
[19/May/2020:15:59:03.267197451 -0400] - ERR - NSMMReplicationPlugin - changelog program - changelog5_init: failed to start changelog
[19/May/2020:15:59:03.269771218 -0400] - ERR - plugin_dependency_startall - Failed to start object plugin Multimaster Replication Plugin
[19/May/2020:15:59:03.272519552 -0400] - ERR - plugin_dependency_startall - Failed to resolve plugin dependencies
[19/May/2020:15:59:03.275565238 -0400] - ERR - plugin_dependency_startall - object plugin Multimaster Replication Plugin is not started
[19/May/2020:15:59:03.278781722 -0400] - INFO - bdb_pre_close - Waiting for 4 database threads to stop
[19/May/2020:15:59:05.688752019 -0400] - INFO - bdb_pre_close - All database threads now stopped

Our tests:

 27 failed, 1361 passed, 63 skipped, 14 xfailed, 8 xpassed, 2201 warnings, 215 error in 4700.43 seconds

Most of these errors are:

E         ldap.UNWILLING_TO_PERFORM: {'desc': 'Server is unwilling to perform', 'info': 'Changelog configuration is part of the backend configuration'}

in any tests that try to use a topology with replication, such as:

dirsrvtests/tests/suites/acl/acl_test.py
dirsrvtests/tests/suites/automember_plugin/basic_test.py
dirsrvtests/tests/suites/config/config_test.py
dirsrvtests/tests/suites/ds_tools/replcheck_test.py
dirsrvtests/tests/suites/fourwaymmr/fourwaymmr_test.py
dirsrvtests/tests/suites/fractional/fractional_test.py
dirsrvtests/tests/suites/mapping_tree/
dirsrvtests/tests/suites/memberof_plugin/regression_test.py
dirsrvtests/tests/suites/replication/acceptance_test.py
dirsrvtests/tests/suites/replication/cascading_test.py
dirsrvtests/tests/suites/replication/changelog_trimming_test.py
dirsrvtests/tests/suites/replication/cleanallruv_test.py

It fails in _ensure_changelog() https://pagure.io/389-ds-base/blob/master/f/src/lib389/lib389/replica.py#_1837
when it tries to add this entry:

dn: cn=changelog5,cn=config
cn: changelog5
nsslapd-changelogdir: /var/lib/dirsrv/slapd-master1/changelogdb
objectclass: top
objectclass: nsChangelogConfig

Thanks for this fast testing.

Regarding the failing tests I have another PR coming, commenting out _ensure_changelog, since izt will be there once a replica is enabled. and some changes forr config to access the correct config entry - so I zthink we will get these fixed.

About IPA it looks a bit strange, what do they do differently at startup ? And I thought for the first master they do not even enable replication.

I reproduced the IPA failure. If I remove all backends and replicas from the dse.ldif I do get the same error messages

Regarding the failing tests I have another PR coming, commenting out _ensure_changelog, since izt will be there once a replica is enabled. and some changes forr config to access the correct config entry - so I zthink we will get these fixed.

We still need _ensure_changelog on older versions, so I think we should use ds_is_older to determine if it's needed or not. Or handle ldap.UNWILLING_TO_PERFORM gracefully.

About IPA it looks a bit strange, what do they do differently at startup ? And I thought for the first master they do not even enable replication.

It fails at instance creation, they have a backend with no entries:
https://github.com/freeipa/freeipa/blob/3dd5053cdd55adf6888ef38bfc927fc255bd7019/ipaserver/install/dsinstance.py#L550

A standalone reproducer is dscreate from-file tmp.inf where tmp.inf has the following content:

[general]
[slapd]
[backend-userroot]
suffix = dc=example,dc=com
Edited by vashirov

About _ensure_changelog: I thought we would use the tests corresponding to a version.

If new tests should work on older versions, you're right we could use ds_is_older (than what ?)
or accept unwilling to perform as return code
or we could not return UNWILLING_TO_PERFORM and just ignore the ADD request.

I think the IPA install will in a later stage also run into this problem - maybe ignoring the add and just logging a message would do.

About starting with an empty instance, too bad we notice this only now, I didn't run into it in our tests.
I understand what is going on, in the previous version cl5Open was triggered by the existence of a changelog dir, we don't have it anymore, but withoz backends it fails.
I am not yet sure how to fix it, either make it succeed without backends or detect the absence of backends and delay it, it will take a bit.

And ignoring the add of changelog5 entry will probably not work. It is a callback making the decision - and if it accepts the ADD, the entry will be added.
So IPA will have to learn

About _ensure_changelog: I thought we would use the tests corresponding to a version.

We use lib389 and tests from master to run across all versions.

If new tests should work on older versions, you're right we could use ds_is_older (than what ?)
or accept unwilling to perform as return code
or we could not return UNWILLING_TO_PERFORM and just ignore the ADD request.

With this tests don't error out immediately:

diff --git a/src/lib389/lib389/replica.py b/src/lib389/lib389/replica.py
index e3fc7fe1f..85a8387f5 100644
--- a/src/lib389/lib389/replica.py
+++ b/src/lib389/lib389/replica.py
@@ -1844,7 +1844,7 @@ class ReplicationManager(object):
                 'cn': 'changelog5',
                 'nsslapd-changelogdir': instance.get_changelog_dir()
             })
-        except ldap.ALREADY_EXISTS:
+        except (ldap.UNWILLING_TO_PERFORM, ldap.ALREADY_EXISTS):
             pass
     def _inst_to_agreement_name(self, to_instance):

dirsrvtests/tests/suites/replication/acceptance_test.py::test_csngen_task got stuck in _csngen_gen_tester_main, it continued to generate csns after server was 'stopped':

[20/May/2020:11:39:20.884434094 +0000] - INFO - _csngen_gen_tester_main - generate csn 5ec51747001100ff0000
[20/May/2020:11:39:20.888656879 +0000] - INFO - _csngen_gen_tester_main - generate csn 5ec51747001200ff0000
[20/May/2020:11:39:20.893365667 +0000] - INFO - _csngen_gen_tester_main - generate csn 5ec51747001300ff0000
[20/May/2020:11:39:22.090851023 +0000] - INFO - op_thread_cleanup - slapd shutting down - signaling operation threads - op stack size 2 max work q size 2 max work q stack si
ze 2
[20/May/2020:11:39:22.104761604 +0000] - INFO - slapd_daemon - slapd shutting down - closing down internal subsystems and plugins
[20/May/2020:11:39:22.255460481 +0000] - INFO - bdb_pre_close - Waiting for 4 database threads to stop
[20/May/2020:11:39:23.039438782 +0000] - INFO - bdb_pre_close - All database threads now stopped
[20/May/2020:11:39:23.111691394 +0000] - INFO - ldbm_back_instance_set_destructor - Set of instances destroyed
[20/May/2020:11:39:23.116110106 +0000] - INFO - connection_post_shutdown_cleanup - slapd shutting down - freed 2 work q stack objects - freed 2 op stack objects
[20/May/2020:11:39:23.120443195 +0000] - INFO - main - slapd stopped.
[20/May/2020:11:39:30.812292808 +0000] - INFO - _csngen_gen_tester_main - generate csn 5ec51751000000ff0000
[20/May/2020:11:39:30.823623581 +0000] - INFO - _csngen_gen_tester_main - generate csn 5ec51751000100ff0000
[20/May/2020:11:39:30.828504706 +0000] - INFO - _csngen_gen_tester_main - generate csn 5ec51751000200ff0000

About starting with an empty instance, too bad we notice this only now, I didn't run into it in our tests.

It's because we use perl installer by default, and it doesn't create a backend without entries :(
Only recently @bsmejkal added in #50903 ability to run tests with python installer even if the rpm was built with perl tools and without changing the defaults.inf file: by using PYINSTALL env variable.

the test_csngen_task should not be affected by the changelog changes.
In my tests with master and with my patch the test soemtimes failed and soemtimes passed - it didn't look stable.

Ah, ok. It was passing for me lately.
I'm rerunning the tests with the patch above to see what fails even if we handle ldap.UNWILLING_TO_PERFORM.

I created a separate PR 51104 for my changes to the tests, this is just a "hint" what needs to be done.

1 new commit added

  • patch to do cleanup and fix problems found during review

I found it used in _cl5WriteOperationTxn but not during upgrade. Could you change the comment ?
My understanding is that it takes the path from ldbminfo, I would prefer that the comment mention this.

I found it used in _cl5WriteOperationTxn but not during upgrade. Could you change the comment ?
My understanding is that it takes the path from ldbminfo, I would prefer that the comment mention this.

it is not set at all, it is used in one leftover message, I will change the message and remove it completely, I am not even sure if the diskfull check makes sens at this place (believe it is from the timen when cl was more independent)

Would prefer that the name uses a define 'changelog' and LDBM_SUFFIX

Would prefer that the name uses a define 'changelog' and LDBM_SUFFIX

Would prefer that the name uses a define 'changelog' and LDBM_SUFFIX

Would prefer that the name uses a define 'changelog' and LDBM_SUFFIX

Would prefer that the name uses a define 'changelog' and LDBM_SUFFIX

I think this call to retrieve the config is now useless

It looks cl5Close, cl5ImportLDIF and cl5Open are using s_cl5Desc. Is it still accessing the changelog5 old structures ?

It looks cl5Close, cl5ImportLDIF and cl5Open are using s_cl5Desc. Is it still accessing the changelog5 old structures ?

there are still a few global vars in s:cl5Desc (like openmode: export or normal, dbenv: same for all and used in txns, but could go away,..) I think this is not as clean yet as could be

I think this call to retrieve the config is now useless

you are right, but looking at this part of the code there is more to do :-)
the changelog import is surrounded by cl5Close and cl5Open - but these calls close and open ALL changelogs, only the one to be imported should be managed

@lkrispen , I think only cosmetic changes should be add to this patch. More important changes should be done under separated ticket. IMHO you may create a ticket explaining what need to be changed in that corner case code (ldif2cl) and details how to verify.

IPA installation is successful (only single instance was tested)
With #51104 tests pass except dirsrvtests/tests/suites/replication/changelog_test.py::test_verify_changelog_online_backup
ns-slapd crashes when test tries to create a user right after backup is restored:

#0  0x00007fb76f80f3e0 in _cl5WriteOperationTxn (cldb=cldb@entry=0x7fb6a261dd20, op=op@entry=0x7fb76fa176f8, txn=txn@entry=0x7fb6a5645180)
    at ldap/servers/plugins/replication/cl5_api.c:3704
#1  0x00007fb76f8109f3 in cl5WriteOperationTxn (txn=0x7fb6a5645180, op=0x7fb76fa176f8, cldb=0x7fb6a261dd20) at ldap/servers/plugins/replication/cl5_api.c:926
#2  cl5WriteOperationTxn (cldb=cldb@entry=0x7fb6a261dd20, op=0x7fb76fa176f8, txn=0x7fb6a5645180) at ldap/servers/plugins/replication/cl5_api.c:902
#3  0x00007fb76f82e629 in write_changelog_and_ruv (pb=pb@entry=0x7fb6a5600000) at ldap/servers/plugins/replication/repl5_plugins.c:1068
#4  0x00007fb76f82f8c2 in multimaster_be_betxnpostop_add (pb=pb@entry=0x7fb6a5600000) at ldap/servers/plugins/replication/repl5_plugins.c:851
#5  0x00007fb76f82f988 in multimaster_mmr_postop (pb=0x7fb6a5600000, flags=560) at ldap/servers/plugins/replication/repl5_plugins.c:612
#6  0x00007fb77392283d in plugin_call_mmr_plugin_postop (pb=pb@entry=0x7fb6a5600000, e=e@entry=0x0, flags=flags@entry=560) at ldap/servers/slapd/plugin_mmr.c:65
#7  0x00007fb76f9011f6 in ldbm_back_add (pb=0x7fb6a5600000) at ldap/servers/slapd/back-ldbm/ldbm_add.c:1229
#8  0x00007fb7738bc0f1 in op_shared_add (pb=pb@entry=0x7fb6a5600000) at ldap/servers/slapd/add.c:689
#9  0x00007fb7738bd0b5 in do_add (pb=pb@entry=0x7fb6a5600000) at ldap/servers/slapd/add.c:236
#10 0x000055834744c96a in connection_dispatch_operation (pb=0x7fb6a5600000, op=0x7fb76fa17600, conn=0x7fb6e88b1208) at ldap/servers/slapd/connection.c:609
#11 connection_threadmain () at ldap/servers/slapd/connection.c:1753
#12 0x00007fb77362e4b4 in _pt_root () at /lib64/libnspr4.so
#13 0x00007fb7735c2432 in start_thread () at /lib64/libpthread.so.0
#14 0x00007fb7734379d3 in clone () at /lib64/libc.so.6

As for #51104, I will modify it so that the tests will pass on older versions too.

initialize config_entry = {0};

Need to test 'rc' or 'config_entry.ce' in case the internal search fails, 'ce' is NULL and it will likely crash

/changelog_test.py::test_verify_changelog_online_backup

ns-slapd crashes when test tries to create a user right after backup is restored:

This is weird. I had this crash and spent a lot of time to fix it, and fixed it :-)
But looks like one of the cleanups later broke it again

At this point cldb is not fully initialized (miss cllock, clCVar, maxAge, crypto..). Any reason to set it so early in cldb_SetReplicaDB rather than the end ?

/changelog_test.py::test_verify_changelog_online_backup

ns-slapd crashes when test tries to create a user right after backup is restored:

This is weird. I had this crash and spent a lot of time to fix it, and fixed it :-)
But looks like one of the cleanups later broke it again

It was the second commit in this PR, I did no full test after the IPA changes. Unfortunately I did some more changes on the fly :-(

/changelog_test.py::test_verify_changelog_online_backup

ns-slapd crashes when test tries to create a user right after backup is restored:

This is weird. I had this crash and spent a lot of time to fix it, and fixed it :-)
But looks like one of the cleanups later broke it again

It was the second commit in this PR, I did no full test after the IPA changes. Unfortunately I did some more changes on the fly :-(

At this point cldb is not fully initialized (miss cllock, clCVar, maxAge, crypto..). Any reason to set it so early in cldb_SetReplicaDB rather than the end ?

good point. At the end is too late, since cl5ConfigTrimming gets the replica passed and uses cldb, but somwhere in between - would require testing again

The replication agreement uses its iterator to access the CL, so it should use the replica cldb. What prevents cldb_UnSetReplicaDB to clear it under the replication agreement ?

The replication agreement uses its iterator to access the CL, so it should use the replica cldb. What prevents cldb_UnSetReplicaDB to clear it under the replication agreement ?

that replication agreements need to be stopped before the replica can be disabled or shutdown

Not clear to me. setting this flag prevents to delete the changelog file in cldb_UnSetReplicaDB.
But when recreating the CL (bad RUV) should not we remove and recreat a file ?

1 new commit added

  • Additional patch for problems raised during review

Not clear to me. setting this flag prevents to delete the changelog file in cldb_UnSetReplicaDB.
But when recreating the CL (bad RUV) should not we remove and recreat a file ?

I think you are right, the flag should trigger the removal and not prevent it, it was probably a late merge of cldb_UnSetReplicaDB and cl5DeleteDBSync which was to quick.
So right now the changelog would be cleared at each shutdown ??
To be investigated, but I'm afraid by someone else.

As procedure to verify I would suggest: change the condition and rerun the test, do dbscans of teh cl after shutdown

I have added a new commit which adresses the failing test reported by Viktor and several issues reported by Thierry in this review,

And I opened a bunch of tickets for known issues not to be included in this PR

regarding DB_FILE_DONE a quick test shows that the cl is retained after shutdown, but the recreation after online init could be impacted.

Few more tests:
ipa server installation succeeds. ipa replica installation fails:

Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 423, in __setup_replica
    repl.setup_promote_replication(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 1847, in setup_promote_replication
    self.basic_replication_setup(self.conn, l_id, self.repl_man_dn, None)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 1154, in basic_replication_setup
    self.setup_changelog(conn)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 586, in setup_changelog
    conn.add_entry(entry)
  File "/usr/lib/python3.8/site-packages/ipapython/ipaldap.py", line 1648, in add_entry
    self.conn.add_s(str(entry.dn), list(attrs.items()))
  File "/usr/lib64/python3.8/contextlib.py", line 131, in __exit__
    self.gen.throw(type, value, traceback)
  File "/usr/lib/python3.8/site-packages/ipapython/ipaldap.py", line 1138, in error_handler
    raise errors.DatabaseError(desc=desc, info=info)
ipalib.errors.DatabaseError: Server is unwilling to perform: Changelog configuration is part of the backend configuration

It can be fixed in IPA code by handling unwilling to perform exception here: https://github.com/freeipa/freeipa/blob/a18d406b5631f80134e202ae3310580683937f92/ipaserver/install/replication.py#L587

-        except errors.DuplicateEntry:
+        except (errors.DuplicateEntry, errors.DatabaseError):

But I'm not sure it's a good idea in case of a real unwilling to perform issue during the changelog setup.
Or maybe do a no-op on DS side instead of returning unwilling to perform?

As for dirsrvtests: 

FAILED dirsrvtests/tests/suites/replication/changelog_test.py::test_dsconf_dump_changelog_files_removed - FileNotFoundError: [Errno 2] No such file or directory: '/var/lib/dirsrv/slapd-master1/changelogdb'

But that's a minor issue, I will submit changes for #51104.

We will probably run into the same issue with our CLI tools when enabling replication as it creates the changelog by default.

Yes, this can be fixed in lib389 as I mentioned in https://pagure.io/389-ds-base/pull-request/51101#comment-120457

If it is not acceptable for applications, like IPA, to be changed, we could follow a path discussed in the handover meetings: In changelog5_config_add() do not return UNWILLING_TO_PERFORM but LDAP_SUCCESS. This will accept the adding of the entry but do nothing with it, just ignore it.

The potential problem is that the existence of cn=changelog5 triggers the auto upgrade cl migration process. If the dir specified in this config entry does no longer exist this could be used to stop autoupgrade and work.

IPA uses lib389, fixing it in the library would be preferred as then both DS and ipa tools would have the same behavior
Edited by abbra

This patch was merged with another one. See https://pagure.io/389-ds-base/issue/49562#comment-671829
It is now pushed upstream, closing the PR

Pull-Request has been closed by tbordaz

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/4154

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
Metadata
None
No Tags
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.