Bug 1851978

Summary: SyncRepl plugin provides a wrong cookie
Product: Red Hat Enterprise Linux 8 Reporter: mreynolds
Component: 389-ds-baseAssignee: thierry bordaz <tbordaz>
Status: CLOSED ERRATA QA Contact: RHDS QE <ds-qe-bugs>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.0CC: bsmejkal, pasik, sgouvern, spichugi, tbordaz, vashirov
Target Milestone: rcKeywords: TestCaseProvided, Triaged
Target Release: 8.0Flags: pm-rhel: mirror+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 389-ds-devel-1.4-8040020201105165416.866effaa Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-05-18 15:45:18 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description mreynolds 2020-06-29 14:39:27 UTC
This bug is created as a clone of upstream ticket:
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

- install ipa server with `ipa-server-install --domain ipa.test --realm IPA.TEST --setup-dns --auto-forwarder --auto-reverse -a $PASSWORD -p $PASSWORD -U`
- enable retro changelog on cn=accounts,$SUFFIX:
```
# ldapmodify -D "cn=directory manager" -w $PASSWORD << EOF
dn: cn=Retro Changelog Plugin,cn=plugins,cn=config
changetype: modify
add: nsslapd-include-suffix
nsslapd-include-suffix: cn=accounts,dc=ipa,dc=test

EOF

# systemctl restart dirsrv
```

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)
```

Comment 1 thierry bordaz 2020-09-09 09:05:23 UTC
Fix is pushed upstream -> POST

Comment 12 sgouvern 2020-11-27 11:02:00 UTC
With build 389-ds-base-1.4.3.16-3.module+el8.4.0+8869+55706461.x86_64, en after applying https://github.com/389ds/389-ds-base/pull/4466,
dirsrvtests/suites/syncrepl_plugin/basic_test.py::test_sync_repl_cookie_with_failure
is still failing with error 
        # checking that the cookie list contains only one entry
>       assert len(cookies) == 1
E       assert 2 == 1
E         +2
E         -1

This needs to be investigated -> marking ASSIGNED for tracking

Comment 13 thierry bordaz 2020-11-27 17:54:04 UTC
The patch https://github.com/389ds/389-ds-base/pull/4467 fixes this remaining failure in test_sync_repl_cookie_with_failure

Waiting for review/ack to merge and produce a new build

Comment 16 bsmejkal 2020-12-08 07:03:40 UTC
==================================================================================== test session starts =====================================================================================
platform linux -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1 -- /usr/bin/python3.6
cachedir: .pytest_cache
metadata: {'Python': '3.6.8', 'Platform': 'Linux-4.18.0-257.el8.x86_64-x86_64-with-redhat-8.4-Ootpa', 'Packages': {'pytest': '6.1.2', 'py': '1.9.0', 'pluggy': '0.13.1'}, 'Plugins': {'metadata': '1.11.0', 'html': '3.1.0', 'libfaketime': '0.1.2'}}
389-ds-base: 1.4.3.16-4.module+el8.4.0+8992+caadce03
nss: 3.53.1-11.el8_2
nspr: 4.25.0-2.el8_2
openldap: 2.4.46-16.el8
cyrus-sasl: 2.1.27-5.el8
FIPS: disabled
rootdir: /mnt/tests/rhds/tests/upstream/ds/dirsrvtests, configfile: pytest.ini
plugins: metadata-1.11.0, html-3.1.0, libfaketime-0.1.2
collected 5 items / 2 deselected / 3 selected                                                                                                                                                

dirsrvtests/tests/suites/syncrepl_plugin/basic_test.py::test_sync_repl_cookie PASSED                                                                                                   [ 33%]
dirsrvtests/tests/suites/syncrepl_plugin/basic_test.py::test_sync_repl_cookie_add_del PASSED                                                                                           [ 66%]
dirsrvtests/tests/suites/syncrepl_plugin/basic_test.py::test_sync_repl_cookie_with_failure PASSED                                                                                      [100%]

=============================================================================== 3 passed in 160.93s (0:02:40) ===============================================================================

Marking as Verified:Tested.

Comment 17 sgouvern 2020-12-14 14:53:44 UTC
Missed the ITM 6 milestone -> moving to ITM 7

Comment 20 sgouvern 2020-12-21 13:46:28 UTC
With build 389-ds-base-1.4.3.16-6.module+el8.4.0+9207+729bbaca.x86_64

================================================== test session starts ==================================================
platform linux -- Python 3.6.8, pytest-6.2.1, py-1.10.0, pluggy-0.13.1 -- /usr/bin/python3.6
cachedir: .pytest_cache
metadata: {'Python': '3.6.8', 'Platform': 'Linux-4.18.0-260.el8.x86_64-x86_64-with-redhat-8.4-Ootpa', 'Packages': {'pytest': '6.2.1', 'py': '1.10.0', 'pluggy': '0.13.1'}, 'Plugins': {'metadata': '1.11.0', 'html': '3.1.1', 'libfaketime': '0.1.2'}}
389-ds-base: 1.4.3.16-6.module+el8.4.0+9207+729bbaca
nss: 3.53.1-13.el8_3
nspr: 4.25.0-2.el8_2
openldap: 2.4.46-16.el8
cyrus-sasl: 2.1.27-5.el8
FIPS: disabled
rootdir: /mnt/tests/rhds/tests/upstream/ds/dirsrvtests, configfile: pytest.ini
plugins: metadata-1.11.0, html-3.1.1, libfaketime-0.1.2
collected 3 items  

INFO:dirsrvtests.tests.suites.syncrepl_plugin.basic_test:test_sync_repl_cookie: PASS
INFO:dirsrvtests.tests.suites.syncrepl_plugin.basic_test:test_sync_repl_cookie_add_del: PASS
INFO:dirsrvtests.tests.suites.syncrepl_plugin.basic_test:test_sync_repl_cookie_with_failure: PASS  

============================================= 3 passed in 145.29s (0:02:25) =============================================

marking VERIFIED

Comment 22 errata-xmlrpc 2021-05-18 15:45:18 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

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

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

https://access.redhat.com/errata/RHBA-2021:1835