#48287 Double free while adding entries (1.2.11 only)
Closed: wontfix None Opened 8 years ago by tbordaz.

This problem was found while investigating https://fedorahosted.org/freeipa/ticket/5235
It was reproduced on RHEL 6.7 (389-ds-base-1.2.11.15-60.el6.x86_64)

The test case to reproduce is:
- install IPA master
- install IPA replica
- (enable core dump: yum install abrt, sysctl -w fs.suid_dumpable=1, 'ulimit -c unlimited' in /etc/sysconfig/dirsrv)
- iterate the provided script 'steps.sh'
- the master replica will crash

The crash is not systematic. On my VMs it happens once in ~[20,100] 'steps.sh'

Sometime the test case ends in breaking IPA topology (ipa user-add fails, or total init fails) without crash. It requires to reinstall the topology.

Each time (crash or IPA topology break) the following messages are logged:

[23/Sep/2015:15:31:25 +0200] NSMMReplicationPlugin - changelog program - _cl5WriteOperationTxn: retry (49) the transaction (csn=5602a9a9000000040000) failed (rc=-30994 (DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock))
[23/Sep/2015:15:31:25 +0200] NSMMReplicationPlugin - changelog program - _cl5WriteOperationTxn: failed to write entry with csn (5602a9a9000000040000); db error - -30994 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock
[23/Sep/2015:15:31:25 +0200] NSMMReplicationPlugin - write_changelog_and_ruv: can't add a change for uid=user_1809_2,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com (uniqid: 51b06805-61f711e5-a12e9486-e75d4fed, optype: 16) to changelog csn 5602a9a9000000040000

