search

389ds / 389-ds-base

The enterprise-class Open Source LDAP server for Linux
https://www.port389.org/
Other
211 stars 93 forks source link

SyncRepl plugin provides a wrong cookie #4243

Closed 389-ds-bot closed 3 years ago

389-ds-bot commented 4 years ago

Cloned from Pagure issue: https://pagure.io/389-ds-base/issue/51190

Issue Description

Within a freeipa environment, the syncrepl plugin sometimes provides a wrong cookie 4294967295 and triggers syncrepl_entry callback for a change that should not.

Package Version and Platform

Fedora 32 with: 389-ds-base-1.4.3.10-1.fc32.x86_64 freeipa-server-4.8.7-1.fc32.x86_64

Steps to reproduce

EOF

systemctl restart dirsrv@IPA-TEST.service


Launch the attached python script to create a refreshAndPersist query:

python test_syncrepl.py

In another window, add a new ipa user:

echo $PASSWORD | kinit admin ipa user-add testuser --first test --last user


#### Actual results
The script displays the callbacks triggered by syncrepl:

syncrepl_entry dn uid=testuser,cn=users,cn=accounts,dc=ipa,dc=test Set cookie: master.ipa.test:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))57 syncrepl_entry dn uid=testuser,cn=users,cn=accounts,dc=ipa,dc=test Set cookie: master.ipa.test:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))57 syncrepl_entry dn uid=testuser,cn=users,cn=accounts,dc=ipa,dc=test Set cookie: master.ipa.test:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))57 syncrepl_entry dn uid=testuser,cn=users,cn=accounts,dc=ipa,dc=test Set cookie: master.ipa.test:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))59 syncrepl_entry dn cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test Set cookie: master.ipa.test:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))4294967295


#### Expected results

The last cookie with changenumber 4294967295 is invalid. It looks like it corresponds to the creation of IPA private group for the user, that has objectclasses `top`, `mepManagedEntry`, `ipaobject` and `posixgroup`.
I would not expect the private group creation to trigger the syncrepl callback `syncrepl_entry`, as it does not contain the objectclass groupofnames that is specified in the filterstr.

Script:

cat test_syncrepl.py

import ldap import ldapurl from ldap.syncrepl import SyncreplConsumer from ldap.ldapobject import ReconnectLDAPObject import os import pwd import sys

from ipalib import api from ipaplatform.paths import paths from ipapython.dn import DN

class TestSyncer(ReconnectLDAPObject, SyncreplConsumer): def init(self, *args, *kwargs): self.cookie = None ldap.ldapobject.ReconnectLDAPObject.init(self, args, **kwargs)

def syncrepl_set_cookie(self, cookie):
    self.cookie = cookie
    print("Set cookie: ", cookie)

def syncrepl_get_cookie(self):
    print("Get cookie: ", self.cookie)
    return self.cookie

def syncrepl_present(self, uuids, refreshDeletes=False):
    print("syncrepl_present uuids ", uuids, refreshDeletes)

def syncrepl_delete(self, uuids):
    print("syncrepl_delete uuids ", uuids)

def syncrepl_entry(self, dn, attrs, uuid):
    print("syncrepl_entry dn ", dn)

def syncrepl_refreshdone(self):
    print("syncrepl_refreshdone")

if len(sys.argv) >= 2: cookie = sys.argv[1] else: cookie = None

api.bootstrap( in_server=True, context='test_syncrepl', confdir=paths.ETC_IPA, log=None ) api.finalize()

basedn = DN(api.env.container_accounts, api.env.basedn) ldap_url = ldapurl.LDAPUrl(api.env.ldap_uri) ldap_url.dn = str(basedn) ldap_url.scope = ldapurl.LDAP_SCOPE_SUBTREE ldap_url.filterstr = '(|(objectClass=groupofnames)(objectClass=person))' ldap_url.attrs = [ 'objectclass', 'cn', 'displayname', 'gidnumber', 'givenname', 'homedirectory', 'ipaexternalmember', 'ipantsecurityidentifier', 'ipauniqueid', 'krbcanonicalname', 'krbprincipalname', 'mail', 'member', 'memberof', 'sn', 'uid', 'uidnumber', ]

ldap_connection = TestSyncer(ldap_url.initializeUrl()) user_name = pwd.getpwuid(os.geteuid()).pw_name auth_tokens = ldap.sasl.external(user_name) ldap_connection.sasl_interactive_bind_s('', auth_tokens)

ldap_search = ldap_connection.syncrepl_search( ldap_url.dn, ldap_url.scope, mode='refreshAndPersist', attrlist=ldap_url.attrs, filterstr=ldap_url.filterstr, cookie=cookie )

try: while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search): pass except (ldap.SERVER_DOWN, ldap.CONNECT_ERROR) as e: print('syncrepl_poll: LDAP error (%s)', e) sys.exit(1)

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-06-25 17:45:18

Metadata Update from @mreynolds389:

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-06-29 16:39:29

Metadata Update from @mreynolds389:

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-06-29 16:39:30

Issue linked to Bugzilla: Bug 1851978

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-06-30 03:24:45

This does seem suspect, 4294967295 is 0xffffffff, so this could be an underflow or something not being return checked properly.

389-ds-bot commented 4 years ago

Comment from elkris at 2020-06-30 08:33:12

This does seem suspect, 4294967295 is 0xffffffff, so this could be an underflow or something not being return checked properly.

In a similar case the reason was that the change returned was not written to the retro changelog and the changenumber used in the cookie was not found.

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-01 21:44:02

Metadata Update from @mreynolds389:

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-02 00:36:41

The lazy fix is to prevent a changenumber of 0xffff_ffff from being sent and skipping it, but I'm really wondering how the change got in there in the first place ...

389-ds-bot commented 4 years ago

Comment from elkris at 2020-07-02 11:04:03

The lazy fix is to prevent a changenumber of 0xffff_ffff from being sent and skipping it,

then the client would miss a change, not better thana bad cookie

but I'm really wondering how the change got in there in the first place ...

there are a couple of scenarios, either the changelog scope does not cover the change(but I think florence handled it) or the change is by a plugin in a state where the sync repl plugin doesn't catch it.

Since there is a test case, I think the only way is to debug when the change with the bad cookie is created, if it goes to the retro changelog (or why not) and when the sync repl plugin handles it

