<html>
<head>
<meta content="text/html; charset=ISO-8859-1"
http-equiv="Content-Type">
</head>
<body text="#000000" bgcolor="#FFFFFF">
<br>
Your analysis is most probably correct. As far as I remember, this
object reuse was confusing to me. But there were no segfaults at the
moment.<br>
<br>
Object reuse is intended to reduce memory allocations/frees, which
have big impact on performance. On the other side, locks are
expensive too. Even unsuitable for the case.<br>
<br>
Can you confirm that just duplication of event.tags solves your
segfaults? <br>
<br>
<br>
--<br>
Pavel<br>
<br>
<br>
<div class="moz-cite-prefix">07.12.2014 0:03, singh.janmejay:<br>
</div>
<blockquote
cite="mid:CAGB1VvyvgHBQ3hqb4DFJ4yD1m5VSfhQPBQTdzwgSy2SLknxScg@mail.gmail.com"
type="cite">
<div dir="ltr">Little bit of an elaborate story.<br>
<div><br>
<div>So, I was fighting a segfault for last few hours. It was
happening in freeing-up of msg. Here is backtrace (it was
the same in many core-dumps):<br>
<br>
(gdb) bt<br>
#0 0x0000000100000019 in ?? ()<br>
#1 0x00007fa23ee9d536 in lh_table_free (t=0x7fa22a28bc70)
at linkhash.c:116<br>
#2 0x00007fa23ee9a6fd in json_object_object_delete
(jso=0x7fa22967bf50) at json_object.c:273<br>
#3 0x00007fa23ee9d536 in lh_table_free (t=0x7fa2009ac960)
at linkhash.c:116<br>
#4 0x00007fa23ee9a6fd in json_object_object_delete
(jso=0x7fa22dcd8a70) at json_object.c:273<br>
#5 0x000000000041bef7 in msgDestruct
(ppThis=0x7fa2317f9b48) at msg.c:928<br>
#6 0x0000000000441bd4 in DeleteProcessedBatch
(pThis=0xa7eb90, pBatch=0xac35a8) at queue.c:1589<br>
#7 0x0000000000441c9e in DequeueConsumableElements
(pThis=0xa7eb90, pWti=0xac3570,
piRemainingQueueSize=0x7fa2317f9bd8) at queue.c:1626<br>
#8 0x0000000000441e6d in DequeueConsumable (pThis=0xa7eb90,
pWti=0xac3570) at queue.c:1680<br>
#9 0x000000000044226c in DequeueForConsumer
(pThis=0xa7eb90, pWti=0xac3570) at queue.c:1821<br>
#10 0x0000000000442502 in ConsumerReg (pThis=0xa7eb90,
pWti=0xac3570) at queue.c:1875<br>
#11 0x000000000043d95a in wtiWorker (pThis=0xac3570) at
wti.c:334<br>
#12 0x000000000043c51f in wtpWorker (arg=0xac3570) at
wtp.c:389<br>
#13 0x00007fa23f6b6b50 in start_thread (arg=<optimized
out>) at pthread_create.c:304<br>
#14 0x00007fa23e7de7bd in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112<br>
#15 0x0000000000000000 in ?? ()<br>
<br>
<br>
</div>
<div>Now, turns out, the thing lh_table_free is trying to
free(#1), is basically an object with several keys, and
whenever it failed, it failed on the last one. How do I know
that?<br>
<br>
(gdb) up 1<br>
#1 0x00007fa23ee9d536 in lh_table_free (t=0x7fa22a28bc70)
at linkhash.c:116<br>
116 linkhash.c: No such file or directory.<br>
(gdb) p *c<br>
$1 = {k = 0x7fa22dcd8a50, v = 0xa6bd20, next = 0x0, prev =
0x7fa22e93d490}<br>
<br>
</div>
<div>And out of 2 rulebases(both being called for events of
roughly the same frequency), every single segfault was for
the rulebase that was using tags on rule.<br>
<br>
</div>
<div>The rulebase in question had 2 rules, matching several
fields, and both rules had tags applied.<br>
<br>
</div>
<div>Note that ln_normalize applies event.tags only when tags
are present, and insert of new key in json-c linked-hash-map
goes in the end of the linked-list (check lh_table_insert).<br>
<br>
</div>
<div>So, this key-value pair was supposed to be 'event.tags'
and corresponding tags. The data that c was pointing to was
garbled, so I couldn't tell what the key actually is, but I
can conclude it was 'event.tags' based on size of objects.
The garbling may be because the memory allocated for key was
reused(note key is freed-up before value, check
json_object_lh_entry_free). Considering it is allocated in a
different thread (when message is parsed using mmnormalize),
it is possible (as opposed to an object allocated in the
same thread, using the same virtual-address range from one
thread only).<br>
<br>
</div>
<div>Now, what makes it a race condition? Not that event.tags
object in ln_normalize is not duplicated, instead it is the
same object with incrementing reference count. Not freeing
routine does the counter check without locking or using
atomic operation, check json_object_put.<br>
<br>
</div>
<div>The only lock that msgDestruct has, is on msg->mut,
which means different messages being processed at the same
time can get that lock and concurrently try to free
'event.tags' object.<br>
<br>
</div>
<div>With careful timing, some of them may concurrently
decrement the counter and one of them may free the object.
Now segfault can happen either because someone accesses it,
or because someone tries to free it again etc.<br>
<br>
</div>
<div>For me, the segfault was reproducing every few hours.<br>
<br>
</div>
<div>The solution is simple, we need to duplicate the
event.tags object instead of passing it on with incrementing
reference count.<br>
<br>
</div>
<div>I'll fix it, but before jumping to fix need another
(few?) pairs of eyes to check correctness in reasoning (to
point out any mistakes in analysis and ensure I haven't
overlooked anything and misdiagnosed).<br>
<br>
</div>
<div>Can someone please help validate/correct?<br>
</div>
<div><br>
-- <br>
<div class="gmail_signature">Regards,<br>
Janmejay<br>
<a moz-do-not-send="true"
href="http://codehunk.wordpress.com">http://codehunk.wordpress.com</a><br>
</div>
</div>
</div>
</div>
<br>
<fieldset class="mimeAttachmentHeader"></fieldset>
<br>
<pre wrap="">_______________________________________________
Lognorm mailing list
<a class="moz-txt-link-abbreviated" href="mailto:Lognorm@lists.adiscon.com">Lognorm@lists.adiscon.com</a>
<a class="moz-txt-link-freetext" href="http://lists.adiscon.net/mailman/listinfo/lognorm">http://lists.adiscon.net/mailman/listinfo/lognorm</a>
</pre>
</blockquote>
<br>
</body>
</html>