reindexing using db2index.pl after deleting and creating a VLV does not work

[389-ds-bot]

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

• Created at 2016-06-02 20:06:35 by vakwetu
• Assigned to nhosoi (@nhosoi)

---

In my script, I am doing the following:

1. remove existing VLVs.
2. create new VLVs (with the same name)
3. online re-indexing the new VLVs using db2index.pl.

In the error log, I see logs indicating that the VLV indexes have been deleted. I also see that the VLV indexing task has been added (by doing an ldapsearch), but the task is never acted upon.

If I restart the server and then attempt the reindexing, it works.

[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Search (allKeys-pki-tomcat).
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Search (kraAll-pki-tomcat).
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Search (kraArchival-pki-tomcat).
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Search (kraRecovery-pki-tomcat).
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Search (kraCanceled-pki-tomcat).
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Search (kraCanceledEnrollment-pki-tomcat).
[02/Jun/2016:09:21:04 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraCanceledRecovery-pki-tomcat).
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraRejected-pki-tomcat).
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraRejectedEnrollment-pki-tomcat).
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraRejectedRecovery-pki-tomcat).
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraComplete-pki-tomcat).
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraCompleteEnrollment-pki-tomcat).
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Index.
[02/Jun/2016:09:21:05 -0400] - Deleted Virtual List View Search (kraCompleteRecovery-pki-tomcat).

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2016-06-03 06:12:27

Interesting... My reindexing task hangs in BDB:

(gdb) bt
0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
1  0x00007fbd1466f0fb in __db_pthread_mutex_condwait (env=0x558915eb3120, mutex=140450187388150, timespec=0x0, mutexp=<optimized out>)
    at ../../src/mutex/mut_pthread.c:321
2  __db_hybrid_mutex_suspend (env=env@entry=0x558915eb3120, mutex=mutex@entry=2306, timespec=timespec@entry=0x0, exclusive=exclusive@entry=1)
    at ../../src/mutex/mut_pthread.c:577
3  0x00007fbd1466e52f in __db_tas_mutex_lock_int (nowait=0, timeout=0, mutex=2306, env=<optimized out>) at ../../src/mutex/mut_tas.c:255
4  __db_tas_mutex_lock (env=env@entry=0x558915eb3120, mutex=2306, timeout=timeout@entry=0) at ../../src/mutex/mut_tas.c:286
5  0x00007fbd14718c97 in __lock_get_internal (lt=lt@entry=0x558915ea2d70, sh_locker=sh_locker@entry=0x7fbd0ee8eac0, flags=flags@entry=0, 
    obj=<optimized out>, lock_mode=<optimized out>, timeout=0, lock=0x7fbce8fe75f8) at ../../src/lock/lock.c:989
6  0x00007fbd14719f21 in __lock_vec (env=0x558915eb3120, sh_locker=sh_locker@entry=0x7fbd0ee8eac0, flags=<optimized out>, 
    list=list@entry=0x7fbce8fe75b0, nlist=nlist@entry=2, elistp=elistp@entry=0x7fbce8fe7558) at ../../src/lock/lock.c:140
7  0x00007fbd147734f9 in __fop_lock_handle (env=<optimized out>, dbp=0x7fbc700054f0, locker=0x7fbd0ee8eac0, mode=<optimized out>, 
    elockp=0x7fbce8fe7680, flags=<optimized out>) at ../../src/fileops/fop_util.c:144
8  0x00007fbd14775568 in __fop_remove_setup (dbp=dbp@entry=0x7fbc700054f0, txn=txn@entry=0x0, 
    name=0x7fbc700042e0 "/var/lib/dirsrv/slapd-test0/db/userRoot/vlv#bymccoupeopledcexampledccom.db", flags=flags@entry=0)
    at ../../src/fileops/fop_util.c:1079
9  0x00007fbd14758b49 in __db_remove_int (dbp=dbp@entry=0x7fbc700054f0, ip=0x0, txn=txn@entry=0x0, 
    name=name@entry=0x7fbce8fe7ad0 "/var/lib/dirsrv/slapd-test0/db/userRoot/vlv#bymccoupeopledcexampledccom.db", subdb=subdb@entry=0x0, 
    flags=flags@entry=0) at ../../src/db/db_remove.c:289