389-ds-bot commented 4 years ago

Comment from frenaud at 2020-07-02 11:30:15

I would like to point out that in my reproducer, the filter is'(|(objectClass=groupofnames)(objectClass=person))' and the faulty change happens on an entry which does not correspond to this filter (the private group entry has objectclasses top, mepManagedEntry, ipaobject and posixgroup but neither groupofnames nor person).

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-02 22:24:30

So we might have an issue with nested BE txn operations adn how the sync plugin calculates its changenumbers. When we get the changenumber and there are multiple entries matching the filter (&(changenumber>=90)(targetuniqueid=ba525001-bc9f11ea-816c867d-c7d8958b)) then we still only grab the first entry. This entry has the highest changenumber. In this IPA case this causes it to miss/skip over valid updates. If I change the code to find the oldest changenumber from that filter then it appears to fix everything and the client is returned the expected results.

diff --git a/ldap/servers/plugins/sync/sync_util.c b/ldap/servers/plugins/sync/sync_util.c
index 847a20df4..fae906e01 100644
--- a/ldap/servers/plugins/sync/sync_util.c
+++ b/ldap/servers/plugins/sync/sync_util.c
@@ -462,10 +462,12 @@ sync_cookie_get_change_number(int lastnr, const char *uniqueid)
     if (rv == LDAP_SUCCESS) {
         slapi_pblock_get(srch_pb, SLAPI_PLUGIN_INTOP_SEARCH_ENTRIES, &entries);
         if (entries && *entries) {
+            /* Use the last entry which has the oldest changenumber */
+            size_t i = 0;
             Slapi_Attr *attr;
             Slapi_Value *val;
-            cl_entry = *entries; /* only use teh first one */
-            slapi_entry_attr_find(cl_entry, CL_ATTR_CHANGENUMBER, &attr);
+            for (; entries[i]; i++);
+            slapi_entry_attr_find(entries[i-1], CL_ATTR_CHANGENUMBER, &attr);
             slapi_attr_first_value(attr, &val);
             newnr = sync_number2ulong((char *)slapi_value_get_string(val));
         }

But I have never really looked at this code before or sync repl for that matter. I do not know if this change could cause other problems. @elkris what are your thoughts?

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-03 01:22:06

So we might have an issue with nested BE txn operations adn how the sync plugin calculates its changenumbers. When we get the changenumber and there are multiple entries matching the filter (&(changenumber>=90)(targetuniqueid=ba525001-bc9f11ea-816c867d-c7d8958b)) then we still only grab the first entry. This entry has the highest changenumber. In this IPA case this causes it to miss/skip over valid updates. If I change the code to find the oldest changenumber from that filter then it appears to fix everything and the client is returned the expected results.

Wow, interesting find there!

Perhaps a better answer than swapping first/vs last is to get all the entries matching and apply the filter test instead.

Imagine say ... your syncrepl wanted all users + groups. In that case if you added a user, managed entries would add the group in the same betxn. With the current impl / your suggestion, could this mean that only one of the two entries are shipped?

Another scenario could be that the client wants only the groups, and in this change could it be possible the addition of the user would then mean we mistakenly send the user instead?

Anyway, I think it may be better to actually just say that for any change we get, given all entries in the changenum, we apply the clients request filter and send back those entries that match. That would cover us in any scenario that exists, rather than just this one.

Certainly a problem with this could be that the entry at the point in time in the change log "may not" have matched the filter, but the current entry state "does match" the filter. So my approach could also cause entries that in the future would match, but in the past "did not" to be sent.

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-03 02:14:33

Wow, interesting find there! Perhaps a better answer than swapping first/vs last is to get all the entries matching and apply the filter test instead.

Actually all the entries have been filtered tested. The problem is that with BE txn plugins is that we see updates like this:

So we send the user changes and set the next change number to 72, then we try send the changes for the group (changenumber 71), but we can not look backwards because we the filter uses changenumber>=72. This all happens in a loop in the sync code. So the fix I use always starts with the first changenumber from this sequence (change number 70).

Imagine say ... your syncrepl wanted all users + groups. In that case if you added a user, managed entries would add the group in the same betxn. With the current impl / your suggestion, could this mean that only one of the two entries are shipped?

Actually this test with IPA it does handle all the managed entry changes.

Another scenario could be that the client wants only the groups, and in this change could it be possible the addition of the user would then mean we mistakenly send the user instead?

That is what my orignal convcers was, but not advancing the changenumber until we are done with an entry you an entry be sent twice, etc? I do not see that hjappening in this case though, but I might not be testing it in the correct way.

Anyway, I think it may be better to actually just say that for any change we get, given all entries in the changenum, we apply the clients request filter and send back those entries that match.

The plugin is/was sending the correct entries (that was never a problem), I know @flo said it was but it's not. All the entries DO match the filter - so I think that was a red herring. All the entries in question have the objectclass groupofnames or person (See below). It was just that we were not using the correct filter to find them in the retro changelog.

So when I run Flo's test script I also print out all the attrs, so you can see how things change:

syncrepl_entry dn  uid=testuser10,cn=users,cn=accounts,dc=ipa,dc=test
attrs: {'objectclass': [b'top', b'person', b'organizationalperson', b'inetorgperson', b'inetuser', b'posixaccount', b'krbprincipalaux', b'krbticketpolicyaux', b'ipaobject', b'ipasshuser', b'ipaSshGroupOfPubKeys', b'mepOriginEntry'], 'cn': [b'test10 user10'], 'displayname': [b'test10 user10'], 'gidnumber': [b'1077800011'], 'givenname': [b'test10'], 'homedirectory': [b'/home/testuser10'], 'ipauniqueid': [b'bf50520a-bc9f-11ea-be54-2c27d719fbbf'], 'krbcanonicalname': [b'testuser10@IPA.TEST'], 'krbprincipalname': [b'testuser10@IPA.TEST'], 'mail': [b'testuser10@ipa.test'], 'sn': [b'user10'], 'uid': [b'testuser10'], 'uidnumber': [b'1077800011']}
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))90

