#49040 deadlock reading and writing changelog
Closed: wontfix by spichugi. Opened by lkrispen.

There is a race condition where the agreement thread reading the changelog and a thread wanting to write to the changelog can deadlock.

The writing thread will at some time be aborted by deadlock detection and the write operation will fail. If the failing operation is a replicated op, the supplier sees an error and should retry (fixed in #47788).

Here are the outputs from db_stat -C A and the pstacks:

       f READ          1 WAIT    /home/lkrispen/TEST/gen/install/var/lib/dirsrv/slapd-master_2/changelogdb/871ec08a-ab3311e6-af0b92e2-4afa8425_582b06fa000000010000.db page         10
       f READ          2 HELD    /home/lkrispen/TEST/gen/install/var/lib/dirsrv/slapd-master_2/changelogdb/871ec08a-ab3311e6-af0b92e2-4afa8425_582b06fa000000010000.db page         11
800001d5 dd= 0 locks held 23   write locks 18   pid/thread 20380/139809045513984 flags 0    priority 100
800001d5 WRITE         1 HELD    userRoot/id2entry.db      page          9
800001d5 WRITE         1 HELD    userRoot/memberOf.db      page          1
800001d5 WRITE         1 HELD    /home/lkrispen/TEST/gen/install/var/lib/dirsrv/slapd-master_2/changelogdb/871ec08a-ab3311e6-af0b92e2-4afa8425_582b06fa000000010000.db page         10
800001d5 READ          2 HELD    userRoot/objectclass.db   page          1
800001d5 READ          3 HELD    userRoot/member.db        page          1
800001d5 WRITE         1 HELD    userRoot/numsubordinates.db page          1
800001d5 WRITE         1 HELD    userRoot/id2entry.db      page          3
800001d5 WRITE         1 HELD    userRoot/entryrdn.db      page          2
800001d5 WRITE         2 HELD    userRoot/entryrdn.db      page          3
800001d5 WRITE         2 HELD    userRoot/ancestorid.db    page          1
800001d5 WRITE         1 HELD    userRoot/parentid.db      page          1
800001d5 WRITE         1 HELD    userRoot/nsuniqueid.db    page          1
800001d5 WRITE         4 HELD    userRoot/cn.db            page          3
800001d5 WRITE         5 HELD    userRoot/cn.db            page          2
800001d5 WRITE         6 HELD    userRoot/cn.db            page          4
800001d5 WRITE         1 HELD    userRoot/member.db        page          1
800001d5 WRITE        15 HELD    userRoot/owner.db         page          2
800001d5 WRITE        35 HELD    userRoot/owner.db         page          3
800001d5 WRITE         2 HELD    userRoot/objectclass.db   page          1
800001d5 WRITE         1 HELD    userRoot/id2entry.db      page         10
800001d5 READ          3 HELD    userRoot/entryrdn.db      page          2
800001d5 READ          8 HELD    userRoot/entryrdn.db      page          3
800001d5 READ          5 HELD    userRoot/nsuniqueid.db    page          1
800001df dd= 0 locks held 0    write locks 0    pid/thread 20380/139809045513984 flags 0    priority 100
800001df WRITE         1 WAIT    /home/lkrispen/TEST/gen/install/var/lib/dirsrv/slapd-master_2/changelogdb/871ec08a-ab3311e6-af0b92e2-4afa8425_582b06fa000000010000.db page         11
Thread 36 (Thread 0x7f27ee74d700 (LWP 20389)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f27f93f80fb in __db_pthread_mutex_condwait (env=0x1dd4950, mutex=139809764762870, timespec=0x0, mutexp=<optimized out>) at ../../src/mutex/mut_pthread.c:321
#2  __db_hybrid_mutex_suspend (env=env@entry=0x1dd4950, mutex=mutex@entry=2209, timespec=timespec@entry=0x0, exclusive=exclusive@entry=1) at ../../src/mutex/mut_pthread.c:577
#3  0x00007f27f93f752f in __db_tas_mutex_lock_int (nowait=0, timeout=0, mutex=2209, env=<optimized out>) at ../../src/mutex/mut_tas.c:255
#4  __db_tas_mutex_lock (env=env@entry=0x1dd4950, mutex=2209, timeout=timeout@entry=0) at ../../src/mutex/mut_tas.c:286
#5  0x00007f27f94a1c97 in __lock_get_internal (lt=lt@entry=0x1f17ab0, sh_locker=sh_locker@entry=0x7f27f26459e0, flags=flags@entry=0, obj=<optimized out>, lock_mode=<optimized out>, timeout=0, lock=0x7f27ee74c718) at ../../src/lock/lock.c:989
#6  0x00007f27f94a2f21 in __lock_vec (env=env@entry=0x1dd4950, sh_locker=0x7f27f26459e0, flags=<optimized out>, list=list@entry=0x7f27ee74c700, nlist=nlist@entry=2, elistp=elistp@entry=0x7f27ee74c6f8) at ../../src/lock/lock.c:140
#7  0x00007f27f94ce236 in __db_lget (dbc=dbc@entry=0x209fc70, action=<optimized out>, action@entry=2, pgno=10, mode=<optimized out>, mode@entry=DB_LOCK_READ, lkflags=lkflags@entry=0, lockp=lockp@entry=0x209f5d8) at ../../src/db/db_meta.c:1284
#8  0x00007f27f93ff54b in __bamc_next (dbc=dbc@entry=0x209fc70, initial_move=initial_move@entry=0, deleted_okay=deleted_okay@entry=1) at ../../src/btree/bt_cursor.c:2484
#9  0x00007f27f9403e0b in __bam_bulk (dbc=0x209fc70, data=0x7f27e000dcc0, flags=<optimized out>) at ../../src/btree/bt_cursor.c:1479
#10 0x00007f27f94bb182 in __dbc_iget (dbc=0x2089900, key=0x7f27e000dc98, data=0x7f27e000dcc0, flags=16) at ../../src/db/db_cam.c:1119
#11 0x00007f27f94bb54d in __dbc_get (dbc=dbc@entry=0x2089900, key=key@entry=0x7f27e000dc98, data=data@entry=0x7f27e000dcc0, flags=flags@entry=16400) at ../../src/db/db_cam.c:770
#12 0x00007f27f94c9ef2 in __dbc_get_pp (dbc=0x2089900, key=0x7f27e000dc98, data=0x7f27e000dcc0, flags=16400) at ../../src/db/db_iface.c:2361
#13 0x00007f27f6d0c17e in clcache_cursor_get (cursor=0x2089900, buf=0x7f27e000dc50, flag=16) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_clcache.c:1070
#14 0x00007f27f6d0a6b0 in clcache_load_buffer_bulk (buf=0x7f27e000dc50, flag=16) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_clcache.c:418
#15 0x00007f27f6d0a498 in clcache_load_buffer (buf=0x7f27e000dc50, anchorCSN=0x7f27ee74cb28) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_clcache.c:346
#16 0x00007f27f6d071cd in _cl5PositionCursorForReplay (consumerRID=1, consumerRuv=0x7f27e000d9c0, replica=0x2071570, fileObj=0x209d200, iterator=0x7f27ee74cc20) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_api.c:5596
#17 0x00007f27f6cfe21c in cl5CreateReplayIterator (prp=0x2042120, consumerRuv=0x7f27e000d9c0, iterator=0x7f27ee74cc20) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_api.c:1600
#18 0x00007f27f6d28039 in send_updates (prp=0x2042120, remote_update_vector=0x7f27e000d9c0, num_changes_sent=0x7f27ee74cd48) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/repl5_inc_protocol.c:1621
#19 0x00007f27f6d26e3d in repl5_inc_run (prp=0x2042120) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/repl5_inc_protocol.c:1083
#20 0x00007f27f6d2f5e3 in prot_thread_main (arg=0x209ed00) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/repl5_protocol.c:267
#21 0x00007f27ffc3265b in _pt_root () from /lib64/libnspr4.so
#22 0x00007f27ff5d1555 in start_thread (arg=0x7f27ee74d700) at pthread_create.c:333
#23 0x00007f27ff30cb9d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 9 (Thread 0x7f27d47e8700 (LWP 20416)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f27f93f80fb in __db_pthread_mutex_condwait (env=0x1dd4950, mutex=139809764762870, timespec=0x0, mutexp=<optimized out>) at ../../src/mutex/mut_pthread.c:321
#2  __db_hybrid_mutex_suspend (env=env@entry=0x1dd4950, mutex=mutex@entry=2300, timespec=timespec@entry=0x0, exclusive=exclusive@entry=1) at ../../src/mutex/mut_pthread.c:577
#3  0x00007f27f93f752f in __db_tas_mutex_lock_int (nowait=0, timeout=0, mutex=2300, env=<optimized out>) at ../../src/mutex/mut_tas.c:255
#4  __db_tas_mutex_lock (env=env@entry=0x1dd4950, mutex=2300, timeout=timeout@entry=0) at ../../src/mutex/mut_tas.c:286
#5  0x00007f27f94a1c97 in __lock_get_internal (lt=lt@entry=0x1f17ab0, sh_locker=sh_locker@entry=0x7f27f2646320, flags=flags@entry=0, obj=<optimized out>, lock_mode=<optimized out>, timeout=timeout@entry=0, lock=0x7f27d47e6b60) at ../../src/lock/lock.c:989
#6  0x00007f27f94a2727 in __lock_get (env=env@entry=0x1dd4950, locker=0x7f27f2646320, flags=0, obj=obj@entry=0x7f2764023660, lock_mode=lock_mode@entry=DB_LOCK_WRITE, lock=lock@entry=0x7f27d47e6b60) at ../../src/lock/lock.c:469
#7  0x00007f27f94ce4c7 in __db_lget (dbc=dbc@entry=0x7f2764023570, action=action@entry=0, pgno=11, mode=mode@entry=DB_LOCK_WRITE, lkflags=lkflags@entry=0, lockp=lockp@entry=0x7f27d47e6b60) at ../../src/db/db_meta.c:1257
#8  0x00007f27f9415222 in __bam_search (dbc=dbc@entry=0x7f2764023570, root_pgno=root_pgno@entry=1, key=key@entry=0x7f27d47e6f70, flags=flags@entry=12802, slevel=slevel@entry=1, recnop=recnop@entry=0x0, exactp=0x7f27d47e6cdc) at ../../src/btree/bt_search.c:723
#9  0x00007f27f93fff0c in __bamc_search (dbc=dbc@entry=0x7f2764023570, root_pgno=1, key=key@entry=0x7f27d47e6f70, flags=<optimized out>, exactp=exactp@entry=0x7f27d47e6cdc) at ../../src/btree/bt_cursor.c:2804
#10 0x00007f27f940478f in __bamc_put (dbc=0x7f2764023570, key=0x7f27d47e6f70, data=0x7f2764020320, flags=14, pgnop=0x7f27d47e6d54) at ../../src/btree/bt_cursor.c:2143
#11 0x00007f27f94bb5dc in __dbc_iput (dbc=0x7f2764023570, key=0x7f27d47e6f70, data=0x7f2764020320, flags=14) at ../../src/db/db_cam.c:2136
#12 0x00007f27f94bd8dd in __dbc_put (dbc=<optimized out>, key=key@entry=0x7f27d47e6f70, data=data@entry=0x7f2764020320, flags=<optimized out>, flags@entry=0) at ../../src/db/db_cam.c:2049
#13 0x00007f27f94b68d5 in __db_put (dbp=dbp@entry=0x2088980, ip=<optimized out>, txn=<optimized out>, key=key@entry=0x7f27d47e6f70, data=data@entry=0x7f2764020320, flags=flags@entry=0) at ../../src/db/db_am.c:583
#14 0x00007f27f94cc563 in __db_put_pp (dbp=0x2088980, txn=0x7f276401d8e0, key=0x7f27d47e6f70, data=0x7f2764020320, flags=<optimized out>) at ../../src/db/db_iface.c:1663
#15 0x00007f27f6d062cb in _cl5WriteOperationTxn (replName=0x20420f0 "871ec08a-ab3311e6-af0b92e2-4afa8425", replGen=0x7f2764017330 "582b06fa000000010000", op=0x7f276401ca50, local=0, txn=0x7f2764006ca0) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_api.c:5153
#16 0x00007f27f6cfdf01 in cl5WriteOperationTxn (replName=0x20420f0 "871ec08a-ab3311e6-af0b92e2-4afa8425", replGen=0x7f2764017330 "582b06fa000000010000", op=0x7f276401ca50, local=0, txn=0x7f2764006ca0) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/cl5_api.c:1431
#17 0x00007f27f6d2e0dc in write_changelog_and_ruv (pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/repl5_plugins.c:1158
#18 0x00007f27f6d2d9d6 in multimaster_be_betxnpostop_add (pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/plugins/replication/repl5_plugins.c:923
#19 0x00007f280187d892 in plugin_call_func (list=0x1d97c80, operation=560, pb=0x7f27d47e7b40, call_one=0) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/plugin.c:2066
#20 0x00007f280187d6fb in plugin_call_list (list=0x1d5f8d0, operation=560, pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/plugin.c:2008
#21 0x00007f2801879a43 in plugin_call_plugins (pb=0x7f27d47e7b40, whichfunction=560) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/plugin.c:446
#22 0x00007f27f6ffdbb1 in ldbm_back_add (pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/back-ldbm/ldbm_add.c:1158
#23 0x00007f280180b957 in op_shared_add (pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/add.c:700
#24 0x00007f280180a923 in do_add (pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/add.c:227
#25 0x00000000004167c5 in connection_dispatch_operation (conn=0x7f2801c25410, op=0x207d760, pb=0x7f27d47e7b40) at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/connection.c:606
#26 0x0000000000418879 in connection_threadmain () at /home/lkrispen/TEST/gen/workspaces2/389-ds-base/ds/ldap/servers/slapd/connection.c:1760
#27 0x00007f27ffc3265b in _pt_root () from /lib64/libnspr4.so
#28 0x00007f27ff5d1555 in start_thread (arg=0x7f27d47e8700) at pthread_create.c:333
#29 0x00007f27ff30cb9d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Metadata Update from @lkrispen:
- Issue set to the milestone: FUTURE

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 issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/2099

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix
- Issue status updated to: Closed (was: Open)

Metadata