Double free while adding entries (1.2.11 only)

[389-ds-bot]

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

• Created at 2015-09-23 20:08:58 by tbordaz (@tbordaz)
• Closed as Fixed
• Assigned to nhosoi (@nhosoi)
• Associated bugzillas
  • https://bugzilla.redhat.com/show_bug.cgi?id=1265851

---

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

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2015-09-23 20:10:08

attachment
steps.sh

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2015-09-23 20:37:53

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

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2015-09-24 04:47:09

Ticket has been cloned to Bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=1265851

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2015-10-13 04:58:03

git patch file (1.2.11 only)
0001-Ticket-48287-Double-free-while-adding-entries-1.2.11.patch

[389-ds-bot]

Comment from tbordaz (@tbordaz) at 2015-10-13 13:53:13

Hello Noriko,

Great finding and fix !!
ACK

Did you manage to reproduce with valgrind ?

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2015-10-13 21:07:56

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

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2015-10-13 23:03:27

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

[389-ds-bot]

Comment from nhosoi (@nhosoi) at 2017-02-11 22:51:58

Metadata Update from @nhosoi:

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