syncrepl_entry dn  uid=testuser10,cn=users,cn=accounts,dc=ipa,dc=test
attrs: {'objectclass': [b'top', b'person', b'organizationalperson', b'inetorgperson', b'inetuser', b'posixaccount', b'krbprincipalaux', b'krbticketpolicyaux', b'ipaobject', b'ipasshuser', b'ipaSshGroupOfPubKeys', b'mepOriginEntry'], 'cn': [b'test10 user10'], 'displayname': [b'test10 user10'], 'gidnumber': [b'1077800011'], 'givenname': [b'test10'], 'homedirectory': [b'/home/testuser10'], 'ipauniqueid': [b'bf50520a-bc9f-11ea-be54-2c27d719fbbf'], 'krbcanonicalname': [b'testuser10@IPA.TEST'], 'krbprincipalname': [b'testuser10@IPA.TEST'], 'mail': [b'testuser10@ipa.test'], 'sn': [b'user10'], 'uid': [b'testuser10'], 'uidnumber': [b'1077800011']}
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))90

syncrepl_entry dn  uid=testuser10,cn=users,cn=accounts,dc=ipa,dc=test
attrs: {'objectclass': [b'top', b'person', b'organizationalperson', b'inetorgperson', b'inetuser', b'posixaccount', b'krbprincipalaux', b'krbticketpolicyaux', b'ipaobject', b'ipasshuser', b'ipaSshGroupOfPubKeys'], 'cn': [b'test10 user10'], 'displayname': [b'test10 user10'], 'gidnumber': [b'1077800011'], 'givenname': [b'test10'], 'homedirectory': [b'/home/testuser10'], 'ipauniqueid': [b'bf50520a-bc9f-11ea-be54-2c27d719fbbf'], 'krbcanonicalname': [b'testuser10@IPA.TEST'], 'krbprincipalname': [b'testuser10@IPA.TEST'], 'mail': [b'testuser10@ipa.test'], 'sn': [b'user10'], 'uid': [b'testuser10'], 'uidnumber': [b'1077800011']}
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))90

syncrepl_entry dn  uid=testuser10,cn=users,cn=accounts,dc=ipa,dc=test
attrs: {'objectclass': [b'top', b'person', b'organizationalperson', b'inetorgperson', b'inetuser', b'posixaccount', b'krbprincipalaux', b'krbticketpolicyaux', b'ipaobject', b'ipasshuser', b'ipaSshGroupOfPubKeys', b'mepOriginEntry'], 'cn': [b'test10 user10'], 'displayname': [b'test10 user10'], 'gidnumber': [b'1077800011'], 'givenname': [b'test10'], 'homedirectory': [b'/home/testuser10'], 'ipauniqueid': [b'bf50520a-bc9f-11ea-be54-2c27d719fbbf'], 'krbcanonicalname': [b'testuser10@IPA.TEST'], 'krbprincipalname': [b'testuser10@IPA.TEST'], 'mail': [b'testuser10@ipa.test'], 'memberof': [b'cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test'], 'sn': [b'user10'], 'uid': [b'testuser10'], 'uidnumber': [b'1077800011']}
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))90

syncrepl_entry dn  cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test
attrs: {'objectclass': [b'top', b'groupofnames', b'nestedgroup', b'ipausergroup', b'ipaobject'], 'cn': [b'ipausers'], 'ipauniqueid': [b'60316b78-bc6e-11ea-b985-2c27d719fbbf'], 'member': [b'uid=testuser,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser2,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser3,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser4,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser5,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser6,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser7,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser8,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser9,cn=users,cn=accounts,dc=ipa,dc=test', b'uid=testuser10,cn=users,cn=accounts,dc=ipa,dc=test']}
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))94

I did verify these results are consistent with and without my fix (except the last entry which is now correctly found in the retro changelog). if you look at the changes in the retro changelog you can see what each mod is doing and to what, etc.

But I agree this needs more testing, and we don't have any thorough sync repl tests yet. I will do a scratch build and ask IPA to run more tests with it for starters.

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-03 02:18:55

Wow, interesting find there! Perhaps a better answer than swapping first/vs last is to get all the entries matching and apply the filter test instead.

Actually all the entries have been filtered tested. The problem is that with BE txn plugins is that we see updates like this:

Add user - Change number 70 plugin creates group - Change number 71 plugin updates user again with memberOf - Change number 72

AHHHHHH oh yeah. That's a bit cursed hey. Sorry for misunderstanding the issue.

Would it be better for the change number not to increment until the txn is complete? Or could that cause other issues? We really just want the "final state" rather than the intermediate changes here I guess.

I did verify these results are consistent with and without my fix (except the last entry which is now correctly found in the retro changelog). if you look at the changes in the retro changelog you can see what each mod is doing and to what, etc. But I agree this needs more testing, and we don't have any thorough sync repl tests yet. I will do a scratch build and ask IPA to run more tests with it for starters.

It probably didn't help that python-ldaps' syncrepl module had some bugs in it. I started to write syncrepl tests as part of my entryuuid/syncrepl openldap changes so there is a start there on how to write these, it should be pretty easy to start adding more.

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-03 02:32:50

Wow, interesting find there! Perhaps a better answer than swapping first/vs last is to get all the entries matching and apply the filter test instead. Actually all the entries have been filtered tested. The problem is that with BE txn plugins is that we see updates like this: Add user - Change number 70 plugin creates group - Change number 71 plugin updates user again with memberOf - Change number 72

AHHHHHH oh yeah. That's a bit cursed hey. Sorry for misunderstanding the issue. Would it be better for the change number not to increment until the txn is complete? Or could that cause other issues? We really just want the "final state" rather than the intermediate changes here I guess.

Well once the sync plugin moves to the next entry it updates the "last changenumber". So it would "appear" that it is working correctly now.

I did verify these results are consistent with and without my fix (except the last entry which is now correctly found in the retro changelog). if you look at the changes in the retro changelog you can see what each mod is doing and to what, etc. But I agree this needs more testing, and we don't have any thorough sync repl tests yet. I will do a scratch build and ask IPA to run more tests with it for starters.

It probably didn't help that python-ldaps' syncrepl module had some bugs in it. I started to write syncrepl tests as part of my entryuuid/syncrepl openldap changes so there is a start there on how to write these, it should be pretty easy to start adding more.

Well @droideck is now a co-maintainer for upstream python-ldap, so maybe he can work on these bugs :-)

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-03 02:36:21