DS aborts with this stack {{{ #0 0x00007f90f5e6e625 in raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64 #1 0x00007f90f5e6fe05 in abort () at abort.c:92 #2 0x00007f90f5eac537 in __libc_message (do_abort=2, fmt=0x7f90f5f94900 "*** glibc detected *** %s: %s: 0x%s ***\n") at ../sysdeps/unix/sysv/linux/libc_fatal.c:198 #3 0x00007f90f5eb1f4e in malloc_printerr (action=3, str=0x7f90f5f929ee "free(): invalid pointer", ptr=<value optimized out>, ar_ptr=<value optimized out>) at malloc.c:6350 #4 0x00007f90f5eb4c5d in _int_free (av=0x7f90f61cbe80, p=0x7f90d82185c0, have_lock=0) at malloc.c:4836 #5 0x00007f90f83ca396 in slapi_ch_free (ptr=0x7f90d8036f70) at ldap/servers/slapd/ch_malloc.c:363 #6 0x00007f90f83c4713 in attr_done (a=0x7f90d8036f70) at ldap/servers/slapd/attr.c:379 #7 0x00007f90f83c478b in slapi_attr_free (ppa=<value optimized out>) at ldap/servers/slapd/attr.c:367 #8 0x00007f90f83c54ec in attrlist_free (alist=<value optimized out>) at ldap/servers/slapd/attrlist.c:53 #9 0x00007f90f83da610 in slapi_entry_free (e=0x7f90d8144ca0) at ldap/servers/slapd/entry.c:1974 #10 0x00007f90edbf99d8 in backentry_free (bep=0x7f90c4be1e68) at ldap/servers/slapd/back-ldbm/backentry.c:57 #11 0x00007f90edbfa57c in entrycache_add_int (cache=<value optimized out>, e=<value optimized out>, state=0, alt=<value optimized out>) at ldap/servers/slapd/back-ldbm/cache.c:1448 #12 0x00007f90edbfba5a in cache_add (cache=0x199e3b8, ptr=0x7f90a890e670, alt=0x7f90c4be1f68) at ldap/servers/slapd/back-ldbm/cache.c:1476 #13 0x00007f90edc0c2c0 in id2entry (be=0x199cf70, id=1757, txn=0x7f90c4be2040, err=<value optimized out>) at ldap/servers/slapd/back-ldbm/id2entry.c:455 #14 0x00007f90edc42203 in ldbm_back_next_search_entry_ext (pb=0x7f90a84c4d00, use_extension=0) at ldap/servers/slapd/back-ldbm/ldbm_search.c:1622 #15 0x00007f90f840a061 in iterate (pb=0x7f90a84c4d00, be=<value optimized out>, pnentries=0x7f90c4be6234, pagesize=-1, pr_statp=0x7f90c4be6228, send_result=1) at ldap/servers/slapd/opshared.c:1296 #16 0x00007f90f840a577 in send_results_ext (pb=0x7f90a84c4d00, nentries=0x7f90c4be6234, pagesize=-1, pr_stat=0x7f90c4be6228, send_result=1) at ldap/servers/slapd/opshared.c:1696 #17 0x00007f90f840b491 in op_shared_search (pb=0x7f90a84c4d00, send_result=1) at ldap/servers/slapd/opshared.c:864 #18 0x00007f90f8417dac in search_internal_callback_pb (pb=0x7f90a84c4d00, callback_data=<value optimized out>, prc=0x7f90f8417970 <internal_plugin_result_callback>, psec=0x7f90f84181f0 <internal_plugin_search_entry_callback>, prec=0x7f90f8418190 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:812 #19 0x00007f90f8417fc8 in search_internal_pb (pb=0x7f90a84c4d00) at ldap/servers/slapd/plugin_internal_op.c:665 #20 0x00007f90f056b157 in search_one_berval (baseDN=0x7f90a81f5ba0, attrName=<value optimized out>, value=<value optimized out>, requiredObjectClass=<value optimized out>, target=0x7f90a8074120) at ldap/servers/plugins/uiduniq/uid.c:322 #21 0x00007f90f056b3fb in search (baseDN=0x7f90a81f5ba0, attrName=0x19306e0 "ipaUniqueID", attr=0x7f90a8035f60, values=<value optimized out>, requiredObjectClass=0x0, target=0x7f90a8074120) at ldap/servers/plugins/uiduniq/uid.c:261 #22 0x00007f90f056b5f5 in searchAllSubtrees (argc=1, argv=<value optimized out>, attrName=0x19306e0 "ipaUniqueID", attr=0x7f90a8035f60, values=0x0, requiredObjectClass=0x0, dn=0x7f90a8074120) at ldap/servers/plugins/uiduniq/uid.c:411 #23 0x00007f90f056c276 in preop_add (pb=0x2bb8fe0) at ldap/servers/plugins/uiduniq/uid.c:645 #24 0x00007f90f8414b92 in plugin_call_func (list=0x1935550, operation=407, pb=0x2bb8fe0, call_one=0) at ldap/servers/slapd/plugin.c:1453 #25 0x00007f90f8414ddf in plugin_call_list (pb=0x2bb8fe0, whichfunction=407) at ldap/servers/slapd/plugin.c:1415 #26 plugin_call_plugins (pb=0x2bb8fe0, whichfunction=407) at ldap/servers/slapd/plugin.c:398 #27 0x00007f90f83c1c64 in op_shared_add (pb=0x2bb8fe0) at ldap/servers/slapd/add.c:669 ---Type <return> to continue, or q <return> to quit--- #28 0x00007f90f83c318d in do_add (pb=0x2bb8fe0) at ldap/servers/slapd/add.c:258 #29 0x0000000000414564 in connection_dispatch_operation () at ldap/servers/slapd/connection.c:579 #30 connection_threadmain () at ldap/servers/slapd/connection.c:2360 #31 0x00007f90f6834a83 in _pt_root (arg=0x1d15be0) at ../../../nspr/pr/src/pthreads/ptthread.c:212 #32 0x00007f90f61d7a51 in start_thread (arg=0x7f90c4bed700) at pthread_create.c:301 #33 0x00007f90f5f2496d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115 }}}

Hello Noriko,

Great finding and fix !!
ACK

Did you manage to reproduce with valgrind ?

Replying to [comment:6 tbordaz]:

Hello Noriko,

Great finding and fix !!
ACK

Did you manage to reproduce with valgrind ?

Thanks, Thierry! Actually, I could not reproduce the bug with valgrind. The issue is IPA start's timeout (I guess). DS itself has no problem to run with valgrind. But using "ipaclt start", I could not make the following KDC start successfully. I guess there's some trick to let it wait, but I gave it up there and did more research in the DS itself. I came to this conclusion in the 1.2.11 code, was to apply the change to the master, then found the same fix was there!! :)

Reviewed by Thierry (Thank you!!)

Pushed to 389-ds-base-1.2.11:
217ea08..265c6e3 389-ds-base-1.2.11 -> 389-ds-base-1.2.11
commit 265c6e3

Metadata Update from @nhosoi:
- Issue assigned to nhosoi
- Issue set to the milestone: 1.2.11.33

7 years ago

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/1618

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 (was: Fixed)

3 years ago

Login to comment on this ticket.

Metadata