cannot reindex retrochangelog

[389-ds-bot]

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

• Created at 2013-12-03 20:06:56 by lkrispen (@elkris)
• Closed as Fixed
• Assigned to tbordaz (@tbordaz)
• Associated bugzillas
  • https://bugzilla.redhat.com/show_bug.cgi?id=1370145

---

needed to add an index to the retro changelog so that memberof and referint don't do unindexed searches, but it fails to reindex

/usr/sbin/db2index.pl -v -n 'changelog' -D "cn=directory manager" -w secret12 -Z mysync -t cn
ldap_initialize( ldap://localhost:1390 )
Successfully added task entry "cn=db2index_2013_12_3_15_3_18, cn=index, cn=tasks, cn=config"

The index thread is created, but waits on a lock:

Thread 2 (Thread 0x7fc88ffff700 (LWP 18992)):
0 pthread_rwlock_wrlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_wrlock.S:86
1 0x0000003f2f6d1489 in slapi_rwlock_wrlock (rwlock=0x14d1240) at ldap/servers/slapd/slapi2nspr.c:267
2 0x0000003f2f64ef0f in slapi_be_Wlock (be=0x14c0e90) at ldap/servers/slapd/backend_manager.c:436
3 0x0000003f2f694d35 in slapi_mtn_be_set_readonly (be=0x14c0e90, readonly=1) at ldap/servers/slapd/mapping_tree.c:3724
4 0x00007fc8b87e852e in instance_set_busy_and_readonly (inst=0x13d5260) at ldap/servers/slapd/back-ldbm/misc.c:210
5 0x00007fc8b87e20c0 in ldbm_back_ldbm2index (pb=0x7fc888003820) at ldap/servers/slapd/back-ldbm/ldif2ldbm.c:1742
6 0x0000003f2f6dbe94 in task_index_thread (arg=0x7fc888003820) at ldap/servers/slapd/task.c:1644
7 0x0000003e6dc28b46 in _pt_root (arg=0x7fc888003ae0) at ../../../nspr/pr/src/pthreads/ptthread.c:204
8 0x000000390b607d14 in start_thread (arg=0x7fc88ffff700) at pthread_create.c:309
9 0x000000390aef168d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

no other activity on the server, indxing an other backend works

[389-ds-bot]

Comment from pspacek at 2013-12-03 20:35:45

I have run into this problem today during syncrepl testing, so changed "Ticket origin" to IPA.

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-07 23:08:30

I was unable to reproduce the problem (kind of hang of the task). Using a test case (lib389), it succeeds to index an attribute (here 'cn').
For example:

dn: cn=db2index_2014_2_7_17_55_14,cn=index,cn=tasks,cn=config
objectClass: top
objectClass: extensibleObject
cn: db2index_2014_2_7_17_55_14
nsinstance: changelog
nsindexattribute: cn
nstaskcurrentitem: 0
nstasktotalitems: 1
nstasklog:: Y2hhbmdlbG9nOiBJbmRleGluZyBhdHRyaWJ1dGU6IGNuCmNoYW5nZWxvZzogRmluaX
 NoZWQgaW5kZXhpbmcu
nstaskstatus: changelog: Finished indexing.
nstaskexitcode: 0

The problem is possibly not systematic or has been fixed since it was reported.
I will continue investigation

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-11 22:41:47

attachment
ticket47619_test.py

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-11 22:47:10

I am still failing to reproduce with the attached test case.
The test case does the following:

• create 1Master-1Consumer
• On master enable: referential integrity, memberof, retro-changelog
• Create entries on the replicated suffix
• Creates several indexes on the 'cn=changelog' suffix and reindex them with tasks.

All reindex completed successfully, although the index are empty.
I fail to reproduce on master, 1.3.1, 1.2.11

[389-ds-bot]

Comment from pspacek at 2014-02-12 16:44:33

Interesting. I don't have the original VM anymore so I will close the ticket.

Thank you for your time!

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-12 17:01:50

Hi Peter,

I reproduced locally the problem:

0  pthread_rwlock_wrlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_wrlock.S:86
1  0x00007fa093178b59 in slapi_rwlock_wrlock (rwlock=0x138e2b0) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/slapi2nspr.c:267
2  0x00007fa0930ed397 in slapi_be_Wlock (be=0x1380950) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/backend_manager.c:436
3  0x00007fa0931384c0 in slapi_mtn_be_set_readonly (be=0x1380950, readonly=1) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/mapping_tree.c:3724
4  0x00007fa08fa48b6a in instance_set_busy_and_readonly (inst=0x132a910) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/back-ldbm/misc.c:210
5  0x00007fa08fa41c63 in ldbm_back_ldbm2index (pb=0x7fa044003810) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/back-ldbm/ldif2ldbm.c:1742
6  0x00007fa093184aa8 in task_index_thread (arg=0x7fa044003810) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/task.c:1644
7  0x0000003c53028b46 in _pt_root (arg=0x7fa044003ad0) at ../../../nspr/pr/src/pthreads/ptthread.c:204
8  0x0000003bee407d14 in start_thread (arg=0x7fa066fe5700) at pthread_create.c:309
9  0x0000003bee0f168d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

Talking with Ludwig yesterday, I realized that the difference of my test case vs. what he did was that the instance was restarted before the reindex. It makes the difference and allow me to reproduce.

I reopen that ticket.

Sorry for the noise

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-12 20:18:12

To do a reindex task, the 'changelog' backend needs to be acquired in Write. The hang of the thread processing the task is due to the 'changelog' backend being already acquired in Read.

This seems to be triggered by the retro-changelog plugin startup routine that acquires the backend in Read but does not to release it after the plugin initialization.

(gdb) where
0  slapi_be_Rlock (be=0x93ac90) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/backend_manager.c:430
1  0x00007ffff7d44c08 in mtn_get_be (target_node=0x7a5e60, pb=0xa8c160, be=0x7fffffffb990, index=0x7fffffffb940, 
    referral=0x7fffffffb998, errorbuf=0x7fffffffb9b0 "")
    at ../workspaces/389-master-branch/ds/ldap/servers/slapd/mapping_tree.c:2789
2  0x00007ffff7d43978 in slapi_mapping_tree_select (pb=0xa8c160, be=0x7fffffffb990, referral=0x7fffffffb998, 
    errorbuf=0x7fffffffb9b0 "") at ../workspaces/389-master-branch/ds/ldap/servers/slapd/mapping_tree.c:2214
3  0x00007ffff30a5ada in retrocl_select_backend ()
    at ../workspaces/389-master-branch/ds/ldap/servers/plugins/retrocl/retrocl.c:241
4  0x00007ffff30a5d07 in retrocl_start (pb=0x9037e8)
    at ../workspaces/389-master-branch/ds/ldap/servers/plugins/retrocl/retrocl.c:333
5  0x00007ffff7d5e7cc in plugin_call_func (list=0x82b1b0, operation=212, pb=0x9037e8, call_one=1)
    at ../workspaces/389-master-branch/ds/ldap/servers/slapd/plugin.c:1474
6  0x00007ffff7d5e6b9 in plugin_call_one (list=0x82b1b0, operation=212, pb=0x9037e8)
    at ../workspaces/389-master-branch/ds/ldap/servers/slapd/plugin.c:1442
7  0x00007ffff7d5deca in plugin_dependency_startall (argc=9, argv=0x7fffffffe2d8, 
    errmsg=0x7ffff7dbc254 "plugin startup failed\n", operation=212)
    at ../workspaces/389-master-branch/ds/ldap/servers/slapd/plugin.c:1214
8  0x00007ffff7d5e5eb in plugin_startall (argc=9, argv=0x7fffffffe2d8, start_backends=1, start_global=1)
    at ../workspaces/389-master-branch/ds/ldap/servers/slapd/plugin.c:1404
9  0x00000000004239f7 in main (argc=9, argv=0x7fffffffe2d8) at ../workspaces/389-master-branch/ds/ldap/servers/slapd/main.c:1187

What I do not understand is why it requires a restart between index configuration and reindex to trigger the hang.

[389-ds-bot]

Comment from lkrispen (@elkris) at 2014-02-12 20:22:14

If the server is not restarted is the index really active, does indexing work and try to acquire the lock ?

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-12 20:59:08

Regarding the test case:
After enabling the RetroCL plugin, at restart, the backend is not found. So it is not locked (in read), just created.
Later restart, will find the backend, that is this time acquired in Read and could trigger this hang.

Regarding the index:
I need to check. Indexes are created/used with a restart between 'index' configuratin and reindex.
I will check without restart

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-12 22:21:56

Regarding index:

Once retroCL is enabled and the server restarted.
Indexes are really active as soon as the index entry is created and reindex task complete.
It does not require a restart to make active the new indexes

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-12 23:30:40

attachment
0001-Ticket-47619-test-case.patch

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-12 23:30:56

attachment
0002-Ticket-47619-cannot-reindex-retrochangelog.patch

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2014-02-13 16:47:44

git merge ticket47619

Updating 5b8dfcd..8087f05
Fast-forward
dirsrvtests/tickets/ticket47619_test.py | 299 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
ldap/servers/plugins/retrocl/retrocl.c | 3 +
2 files changed, 302 insertions(+)
create mode 100644 dirsrvtests/tickets/ticket47619_test.py

git push origin master

Counting objects: 18, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (10/10), done.
Writing objects: 100% (10/10), 4.09 KiB, done.
Total 10 (delta 6), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
5b8dfcd..8087f05 master -> master

commit 8087f05
Author: Thierry bordaz (tbordaz) tbordaz@redhat.com
Date: Wed Jan 15 09:59:13 2014 +0100

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2016-10-11 11:07:57

Pushed to 389-ds-base-1.2.11:

9034668..a5499cb 389-ds-base-1.2.11 -> 389-ds-base-1.2.11
commit a5499cb

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2017-02-11 23:06:04

Metadata Update from @tbordaz:

• Issue assigned to tbordaz
• Issue set to the milestone: 1.3.3 - 1/14 (January)