Wow, interesting find there! Perhaps a better answer than swapping first/vs last is to get all the entries matching and apply the filter test instead. Actually all the entries have been filtered tested. The problem is that with BE txn plugins is that we see updates like this: Add user - Change number 70 plugin creates group - Change number 71 plugin updates user again with memberOf - Change number 72 AHHHHHH oh yeah. That's a bit cursed hey. Sorry for misunderstanding the issue. Would it be better for the change number not to increment until the txn is complete? Or could that cause other issues? We really just want the "final state" rather than the intermediate changes here I guess.

Well once the sync plugin moves to the next entry it updates the "last changenumber". So it would "appear" that it is working correctly now.

I almost feel like an essay in the comments of this code is needed to explain how/why this works :| so that future team members know what's going on because it's really not obvious reading that code I think. Is that a reasonable request for a PR to have a pretty big comment section with how/why/what's going on?

Well @droideck is now a co-maintainer for upstream python-ldap, so maybe he can work on these bugs :-)

I already submitted fixes and they have been approved by @cheimes and merged :)

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-07-03 18:50:41

just for recording syncrepl evaluates any update and if it is in the scope and match the filter, it enqueue the updated entry (ipauser group) to be send back. This entry is found to not match the filter (before and after the MOD) and the server even logged that it is not enqueue to be send.

But for some reason the persistent search find it on the queue and send it back (with the broken cookie).

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-03 19:38:37

just for recording syncrepl evaluates any update and if it is in the scope and match the filter, it enqueue the updated entry (ipauser group) to be send back. This entry is found to not match the filter (before and after the MOD) and the server even logged that it is not enqueue to be send. But for some reason the persistent search find it on the queue and send it back (with the broken cookie).

No, it does match the filter. If you see my update showing the modified output of Flo's test script you can see the group has objectclass groupofnames, so it should be found and returned. #4243#comment-663269

Well in my testing I don't see any log message saying it should not queue the group entry. Like I said in my testing the group does match the filter. The only issue I found was the way the changenumber was being incremented when these multiple updates occur on the ADD operation. Maybe I am missing something??

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-07 02:36:59

Did you have a draft PR for this we could look at? That might be a good place to go from here so we have something concrete to look at :)

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-07 17:19:24

@flo - any chance you could test this copr build and see if it gives you the expected results? Maybe run it against those CI test what use sync repl again (like you did for that other patch a few weeks ago)?

https://copr.fedorainfracloud.org/coprs/build/1523619

Thanks!

389-ds-bot commented 4 years ago

Comment from frenaud at 2020-07-07 18:55:38

Hi @mreynolds389 thanks for the copr build. With this patch, the cookie does not seem to be incremented systematically. For instance: ipa group-add mygroup => cookie 305 ipa group-del mygroup => cookie 305

For a single user-add operation, I get 5 times the same cookie, from the changelog I can imagine that the 5 ops correspond to

But I don't see any more the invalid cookie 4294967295.

The tests with the patch are running in PR 279

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-07 19:40:48

Hi @mreynolds389 thanks for the copr build. With this patch, the cookie does not seem to be incremented systematically. For instance: ipa group-add mygroup => cookie 305 ipa group-del mygroup => cookie 305 For a single user-add operation, I get 5 times the same cookie,

Well the same cookie was also being reused in your original test, just not as many times as with my patch. To be honest I don't know know if that's expected or unexpected. I need to read more about Sync Repl and the RFC.

from the changelog I can imagine that the 5 ops correspond to

  • user creation
  • private group creation
  • addition of mepOriginEntry objectclass to the user
  • addition of mepManagedEntry to the user entry
  • addition of ipantuserattrs to the user entry But I don't see any more the invalid cookie 4294967295. The tests with the patch are running in PR 279

Thank you so much! I'll update this ticket again once I get chance to do more research on the cookie's expected behaviour...

389-ds-bot commented 4 years ago

Comment from flo at 2020-07-07 19:49:00

@flo - any chance you could test this copr build and see if it gives you the expected results?

sorry - I guess I'm tagged wrongly here.

389-ds-bot commented 4 years ago

Comment from elkris at 2020-07-07 21:48:22

Well the same cookie was also being reused in your original test, just not as many times as with my patch. To be honest I don't know know if that's expected or unexpected. I need to read more about Sync Repl and the RFC.

In the 389 sync repl the cookie should always be built with the changenumber of the change in the retro changelog, so it should be unique

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-07 22:02:58

Well the same cookie was also being reused in your original test, just not as many times as with my patch. To be honest I don't know know if that's expected or unexpected. I need to read more about Sync Repl and the RFC.

In the 389 sync repl the cookie should always be built with the changenumber of the change in the retro changelog, so it should be unique

Thanks Ludwig, we were definitely not doing that before we found this bug with the invalid cookie. In the description of this ticket you can see the server was reusing the same changenumber in multiple cookies. So looks like the cookie handling needs a bit work, and my proposed fix is not enough, but I think i was headed in the right direction. I will continue to investigate...

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-07 22:04:38

@flo - any chance you could test this copr build and see if it gives you the expected results?

sorry - I guess I'm tagged wrongly here.

Sorry I meant Florence, not Florian. You can ignore this :-)

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-08 02:09:53

Well the same cookie was also being reused in your original test, just not as many times as with my patch. To be honest I don't know know if that's expected or unexpected. I need to read more about Sync Repl and the RFC.

The RFC is extremely dense and confusing at the best of times. I've been reading it lately and it's extremely fun.

In the 389 sync repl the cookie should always be built with the changenumber of the change in the retro changelog, so it should be unique

Sure, that's true of us internally. But I think from the view of the RFC the definition is:

https://tools.ietf.org/html/rfc4533#section-2.1

2.1.2:

its value is an opaque value containing information about 
the synchronization session and its state.

Provided the cookie that we send at the end of a single sync repl operation is "incremented" relative to our internals, it doesn't matter much to the client as they do not parse that structure. So it's appears valid to have:

chgnum: 1
chgnum: 1
chgnum: 1
send cookie: chgnum: 1
chgnum: 2
send cookie: chgnum: 2
chgnum: 3
chgnum: 3
send cookie: chgnum: 3

provided we never send the updated cookie part-way through a session as that could cause a client to de-sync (IE if we had):

chgnum: 1
chgnum: 1
send cookie: chgnum: 1
chgnum: 1

