Re: (ITS#5439) syncprov race condition seg. fault

[rein@basefarm.no]

On Tue, 25 Mar 2008, hyc@symas.com wrote:

> rein@basefarm.no wrote:

>> We have bin hit by what looks like a race condition bug in syncprov.  We got
>> some core dumps all showing stack frames like the one at the end.  As such nasty
>> bugs tends to do it have behaved OK after I restarted slapd with more debug
>> output :-( (trace + stats + stats2 + sync).
>>
>>
>> Note the a=0xBAD argument to attr_find(), which I expect is the result of some
>> other thread freeing the attribute list it was called with while it was
>> processing it.  The rs->sr_entry->e_attrs argument passed to attr_find() as the
>> original "a" argument by findpres_cb() looks like a perfectly valid structure,
>> as are all the attributes found by following the a_next pointer.  The list is
>> terminated by an attribute with a NULL a_next value, none of the a_next values
>> are 0xBAD.
>
> I don't believe that's the cause. Notice that arg0 in stack frame #9 is also
> 0xbad, even though it is shown correctly in frames 8 and 10. Something else is
> going on.

I don't know how I managed to overlook the strange 0xbad argument in
frame #9, and I really haven't any explanation as to why it shows that
value.  But if I am on the right track in my assumptions below I
currently writes is off as an unexpected result of optimization.

It now looks to me as if the entire rs->sr_entry was released an reused,
and that the bug probably is in back-bdb.  It just always happened when
syncprov was running as this is a master server with mostly writes
except from the reads syncprov does.  Which also means that the title on
the bug report is probably misleading :-(

The reason for my shift of focus is some highly suspicious variables
found in the bdb_search() frame.

First, ei->bei_e seem to be NULL every time this happen, not the same as
the "e" variable as I would except from looking at the code.  Second,
e->e_id is either 0 or ei->bei_id+1, the content of *e is the (more or
less completely initialized) entry following the *ei entry in the
database, while I would expect that ei->bei_id==e->e_id and that
ei->bei_e==e.  I don't think the consecutive ID numbers or entries has
anything with the bug to do though, they are probably a result of the
searches reading the entire database.

I looks to me as if the EntryInfo referred to by ei was released somehow
when slap_send_search_entry() was running, and that the ei->bei_e passed
as rs->rs_entry was first released and then reused for the next entry.
Alternatively that the structures wasn't properly initialized and
thereby appeared free to the second thread.

I have found a core file that adds to my suspicions, this time with two
active threads.  Their stack frames are shown at the end.  In this core
file the id variable in the bdb_search() frame is 9318, the second
thread is loading id==9319.  The value of the "e" variable in
bdb_search() for the first thread equals the "x" variable of the
entry_decode() frame in the second thread.  Since entry_decode() has
just allocated its "x" value it shouldn't have found the same value as
the other thread has unless someone released its "e" entry while it was
still using it.  Why this happened I haven't figured out yet.

The cachsesize directive has its default value, which is way below the
optimal value.  The result is that the cache is always full.  I don't
know if that can have any influence on the bug?  I tried to lower its
value to see if that should help reproducing the problem, but not so
far.

>> I'm currently trying to gather more information related to this bug, any
>> pointers as to what I should look for is appreciated.  I'm posting this bug
>> report now in the hope that the stack frame should enlighten someone with better
>> knowledge of the code than what I have.
>
> Check for stack overruns, compile without optimization and make sure it's not
> a compiler optimization bug, etc.

I'll try to run it with a version compiled with only -g and see if the
same thing should happen then.

Rein

Acive thread when segmentation fault occured:

#0  0x0807d03a in attr_find (a=0xbad, desc=0x81e8680) at attr.c:665
#1  0xb7a656f6 in findpres_cb (op=0xac05cba4, rs=0xac05cb68) at syncprov.c:546
#2  0x0808416d in slap_response_play (op=0xac05cba4, rs=0xac05cb68) at result.c:307
#3  0x0808555b in slap_send_search_entry (op=0xac05cba4, rs=0xac05cb68) at result.c:770
#4  0x080f2cdc in bdb_search (op=0xac05cba4, rs=0xac05cb68) at search.c:870
#5  0x080db72b in overlay_op_walk (op=0xac05cba4, rs=0xac05cb68, which=op_search, oi=0x8274218, on=0x8274318) at backover.c:653
#6  0x080dbcaf in over_op_func (op=0xac05cba4, rs=0xac05cb68, which=op_search) at backover.c:705
#7  0x080dbdef in over_op_search (op=0xac05cba4, rs=0xac05cb68) at backover.c:727
#8  0x080d9570 in glue_sub_search (op=0xac05cba4, rs=0xac05cb68, b0=0xac05cba4, on=0xac05cba4) at backglue.c:340
#9  0x080da131 in glue_op_search (op=0xbad, rs=0xac05cb68) at backglue.c:459
#10 0x080db6d5 in overlay_op_walk (op=0xac05cba4, rs=0xac05cb68, which=op_search, oi=0x8271860, on=0x8271a60) at backover.c:643
#11 0x080dbcaf in over_op_func (op=0xac05cba4, rs=0xac05cb68, which=op_search) at backover.c:705
#12 0x080dbdef in over_op_search (op=0xac05cba4, rs=0xac05cb68) at backover.c:727
#13 0xb7a65ff4 in syncprov_findcsn (op=0x85085b8, mode=FIND_PRESENT) at syncprov.c:700
#14 0xb7a670a0 in syncprov_op_search (op=0x85085b8, rs=0xac05e1c0) at syncprov.c:2277
#15 0x080db6d5 in overlay_op_walk (op=0x85085b8, rs=0xac05e1c0, which=op_search, oi=0x8271860, on=0x8271b60) at backover.c:643
#16 0x080dbcaf in over_op_func (op=0x85085b8, rs=0xac05e1c0, which=op_search) at backover.c:705
#17 0x080dbdef in over_op_search (op=0x85085b8, rs=0xac05e1c0) at backover.c:727
#18 0x08076554 in fe_op_search (op=0x85085b8, rs=0xac05e1c0) at search.c:368
#19 0x080770e4 in do_search (op=0x85085b8, rs=0xac05e1c0) at search.c:217
#20 0x08073e28 in connection_operation (ctx=0xac05e2b8, arg_v=0x85085b8) at connection.c:1084
#21 0x08074f14 in connection_read_thread (ctx=0xac05e2b8, argv=0x3d) at connection.c:1211
#22 0xb7fb5546 in ldap_int_thread_pool_wrapper (xpool=0x81ee240) at tpool.c:663
#23 0xb7c80371 in start_thread () from /lib/tls/libpthread.so.0
#24 0xb7c17ffe in clone () from /lib/tls/libc.so.6

Thead loading the next entry:

#0  0x08123ef6 in avl_find (root=0x81e7940, data=0xae7a62e8, fcmp=0x80b8871 <attr_index_name_cmp>) at avl.c:541
#1  0x080b7852 in at_bvfind (name=0xae7a62e8) at at.c:130
#2  0x080b5fd8 in slap_bv2ad (bv=0xae7a6354, ad=0xae7a6360, text=0xae7a6364) at ad.c:189
#3  0x0807eef5 in entry_decode (eh=0xae7a63bc, e=0xae7a64a8) at entry.c:859
#4  0x0810d849 in bdb_id2entry (be=0xae8666c0, tid=0x0, locker=0xb742da7c, id=9319, e=0xae7a64a8) at id2entry.c:169
#5  0x08104ffb in bdb_cache_find_id (op=0xae866ba4, tid=0x0, id=9319, eip=0xae7a6614, flag=2, locker=0xb742da7c, lock=0xae7a65f4) at cache.c:834
#6  0x080f2682 in bdb_search (op=0xae866ba4, rs=0xae866b68) at search.c:684
#7  0x080db72b in overlay_op_walk (op=0xae866ba4, rs=0xae866b68, which=op_search, oi=0x8274218, on=0x8274318) at backover.c:653
#8  0x080dbcaf in over_op_func (op=0xae866ba4, rs=0xae866b68, which=op_search) at backover.c:705
#9  0x080dbdef in over_op_search (op=0xae866ba4, rs=0xae866b68) at backover.c:727
#10 0x080d9570 in glue_sub_search (op=0xae866ba4, rs=0xae866b68, b0=0x81e7930, on=0xae866ba4) at backglue.c:340
#11 0x080da131 in glue_op_search (op=0xfffffffa, rs=0xae866b68) at backglue.c:459
#12 0x080db6d5 in overlay_op_walk (op=0xae866ba4, rs=0xae866b68, which=op_search, oi=0x8271860, on=0x8271a60) at backover.c:643
#13 0x080dbcaf in over_op_func (op=0xae866ba4, rs=0xae866b68, which=op_search) at backover.c:705
#14 0x080dbdef in over_op_search (op=0xae866ba4, rs=0xae866b68) at backover.c:727
#15 0xb7a65ff4 in syncprov_findcsn (op=0x8508e60, mode=FIND_PRESENT) at syncprov.c:700
#16 0xb7a670a0 in syncprov_op_search (op=0x8508e60, rs=0xae8681c0) at syncprov.c:2277
#17 0x080db6d5 in overlay_op_walk (op=0x8508e60, rs=0xae8681c0, which=op_search, oi=0x8271860, on=0x8271b60) at backover.c:643
#18 0x080dbcaf in over_op_func (op=0x8508e60, rs=0xae8681c0, which=op_search) at backover.c:705
#19 0x080dbdef in over_op_search (op=0x8508e60, rs=0xae8681c0) at backover.c:727
#20 0x08076554 in fe_op_search (op=0x8508e60, rs=0xae8681c0) at search.c:368
#21 0x080770e4 in do_search (op=0x8508e60, rs=0xae8681c0) at search.c:217
#22 0x08073e28 in connection_operation (ctx=0xae8682b8, arg_v=0x8508e60) at connection.c:1084
#23 0x08074f14 in connection_read_thread (ctx=0xae8682b8, argv=0x54) at connection.c:1211
#24 0xb7fb5546 in ldap_int_thread_pool_wrapper (xpool=0x81ee240) at tpool.c:663
#25 0xb7c80371 in start_thread () from /lib/tls/libpthread.so.0
#26 0xb7c17ffe in clone () from /lib/tls/libc.so.6