Package: slapd
Version: 2.4.44+dfsg-5+deb9u1
Severity: normal
Dear Maintainer,
A partial replica slave crashed with
Apr 3 14:53:51 birch kernel: [1906479.552078] slapd[4515]: segfault at 4c ip 00007f71abdbfc9b sp 00007f716f184780 error 4 in back_mdb-2.4.so.2.10.7[7f71abdb0000+39000]
Unfortunately it didn't create a core file, but I lifted the limit now.
Based on the very little data in the kernel message, it was caused by a wrong
pointer in the mdb_modify_internal() function at offset 299:
96 for ( ml = modlist; ml != NULL; ml = ml->sml_next ) {
0x000000000000fc8e <+286>: mov 0x30(%rbx),%rbx /* ml = ml->sml_next */
0x000000000000fc92 <+290>: test %rbx,%rbx /* exit if NULL */
0x000000000000fc95 <+293>: je 0x10410 <mdb_modify_internal+2208>
97 int match;
98 mod = &ml->sml_mod; /* mod = ml */
99 switch( mod->sm_op ) {
0x000000000000fc9b <+299>: movzwl 0x1c(%rbx),%eax /* read mod->sm_op */
0x000000000000fc9f <+303>: test %ax,%ax /* test for LDAP_MOD_ADD */
0x000000000000fca2 <+306>: jne 0xfc88 <mdb_modify_internal+280>
As far as I understand it, ml (in %rbx) must have been 0x30=0x4c-0x1c
there, which is an invalid value. By coincidence, the offset of
sml_next is also 0x30 in the structure pointed to by ml, because the
size of struct Modification (ml->sml_mod) is 0x30 bytes. I can't see
how these quantities could enter %rbx, though, just noting it.
Does this ring any bells? This crash does not happen frequently, so I
decided to report this little info now, but I'll add more as I got any.
Hello Ferenc, Not familiar to me, nor to upstream based on the information provided. Feel free to remove the 'moreinfo' tag if it happens again and you're able to capture a core or stacktrace. Thank you Ryan
Control: tag -1 - moreinfo
Hi Ryan,
One and a half year later, and I've got a core dump! Stretch system,
slapd 2.4.44+dfsg-5+deb9u3, segmentation fault at the same point, but
with a different value:
Dec 19 10:31:40 birch slapd[19274]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE - NEW_COOKIE
Dec 19 10:31:40 birch slapd[19274]: do_syncrep2: rid=001 NEW_COOKIE: rid=001,csn=20191219093138.816310Z#000000#000#000000
Dec 19 10:31:40 birch slapd[19274]: slap_queue_csn: queueing 0x7ff460102d90 20191219093138.816310Z#000000#000#000000
Dec 19 10:31:40 birch slapd[19274]: slap_graduate_commit_csn: removing 0x7ff460102d90 20191219093138.816310Z#000000#000#000000
Dec 19 10:31:59 birch slapd[19274]: do_syncrep2: rid=001 cookie=rid=001,csn=20191219093159.802851Z#000000#000#000000
Dec 19 10:31:59 birch slapd[19274]: syncrepl_message_to_entry: rid=001 DN: uid=jeszenszkya,ou=users,o=niifi,o=niif,c=hu, UUID: 6eb0ba40-14b1-1039-9559-11af45fdb739
Dec 19 10:31:59 birch slapd[19274]: syncrepl_entry: rid=001 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY)
Dec 19 10:31:59 birch slapd[19274]: syncrepl_entry: rid=001 be_search (0)
Dec 19 10:31:59 birch slapd[19274]: syncrepl_entry: rid=001 uid=jeszenszkya,ou=users,o=niifi,o=niif,c=hu
Dec 19 10:31:59 birch slapd[19274]: slap_queue_csn: queueing 0x7ff46c11d760 20191219093159.802851Z#000000#000#000000
Dec 19 10:31:59 birch kernel: [3068983.104734] slapd[19276]: segfault at 80b9542009 ip 00007ff4b7304c9b sp 00007ff47a6c9700 error 4 in back_mdb-2.4.so.2.10.7[7ff4b72f5000+39000]
Some random info that looked useful at first sight:
(gdb) bt
#0 mdb_modify_internal (op=op@entry=0x7ff47a6ca760, tid=tid@entry=0x5652a1c04f50,
modlist=0x7ff46c11d8d0, e=e@entry=0x7ff47a6c9850, text=text@entry=0x7ff47a6ca020,
textbuf=textbuf@entry=0x7ff47a6c98d0 "\024", textlen=256)
at ../../../../../servers/slapd/back-mdb/modify.c:99
#1 0x00007ff4b7307f8e in mdb_modrdn (op=0x7ff47a6ca760, rs=0x7ff47a6ca000)
at ../../../../../servers/slapd/back-mdb/modrdn.c:509
#2 0x00005652a06cb040 in overlay_op_walk (op=op@entry=0x7ff47a6ca760, rs=0x7ff47a6ca000,
which=op_modrdn, oi=0x5652a1a2a850, on=<optimized out>)
at ../../../../servers/slapd/backover.c:677
#3 0x00005652a06cb19d in over_op_func (op=0x7ff47a6ca760, rs=<optimized out>, which=<optimized out>)
at ../../../../servers/slapd/backover.c:730
#4 0x00005652a06c29df in syncrepl_entry (syncCSN=0x7ff46c115400, syncUUID=0x7ff47a6ca070,
syncstate=<optimized out>, modlist=0x7ff47a6c9d30, entry=0x5652a19a8f38, op=0x7ff47a6ca760,
si=0x5652a1a39600) at ../../../../servers/slapd/syncrepl.c:3273
#5 do_syncrep2 (op=op@entry=0x7ff47a6ca760, si=si@entry=0x5652a1a39600)
at ../../../../servers/slapd/syncrepl.c:1040
#6 0x00005652a06c4134 in do_syncrepl (ctx=ctx@entry=0x7ff47a6cac10, arg=arg@entry=0x5652a1a21e90)
at ../../../../servers/slapd/syncrepl.c:1564
#7 0x00005652a065deed in connection_read_thread (ctx=0x7ff47a6cac10, argv=0xb)
at ../../../../servers/slapd/connection.c:1296
#8 0x00007ff4bbe3efda in ?? () from /usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2
#9 0x00007ff4ba3a74a4 in start_thread (arg=0x7ff47a6cb700) at pthread_create.c:456
#10 0x00007ff4ba0e9d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
(gdb) p *modlist
$9 = {sml_mod = {sm_desc = 0x5652a198dc00, sm_values = 0x7ff46c11d910, sm_nvalues = 0x7ff46c11d960,
sm_numvals = 1, sm_op = 1, sm_flags = 0, sm_type = {bv_len = 0, bv_val = 0x0}},
sml_next = 0x7ff46c11d7f0}
(gdb) p *modlist->sml_next
$10 = {sml_mod = {sm_desc = 0x5652a198dc00, sm_values = 0x7ff46c11d830, sm_nvalues = 0x7ff46c11d880,
sm_numvals = 1, sm_op = 4096, sm_flags = 0, sm_type = {bv_len = 0, bv_val = 0x0}},
sml_next = 0x80b9541fed}
(gdb) p mod
$12 = (Modification *) 0x80b9541fed
(gdb) p &mod->sm_op
$13 = (short *) 0x80b9542009
The end of the console output:
$ /usr/sbin/slapd -h ldapi:/// -F /etc/ldap/slapd.d -d Stats,Stats2
[...]
5dfb4079 conn=1001 op=4783 SRCH base="o=niifi,o=niif,c=hu" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=jsj))"
5dfb4079 conn=1001 op=4783 SRCH attr=uidNumber cn gecos uid objectClass homeDirectory gidNumber loginShell
5dfb4079 conn=1001 op=4783 SEARCH RESULT tag=101 err=0 nentries=0 text=
Segmentation fault
I'm ready to extract more info from the core dump or provide the
configuration if needed. In short, it's a partial replica (constrained
by ACLs) from a wheezy slapd (2.4.40-4~bpo70+2).
Yay! I guess the problem here is the "sml_next" value. I have not reproduced the crash yet, but for a start I am looking at "m2" on syncrepl.c:3236. With your coredump, could you dig a little further into the two "sml_mod" structures and show their sm_desc/sm_values/sm_nvalues? (For the "sm_op" values, 1 is LDAP_MOD_DELETE and 4096 is SLAP_MOD_SOFTADD.) Also, if the frame is still valid, the contents of "dni" in syncrepl_entry (frame #4) would be useful too. Thanks!
Ryan Tandy <ryan@nardis.ca> writes:
Sure:
(gdb) p *modlist->sml_mod.sm_desc
$8 = {ad_next = 0x0, ad_type = 0x5652a198da20, ad_cname = {bv_len = 3, bv_val = 0x5652a198d900 "uid"}, ad_tags = {bv_len = 0, bv_val = 0x0}, ad_flags = 0,
ad_index = 47}
(gdb) p *modlist->sml_mod.sm_values
$9 = {bv_len = 12, bv_val = 0x7ff46c11d940 "jeszenszkyan"}
(gdb) p *modlist->sml_mod.sm_nvalues
$10 = {bv_len = 12, bv_val = 0x7ff46c11d990 "jeszenszkyan"}
and
(gdb) p *modlist->sml_next->sml_mod.sm_desc
$11 = {ad_next = 0x0, ad_type = 0x5652a198da20, ad_cname = {bv_len = 3, bv_val = 0x5652a198d900 "uid"}, ad_tags = {bv_len = 0, bv_val = 0x0},
ad_flags = 0, ad_index = 47}
(gdb) p *modlist->sml_next->sml_mod.sm_values
$12 = {bv_len = 11, bv_val = 0x7ff46c11d860 "jeszenszkya"}
(gdb) p *modlist->sml_next->sml_mod.sm_nvalues
$13 = {bv_len = 11, bv_val = 0x7ff46c11d8b0 "jeszenszkya"}
Makes sense, I guess...
(gdb) up
#4 0x00005652a06c29df in syncrepl_entry (syncCSN=0x7ff46c115400, syncUUID=0x7ff47a6ca070, syncstate=<optimized out>, modlist=0x7ff47a6c9d30,
entry=0x5652a19a8f38, op=0x7ff47a6ca760, si=0x5652a1a39600) at ../../../../servers/slapd/syncrepl.c:3273
3273 rc = op->o_bd->be_modrdn( op, &rs_modify );
(gdb) p dni
$14 = {new_entry = 0x5652a19a8f38, dn = {bv_len = 45, bv_val = 0x7ff46c000ff0 "uid=jeszenszkyan,ou=users,o=niifi,o=niif,c=hu"}, ndn = {bv_len = 45,
bv_val = 0x7ff46c001028 "uid=jeszenszkyan,ou=users,o=niifi,o=niif,c=hu"}, nnewSup = {bv_len = 0, bv_val = 0x0}, renamed = 1, delOldRDN = 1,
modlist = 0x7ff47a6c9d30, mods = 0x0, oldNcount = 1, oldDesc = 0x5652a198dc00, newDesc = 0x5652a198dc00}
(gdb) p *dni.new_entry
$16 = {e_id = 0, e_name = {bv_len = 44, bv_val = 0x7ff46c115430 "uid=jeszenszkya,ou=users,o=niifi,o=niif,c=hu"}, e_nname = {bv_len = 44,
bv_val = 0x7ff46c1191c0 "uid=jeszenszkya,ou=users,o=niifi,o=niif,c=hu"}, e_attrs = 0x5652a19bed90, e_ocflags = 0, e_bv = {bv_len = 0, bv_val = 0x0},
e_private = 0x0}
(gdb) p dni.modlist->sml_mod
$18 = {sm_desc = 0x5652a198d870, sm_values = 0x7ff46c119200, sm_nvalues = 0x7ff46c8bd960, sm_numvals = 1, sm_op = 2, sm_flags = 0, sm_type = {bv_len = 2,
bv_val = 0x7ff46c114aed "cn"}}
(gdb) p dni.modlist->sml_mod.sm_desc
$19 = (AttributeDescription *) 0x5652a198d870
(gdb) p *dni.modlist->sml_mod.sm_desc
$20 = {ad_next = 0x5652a1bfcf80, ad_type = 0x5652a198d650, ad_cname = {bv_len = 2, bv_val = 0x5652a198d590 "cn"}, ad_tags = {bv_len = 0, bv_val = 0x0},
ad_flags = 0, ad_index = 46}
(gdb) p *dni.modlist->sml_mod.sm_values
$21 = {bv_len = 16, bv_val = 0x7ff46c10d5c0 "Jeszenszky Andor"}
(gdb) p *dni.modlist->sml_mod.sm_nvalues
$22 = {bv_len = 16, bv_val = 0x7ff46c8bd990 "jeszenszky andor"}
[...]
(gdb) p dni.modlist->sml_next->sml_next->sml_next->sml_next->sml_next->sml_next->sml_next->sml_next
$32 = (Modifications *) 0x0
(gdb) p *dni.oldDesc
$34 = {ad_next = 0x0, ad_type = 0x5652a198da20, ad_cname = {bv_len = 3, bv_val = 0x5652a198d900 "uid"}, ad_tags = {bv_len = 0, bv_val = 0x0},
ad_flags = 0, ad_index = 47}
Hope this helps.