In this case, it's possible the client may not process the last chgnum and it would be invalid.

As well, because we are doing syncrepl, not delta syncrepl that makes things much much simpler too because each change is a whole entry state.

If there is a required order that must exist for the sending states to be valid, that's also a problem for us internally too. I think we already provide this ordering in the changelog anyway.

So I'm not sure that duplicate changenumbers in the cookie is a problem, provided all duplicate changenumber entries are sent before we send the cookie (which from my understanding of the code, we do correctly).

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-08 03:04:12

In the IPA case it's much worse, and if we need to set the cookie to the retro change number then we are going have major problems. This is what is happening the IPA case. We add a user which triggers 5 updates:

dn: changenumber=150,cn=changelog targetuniqueid: c1120601-c09711ea-983c867d-c7d8958b changeNumber: 150 targetDn: uid=testuser20,cn=users,cn=accounts,dc=ipa,dc=test changeType: add

dn: changenumber=151,cn=changelog targetuniqueid: c1120603-c09711ea-983c867d-c7d8958b changeNumber: 151 targetDn: cn=testuser20,cn=groups,cn=accounts,dc=ipa,dc=test changeType: add

dn: changenumber=152,cn=changelog targetuniqueid: c1120601-c09711ea-983c867d-c7d8958b changeNumber: 152 targetDn: uid=testuser20,cn=users,cn=accounts,dc=ipa,dc=test changeType: modify

dn: changenumber=153,cn=changelog targetuniqueid: c1120601-c09711ea-983c867d-c7d8958b changeNumber: 153 targetDn: uid=testuser20,cn=users,cn=accounts,dc=ipa,dc=test changeType: modify

dn: changenumber=154,cn=changelog targetuniqueid: 5ebb9eaa-bc6e11ea-816c867d-c7d8958b changeNumber: 154 targetDn: cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test changeType: modify

dn: changenumber=155,cn=changelog targetuniqueid: c1120601-c09711ea-983c867d-c7d8958b changeNumber: 155 targetDn: uid=testuser20,cn=users,cn=accounts,dc=ipa,dc=test changeType: modify

So we add test user 20, then a plugin adds a group (not in the scope of of the sync repl search in this case). Then we update user 20 two more times. Then we update a group with user20 info, then we update user 20 again.

When sync repl kicks in it does all the updates for user 20 first: 150,152,153,155. So the last known changenumber in repl sync is now set to 155. Then we try and send the update for change 154 (the ipauser group), but since we moved the changenumber/cookie to 155 it does not find it because repl sync finds its entries by using "(&(changenumber>=COOKIE_VAL)(targetuniqueid=VALUE))".

There is no reliable way to move the cookie backward to find the update to the ipausers group. So in my previous fix it still works but the cookie is not useful in that regard and is repeated within that nested operation set. Trying to move the cookie backwards is not reliable since we use the changenumber like a cursor. So moving it backward or to the beginning will resend old updates.

I checked with my first fix suggestion, the changenumbers are not incremented until we do a different entry. So it still works but the cookie value does not increment until the sequence of those nested operations is complete. Adding a second IPA user correctly uses the changenumber from the retro changelog.

So how important is the cookie value? In my tests things are correctly processed and the correct entries are returned, but the cookie value is not exactly matching the retro changelog changenumber. But when the next session is started it is using the correct number. It's only when we get these nested operations where we reuse the same number in the cookie, but once we start looking at a different entry the change number is correctly set to the retro changenumber. Does that makes sense? This comment is getting long, hope I didn't repeat myself too much :-)

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-08 03:17:02

So how important is the cookie value? In my tests things are correctly processed and the correct entries are returned, but the cookie value is not exactly matching the retro changelog changenumber. But when the next session is started it is using the correct number. It's only when we get these nested operations where we reuse the same number in the cookie, but once we start looking at a different entry the change number is correctly set to the retro changenumber. Does that makes sense? This comment is getting long, hope I didn't repeat myself too much :-)

As mentioned - it's opaque. So long as we can parse it correctly, that's all that matters. The cookie is an opaque token that represents the state of the session. IE we can do whatever we want to the cookie structure and pattern, provided that we can then provide "consistent data" afterwards.

So it still works but the cookie value does not increment until the sequence of those nested operations is complete. Adding a second IPA user correctly uses the changenumber from the retro changelog.

And that's fine, provided that what I said holds true. We can have the cookie number "stay the same" provided that we send all the related elements and changes in the single syncrepl change window. The issue would be say ... you change ipauser X in one op, that does internal changes, then another external change to ipauser X happens. Does the change number increment on the external change? Or is it dependent on the target too?

Reading your comments though, I think the issue sounds like the way changenumbercs are assigned into the cookie. I was under the assumption we set the cookie changenember to max chgnum at the end of a session? But it sounds like we set it to the last processed change number instead?

389-ds-bot commented 4 years ago

Comment from elkris at 2020-07-09 08:07:43

As mentioned - it's opaque. So long as we can parse it correctly, that's all that matters. The cookie is an opaque token that represents the state of the session. IE we can do whatever we want to the cookie structure and pattern, provided that we can then provide "consistent data" afterwards.

The client does not need to parse the cookie, but for the server the content is important. The use of the cookie is to define a staring point in a "refresh" request, eg if a client connection is terminated or if the client only uses series of refreshs and no persist phases. So the changenumber in the cookie is used to define a staring point for sending changes in refresh mode. That said and the fact that we do full sync repl, not delta, clients can and have to deal with changed entries sent a second time, so there can be overlap, but gaps have to be avoided.

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-09 14:32:31

As mentioned - it's opaque. So long as we can parse it correctly, that's all that matters. The cookie is an opaque token that represents the state of the session. IE we can do whatever we want to the cookie structure and pattern, provided that we can then provide "consistent data" afterwards. The client does not need to parse the cookie, but for the server the content is important. The use of the cookie is to define a staring point in a "refresh" request, eg if a client connection is terminated or if the client only uses series of refreshs and no persist phases. So the changenumber in the cookie is used to define a staring point for sending changes in refresh mode. That said and the fact that we do full sync repl, not delta, clients can and have to deal with changed entries sent a second time, so there can be overlap, but gaps have to be avoided.