10 0x00007fbd1475956f in __db_remove (dbp=dbp@entry=0x7fbc700054f0, ip=<optimized out>, txn=txn@entry=0x0, 
    name=name@entry=0x7fbce8fe7ad0 "/var/lib/dirsrv/slapd-test0/db/userRoot/vlv#bymccoupeopledcexampledccom.db", subdb=subdb@entry=0x0, 
    flags=flags@entry=0) at ../../src/db/db_remove.c:220
11 0x00007fbd147596cb in __db_remove_pp (dbp=0x7fbc700054f0, 
    name=0x7fbce8fe7ad0 "/var/lib/dirsrv/slapd-test0/db/userRoot/vlv#bymccoupeopledcexampledccom.db", subdb=0x0, flags=0)
    at ../../src/db/db_remove.c:194
12 0x00007fbd122838eb in dblayer_db_remove_ex (env=0x558915d6acb0, 
    path=0x7fbce8fe7ad0 "/var/lib/dirsrv/slapd-test0/db/userRoot/vlv#bymccoupeopledcexampledccom.db", dbName=0x0, use_lock=0)
    at ldap/servers/slapd/back-ldbm/dblayer.c:3190
13 0x00007fbd12283dbb in dblayer_erase_index_file_ex (be=0x558915d6e430, a=0x7fbc7c017540, use_lock=0, no_force_checkpoint=1)
    at ldap/servers/slapd/back-ldbm/dblayer.c:3308
14 0x00007fbd12283e8d in dblayer_erase_index_file_nolock (be=0x558915d6e430, a=0x7fbc7c017540, no_force_chkpt=1)
    at ldap/servers/slapd/back-ldbm/dblayer.c:3330
15 0x00007fbd122fb67a in vlvIndex_go_offline (p=0x7fbc7c002a20, be=0x558915d6e430) at ldap/servers/slapd/back-ldbm/vlv_srch.c:763
16 0x00007fbd122e668d in ldbm_back_ldbm2index (pb=0x7fbc6c001af0) at ldap/servers/slapd/back-ldbm/ldif2ldbm.c:1880
17 0x00007fbd1e5d3b0b in task_index_thread (arg=0x7fbc6c001af0) at ldap/servers/slapd/task.c:1652
18 0x00007fbd1becf65b in _pt_root (arg=0x7fbc6c001dc0) at ../../../nspr/pr/src/pthreads/ptthread.c:216
19 0x00007fbd1b86d555 in start_thread (arg=0x7fbce8fe9700) at pthread_create.c:333
20 0x00007fbd1b5a7ded in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

And my shutdown attempt hangs due to this db_tas_mutex_lock.

But it looks you had no problem to restart the server. I'm worried if I'm seeing the same issue you reported.

Could it be possible to try the operation again and attach gdb to the server to get the stacktraces?

The instruction is found here:
http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs

Thanks.

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2016-06-03 07:09:42

In addition to the gdb output, can we have the output from this ldapsearch on the VLV indexing task?

I also see that the VLV indexing task has been added (by doing an ldapsearch),

Could it have this status?

nstaskstatus: userRoot: Finished indexing.

If yes, what happens if you run a search using the VLV index? Does it fail?

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2016-06-10 01:26:35

Per weekly meeting, setting the milestone to 1.3.6.

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2017-02-11 22:52:03

Metadata Update from @nhosoi:

• Issue assigned to nhosoi
• Issue set to the milestone: 1.3.6.0

[389-ds-bot]

Comment from mreynolds (@mreynolds389) at 2017-05-08 22:34:59

Metadata Update from @mreynolds389:

• Custom field reviewstatus reset (from needinfo)
• Issue close_status updated to: None
• Issue set to the milestone: 1.4 backlog (was: 1.3.6.0)

[tbordaz]

Tried to reproduce without success. Closing this ticket. Please reopen it if needed or a clear testcase exists