#48287 Double free while adding entries (1.2.11 only)
Closed: Fixed None Opened 4 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-

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 !!

Did you manage to reproduce with valgrind ?

Replying to [comment:6 tbordaz]:

Hello Noriko,

Great finding and fix !!

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:

3 years ago

Login to comment on this ticket.