Ok well I'm starting to feel much more confident about my patch. In all my tests so far we don't miss any entries or resend the same change twice even (even when we have perform updates /changenumbers out of order). I'm going to file a WIP PR now...

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-09 15:15:28

Ok well I'm starting to feel much more confident about my patch. In all my tests so far we don't miss any entries or resend the same change twice even (even when we have perform updates /changenumbers out of order). I'm going to file a WIP PR now...

I spoke too soon. With or without my patch I found another problem.

If an operation triggers a preop plugin that updates a different entry(different uniqueid) then we lose the initial operation and it is not synced. So we need to find a safe/reliable way to rollback the sync cookie changenumber, or completely change how we check for changes or build the sync queue. :-(

The way it works now is that when an entry is changed that entry(uniqueid) is added to the sync queue. Then when we process the queue we take an entry and search for the changenumber>=COOKIE_CHANGENUMBER and the unique ID if the entry from the queue. Then we increment the cookie changenumber after processing all the matching entries. In the preop case. In the preop case we add the entry updated by the preop plugin in the queue before the original entry is added to the queue. After we perform the preop ADD operation (MEP plugin in the IPA case) we advance the cookie changenumber. Now when go to process the original entry from the queue that triggered the preop plugin, but we don't find the initial operation because we advanced the cookie changenumber after doing the preop plugin operation.

Looking at the retro changelog, it is in the expected order, the initial operation is logged first, but the sync queue has the preop entry before the initial entry. So maybe the sync queue can be revised to behave like the retro changelog?? Needs more investigation...

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-09 20:57:42

Okay, another update...

We are not skipping updates when the preop plugin makes a change. So that's good I guess, but we send the updates in the wrong order. Almost appears random...

So the initial "ADD" of the IPA user happens on the 3 update sent to the client, not the first.

syncrepl_entry dn  uid=testuser35,cn=users,cn=accounts,dc=ipa,dc=test
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))241

syncrepl_entry dn  uid=testuser35,cn=users,cn=accounts,dc=ipa,dc=test
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))241

syncrepl_entry dn  uid=testuser35,cn=users,cn=accounts,dc=ipa,dc=test
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))241  <-----  This is the initial ADD of the entry

syncrepl_entry dn  uid=testuser35,cn=users,cn=accounts,dc=ipa,dc=test
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))241

syncrepl_entry dn  cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test
Set cookie:  hp-z210-01.ml3.eng.bos.redhat.com:389#cn=Directory Manager:cn=accounts,dc=ipa,dc=test:(|(objectClass=groupofnames)(objectClass=person))245

How the ADD is happening in the middle is still a mystery. It's not like we are doing the updates in reverse order - the randomness is a bit hard to explain at this time. But the final state of the entry that is sent to the client is correct (not sure if that is a coincidence or not). But something is off with the sync request queue. Maybe we are not updating the linked list correctly? Hard to say...

Regardless my proposed patch still fixes the invalid cookie, but we still have odd behavior with the sync request queue. I will be on PTO next week, but I will continue to look into this when I get back.

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-07-10 19:18:50

I made a testcase without using IPA that reproduce the symptom of a cookie with a changenumber=-1.

First there is an issue related to validation of the filter against the schema. At some point sync-repl plugin uses a unknown attribute "targetuniqueid" "(&(changenumber>=%d)(targetuniqueid=%s))" to retrieves the updates. The search may be rejected (because schema checking) and then no update is found leading to changenumber=-1.

Second targetuniqueid looks weird to me. retroCL contains targetDN but not targetuniqueid. That also explains why the search has no result.

Then I do not understand the need to retrieve next updates related to a specific entry. @elkris shouldn't we simply send entries targeted by next updates (and matching the filter) ?

Also I have a doubt about the matching rule '>=' it will retrieve an update greater than the one in the cookie. But I have a doubt that it will be correctly ordered. If looking for '(changenumber>=19)' and it exists 20, 21, 22. Without sorting I wonder if '22' may not be the first one retrieved by the search instead of '20'

Finally should it be '>=' or '>'

I did the following fix that fixes the pb of changenumber=-1 (in local testcase) it needs to be tested with IPA as well.

diff --git a/ldap/servers/plugins/sync/sync_util.c b/ldap/servers/plugins/sync/sync_util.c
index 847a20df4..6ab3d8b08 100644
--- a/ldap/servers/plugins/sync/sync_util.c
+++ b/ldap/servers/plugins/sync/sync_util.c
@@ -452,7 +452,8 @@ sync_cookie_get_change_number(int lastnr, const char *uniqueid)
     Slapi_Entry *cl_entry;
     int rv;
     unsigned long newnr = SYNC_INVALID_CHANGENUM;
-    char *filter = slapi_ch_smprintf("(&(changenumber>=%d)(targetuniqueid=%s))", lastnr, uniqueid);
+    /*char *filter = slapi_ch_smprintf("(&(changenumber>=%d)(targetuniqueid=%s))", lastnr, uniqueid); */
+    char *filter = slapi_ch_smprintf("(changenumber>=%d)", lastnr);

     srch_pb = slapi_pblock_new();
     slapi_search_internal_set_pb(srch_pb, CL_SRCH_BASE, LDAP_SCOPE_SUBTREE, filter,
389-ds-bot commented 4 years ago

Comment from elkris at 2020-07-10 19:27:02

Second targetuniqueid looks weird to me. retroCL contains targetDN but not targetuniqueid. That also explains why the search has no result.

You need to configure RetroCL, I thin k IPA does it.

http://www.port389.org/docs/389ds/design/content-synchronization-plugin.html#access-to-nsuniqueid

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-15 07:30:02

How the ADD is happening in the middle is still a mystery. It's not like we are doing the updates in reverse order - the randomness is a bit hard to explain at this time. But the final state of the entry that is sent to the client is correct (not sure if that is a coincidence or not). But something is off with the sync request queue. Maybe we are not updating the linked list correctly? Hard to say...

Could we be updating the cookie num from "last seen chg num" rather than "max seen chg num"?

Regardless my proposed patch still fixes the invalid cookie, but we still have odd behavior with the sync request queue. I will be on PTO next week, but I will continue to look into this when I get back.

Have a good week off man :)

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-07-16 12:29:50

@elkris thanks for the tip matching nsuniqueid with targetuniqueid helps a lot. I think the testcase I reproduce should be close to the original one.

I reproduce a weird order of sent back cookies (including -1 update number). The root cause of all of that the order of the sent back updates is not the order that the updates were applied. In short, all updates are orders in retroCL (thanks to betxn). But sync repl registers (in a queue) updates in postop, so if we have nested updates 1,2,3,4 they are registered in the queue 4,3,2,1.

The persistent thread poll the queue (on notify and periodicity) for updates to send. But if it detects update 4, it has no idea that the update 1 will come. So it can send unordered update, send jumpoing cookie (when sending update_number 4, it has not yet sent update_number 1), and can fall to -1 update_number if it dequeue a late update.

at the moment I have no clear idea how to fix that. If we have nested updates how to know we reached the first one ? Even if we managed to reorder the queue, it looks significant change to make the persistent thread wait for an ordered queue.

An option is too rely on retroCL (that is ordered). We may wait for the next update (according to the cookie), when this update is detected (in retroCL) then wait for the update in queue, then pick the update from the queue, send the entry, update the change_number and iterate.

Anyway IMHO this ticket may require some time to be fixed

389-ds-bot commented 4 years ago

Comment from elkris at 2020-07-16 21:48:34

@tbordaz thanks for all the investigation, I think you are on the right track. Probably we need to do something like the csn pending lists, where csns are collected until the outmost operation finally completes. so do not send intermediate results and wait if you know all the changes to be sent.

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-07-17 01:43:55

Wow, excellent investigation @tbordaz :)

could we potentially use something like a min/max heap for the queue rather than a list which would allow us to have ordering of the elements in the queue instead?

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-07-22 17:40:36

Just for recording, I made a fix using a kind or per thread operation pending list (approach suggested by @elkris). The fix works to reorder cookie and prevent invalid (-1) cookie. I am trying to merge the testcase with the syncrepl script that @frenaud provided.

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-07-23 16:45:30

tentative PR - #4267

Have not yet be tested with Global Catalog deployement

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-08-10 11:49:53

Some news as I am still working on that ticket ...

The RC is identified: nested updates are not processed by sync_repl in the order they were applied on DB. This leads invalid jumps/failure of the cookie (more specifically the change identifier).

There is an identified fix to reorder the updates (with and without failure during internal updates).

A last missing part is the correct ordering of the changenumber (see #4243#comment-664634). In some rare case, the order is invalid (although I forced the sorting). I am trying to reproduce this.

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-08-11 11:07:08

The good news is that I reproduced and understand the reason of the rare invalid cookie (rare because it happens less than 1 out 100times). The bad news is that it hits a design choice and that needs to be discussed.

Initially the invalid cookie were generated by the processing of nested updates in an invalid order . Sorting internal search results and management of pending list update, fixed this.

Sync repl is a dedicated thread reading a queue (ordered) of updates. This queue is written on plugin callback (post op). So nested updates (under a single txn) are flushed in the queue outside of the txn (or backend lock). A consequence is that second set of nested updates can start/complete before the first set is fully flushed on the queue. The order of the updates on the queue is not the same order of what was processed by the server.

@elkris, the step to flush the update on the sync_repl queue (sync_queue_change) is in postop (http://www.port389.org/docs/389ds/design/content-synchronization-plugin.html#post_modify--add-delete--modrdn_plugin). Any reason why it is a postop rather than a bepostop or betxnpostop ? I think that even if we protect the queue along the flush of a full set of nested updates it remains a risk that recent updates can be enqueue before old updates.

Next, will try to improve reproducer to reproduce faster the rare invalid order

Here are logs (with additional debug msg) that captured the invalid order

# Here the first direct update uid=test_user_1001 is completed
# Thread_1 is flushing the pending list to the sync_repl queue
# the pending list contains:
#   1.1 uid=test_user_1001
#   1.2 cn=group1
#   1.3 uid=test_user_1001
#   1.4 cn=group2
#   1.5 uid=test_user_1001
[10/Aug/2020:17:58:25.787587655 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0xcaf340) uid=test_user_10001,ou=people,dc=example,dc=com

# Thread_1 is in post op so Thread_2 starts the second direct uid=test_user_10002
[10/Aug/2020:17:58:25.794009372 +0200] - DEBUG - content-sync-plugin - sync_update_persist_betxn_pre_op - primary operation targets "uid=test_user_10002,ou=People,dc=example,dc=com" (0xcad160)

# Thread_1 flushes 1.1, 1.2 on sync_repl queue
[10/Aug/2020:17:58:25.794985771 +0200] - DEBUG - content-sync-plugin - sync_queue_change - entry "uid=test_user_10001,ou=people,dc=example,dc=com" 
[10/Aug/2020:17:58:25.805753096 +0200] - DEBUG - content-sync-plugin - sync_queue_change - entry "cn=group1,ou=groups,dc=example,dc=com" 

# Thread_2 
# Thread_2 completed the second direct update uid=test_user_1002 is completed
# Thread_2 is flushing the pending list to the sync_repl queue
# the pending list contains:
#   2.1 uid=test_user_1002
#   2.2 cn=group1
#   2.3 uid=test_user_1002
#   2.4 cn=group2
#   2.5 uid=test_user_1002
[10/Aug/2020:17:58:25.985033027 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0xcad160) uid=test_user_10002,ou=people,dc=example,dc=com

# Thread_2 flushes 2.1
[10/Aug/2020:17:58:25.988488764 +0200] - DEBUG - content-sync-plugin - sync_queue_change - entry "uid=test_user_10002,ou=people,dc=example,dc=com" 

# Thread_2 is in post op so Thread_3 starts the second direct uid=test_user_10003
[10/Aug/2020:17:58:25.992498488 +0200] - DEBUG - content-sync-plugin - sync_update_persist_betxn_pre_op - primary operation targets "uid=test_user_10003,ou=People,dc=example,dc=com" (0xcaf690)

# Thread_3 
# Thread_3 completed the second direct update uid=test_user_1003 is completed
# Thread_3 is flushing the pending list to the sync_repl queue
# the pending list contains:
#   3.1 uid=test_user_1003
#   3.2 cn=group1
#   3.3 uid=test_user_1003
#   3.4 cn=group2
#   3.5 uid=test_user_1003
[10/Aug/2020:17:58:26.293316904 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0xcaf690) uid=test_user_10003,ou=people,dc=example,dc=com

# Thread_3 is in post op so Thread_4 starts the second direct uid=test_user_10004
[10/Aug/2020:17:58:26.300071653 +0200] - DEBUG - content-sync-plugin - sync_update_persist_betxn_pre_op - primary operation targets "uid=test_user_10004,ou=People,dc=example,dc=com" (0xb85980)

# Thread_3 flushes 3.1
[10/Aug/2020:17:58:26.301135468 +0200] - DEBUG - content-sync-plugin - sync_queue_change - entry "uid=test_user_10003,ou=people,dc=example,dc=com" 

# Thread_4 
# Thread_4 completed the second direct update uid=test_user_1004 is completed
# Thread_4 is flushing the pending list to the sync_repl queue
# the pending list contains:
#   4.1 uid=test_user_1004
#   4.2 cn=group1
#   4.3 uid=test_user_1004
#   4.4 cn=group2
#   4.5 uid=test_user_1004
[10/Aug/2020:17:58:26.593164162 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0xb85980) uid=test_user_10004,ou=people,dc=example,dc=com

# Thread_4 flushes 4.1
[10/Aug/2020:17:58:26.594679100 +0200] - DEBUG - content-sync-plugin - sync_queue_change - entry "uid=test_user_10004,ou=people,dc=example,dc=com" 

# Sync_repl detected update 1.1
[10/Aug/2020:17:58:26.796987208 +0200] - DEBUG - content-sync-plugin - sync_queue_change - dequeue  "uid=test_user_10001,ou=people,dc=example,dc=com" 

# Thread_1 flushes 1.3
[10/Aug/2020:17:58:26.800396631 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0x7f0278038170) uid=test_user_10001,ou=people,dc=example,dc=com

# Thread_4 flushes 4.2
[10/Aug/2020:17:58:26.804935544 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0x7f0264028500) cn=group1,ou=groups,dc=example,dc=com

# Thread_2 flushes 2.2
[10/Aug/2020:17:58:26.807735021 +0200] - DEBUG - content-sync-plugin - flush pending list on listeners queue (0x7f0274020f40) cn=group1,ou=groups,dc=example,dc=com

--> updates seen by sync_repl thread: 
        - 1.1, 1.2, 2.1, 3.1, 4.1, 1.3, 4.2, 2.2...
instead of  - 1.1, 1.2, 1.3, 1.4, 1.5, 2.1, 2,2, 2.3...

With those jumps, sync_repl will generate jump in cookie (missing some entries) and sometime failure to retrieve next update (cookie=-1): ['1', '2', '6', '11', '16', '4294967295',...
    (cookie=-1 is a result of "(&(changenumber>=16)(targetuniqueid=<uid=test_user_10001>))")
389-ds-bot commented 4 years ago

Comment from elkris at 2020-08-11 17:58:51

@elkris, the step to flush the update on the sync_repl queue (sync_queue_change) is in postop (http://www.port389.org/docs/389ds/design/content-synchronization-plugin.html#post_modify--add-delete--modrdn_plugin). Any reason why it is a postop rather than a bepostop or betxnpostop ?

no, I do not remember a specific reason for this, I think I tried to make it analogous to persistent search. I think it could be betxnpostop, just check what happens to modifications by a postop plugin

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2020-08-12 05:33:59

@tbordaz An aspect here is how we handle failure too. In a failure case we need to be able to undo the changes into the sync repl thread.

Can we add some meta-data messages to the queue system? I'm thinking something like:

START_OP (id number)
APPEND_OP(id number, operation)
ABORT_OP (id number)
COMMIT_OP (id number)

This would let us handle this situation you have by doing something like:

let next = queue.recv;

if next == start_op {
    // associate the id number with a list of events in a hashmap or similar
} else if next == append_op {
    // push the operation to the hashmap'd slot with the id number
} else if next == abort_op {
    // drop the hashmap'd slot and all changes pending
} else if commit_op {
    // take all the items from the slot, and push them into the sync repl change queue
}

Effectively, this is doing a form of batching, so that all operations from an operation are submitted as a whole unit of change into sync repl, rather than being inter-leaved which is causing the issues you have. This would mean that you would see all changes from a single op at once, and gives us a method to rollback if something goes wrong IE db deadlock because two threads modified the same entry etc. It also means we are sorting everything as we read from the queue.

Does that help as a possible idea to this issue?

Thanks for the great writeup!

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-08-13 15:56:01

Reproducer: I identified an almost systematic reproducer that unfortunately requires adding a tempo in sync_repl dedicated thread. I can not be used for CI test but I used it to validate a fix.

diff --git a/ldap/servers/plugins/sync/sync_persist.c b/ldap/servers/plugins/sync/sync_persist.c
index 24aa9eac4..c965c07fd 100644
--- a/ldap/servers/plugins/sync/sync_persist.c
+++ b/ldap/servers/plugins/sync/sync_persist.c
@@ -849,6 +849,7 @@ sync_send_results(void *arg)
             LDAPControl **ectrls = NULL;
             Slapi_Entry *ec;
             int chg_type = LDAP_SYNC_NONE;
+            PR_Sleep(PR_SecondsToInterval(1));

             /* deque one element */
             PR_Lock(req->req_lock);

Thanks @elkris for your feedback. Changing postop (update) to be_postop made it work. I need now to update the design to reflect the changes proposed with this PR.

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-08-26 18:28:00

PR #4267

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-09-09 10:45:05

Metadata Update from @tbordaz:

389-ds-bot commented 4 years ago

Comment from tbordaz (@tbordaz) at 2020-09-09 10:56:56

Fix pushed

e8f069271..f9638bbd8 master 65c01bbae..353358978 389-ds-base-1.4.3

tbordaz commented 3 years ago

Fix (testcase test_sync_repl_cookie_with_failure) https://github.com/389ds/389-ds-base/pull/4467 ce7beae4d..f1243f7cb master aacdac380..de9965d00 389-ds-base-1.4.4 db8a6bdeb..6fe2ed44d 389-ds-base-1.4.3

tbordaz commented 3 years ago

Fix testcases (https://github.com/389ds/389-ds-base/pull/4466) b7219518d..7d2f95dc5 master b09e60339..a074b28cc 389-ds-base-1.4.4 3c2d054e1..c28d5285d 389-ds-base-1.4.3