<div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><br><div>I was looking into the issue and  this is what I could find while working with shyam.</div><div><br></div><div>There are 2 things here.</div><div><br></div><div>1) The multiplexed brick process for the snapshot(s) getting the client volfile (I suspect, it happened</div><div>     when restore operation was performed).</div><div>2) Memory corruption happening while the multiplexed brick process is building the graph (for the client</div><div>     volfile it got above)</div><div><br></div><div>I have been able to reproduce the issue in my local computer once, when I ran the testcase tests/bugs/snapshot/bug-1275616.t</div><div><br></div><div>Upon comparison, we found that the backtrace of the core I got and the core generated in the regression runs was similar.</div><div>In fact, the victim information shyam mentioned before, is also similar in the core that I was able to get.  </div><div><br></div><div>On top of that, when the brick process was run with valgrind, it reported following memory corruption</div><div><br></div><div><div>==31257== Conditional jump or move depends on uninitialised value(s)</div><div>==31257==    at 0x1A7D0564: mdc_xattr_list_populate (md-cache.c:3127)</div><div>==31257==    by 0x1A7D1903: mdc_init (md-cache.c:3486)</div><div>==31257==    by 0x4E62D41: __xlator_init (xlator.c:684)</div><div>==31257==    by 0x4E62E67: xlator_init (xlator.c:709)</div><div>==31257==    by 0x4EB2BEB: glusterfs_graph_init (graph.c:359)</div><div>==31257==    by 0x4EB37F8: glusterfs_graph_activate (graph.c:722)</div><div>==31257==    by 0x40AEC3: glusterfs_process_volfp (glusterfsd.c:2528)</div><div>==31257==    by 0x410868: mgmt_getspec_cbk (glusterfsd-mgmt.c:2076)</div><div>==31257==    by 0x518408D: rpc_clnt_handle_reply (rpc-clnt.c:755)</div><div>==31257==    by 0x51845C1: rpc_clnt_notify (rpc-clnt.c:923)</div><div>==31257==    by 0x518084E: rpc_transport_notify (rpc-transport.c:525)</div><div>==31257==    by 0x123273DF: socket_event_poll_in (socket.c:2504)</div><div>==31257==  Uninitialised value was created by a heap allocation</div><div>==31257==    at 0x4C2DB9D: malloc (vg_replace_malloc.c:299)</div><div>==31257==    by 0x4E9F58E: __gf_malloc (mem-pool.c:136)</div><div>==31257==    by 0x1A7D052A: mdc_xattr_list_populate (md-cache.c:3123)</div><div>==31257==    by 0x1A7D1903: mdc_init (md-cache.c:3486)</div><div>==31257==    by 0x4E62D41: __xlator_init (xlator.c:684)</div><div>==31257==    by 0x4E62E67: xlator_init (xlator.c:709)</div><div>==31257==    by 0x4EB2BEB: glusterfs_graph_init (graph.c:359)</div><div>==31257==    by 0x4EB37F8: glusterfs_graph_activate (graph.c:722)</div><div>==31257==    by 0x40AEC3: glusterfs_process_volfp (glusterfsd.c:2528)</div><div>==31257==    by 0x410868: mgmt_getspec_cbk (glusterfsd-mgmt.c:2076)</div><div>==31257==    by 0x518408D: rpc_clnt_handle_reply (rpc-clnt.c:755)</div><div>==31257==    by 0x51845C1: rpc_clnt_notify (rpc-clnt.c:923)</div></div><div><br></div><div>Based on the above observations, I think the below patch  by Shyam should fix the crash.</div><div><a href="https://review.gluster.org/#/c/glusterfs/+/21299/">https://review.gluster.org/#/c/glusterfs/+/21299/</a><br></div><div><br></div><div>But, I am still trying understand, why a brick process should get a client volfile (i.e. the 1st issue mentioned above). </div><div><br></div><div>Regards,<br>Raghavendra</div></div></div></div></div><br><div class="gmail_quote"><div dir="ltr">On Wed, Sep 26, 2018 at 9:00 PM Shyam Ranganathan &lt;<a href="mailto:srangana@redhat.com">srangana@redhat.com</a>&gt; wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">On 09/26/2018 10:21 AM, Shyam Ranganathan wrote:<br>
&gt; 2. Testing dashboard to maintain release health (new, thanks Nigel)<br>
&gt;   - Dashboard at [2]<br>
&gt;   - We already have 3 failures here as follows, needs attention from<br>
&gt; appropriate *maintainers*,<br>
&gt;     (a)<br>
&gt; <a href="https://build.gluster.org/job/regression-test-with-multiplex/871/consoleText" rel="noreferrer" target="_blank">https://build.gluster.org/job/regression-test-with-multiplex/871/consoleText</a><br>
&gt;       - Failed with core: ./tests/basic/afr/gfid-mismatch-resolution-with-cli.t<br>
&gt;     (b)<br>
&gt; <a href="https://build.gluster.org/job/regression-test-with-multiplex/873/consoleText" rel="noreferrer" target="_blank">https://build.gluster.org/job/regression-test-with-multiplex/873/consoleText</a><br>
&gt;       - Failed with core: ./tests/bugs/snapshot/bug-1275616.t<br>
&gt;       - Also test ./tests/bugs/glusterd/validating-server-quorum.t had to be<br>
&gt; retried<br>
<br>
I was looking at the cores from the above 2 instances, the one in job<br>
873 is been a typical pattern, where malloc fails as there is internal<br>
header corruption in the free bins.<br>
<br>
When examining the victim that would have been allocated, it is often<br>
carrying incorrect size and other magic information. If the data in<br>
victim is investigated it looks like a volfile.<br>
<br>
With the crash in 871, I thought there maybe a point where this is<br>
detected earlier, but not able to make headway in the same.<br>
<br>
So, what could be corrupting this memory and is it when the graph is<br>
being processed? Can we run this with ASAN or such (I have not tried,<br>
but need pointers if anyone has run tests with ASAN).<br>
<br>
Here is the (brief) stack analysis of the core in 873:<br>
NOTE: we need to start avoiding flushing the logs when we are dumping<br>
core, as that leads to more memory allocations and causes a sort of<br>
double fault in such cases.<br>
<br>
Core was generated by `/build/install/sbin/glusterfsd -s<br>
<a href="http://builder101.cloud.gluster.org" rel="noreferrer" target="_blank">builder101.cloud.gluster.org</a> --volfile-id /sn&#39;.<br>
Program terminated with signal 6, Aborted.<br>
#0  0x00007f23cf590277 in __GI_raise (sig=sig@entry=6) at<br>
../nptl/sysdeps/unix/sysv/linux/raise.c:56<br>
56        return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);<br>
(gdb) bt<br>
#0  0x00007f23cf590277 in __GI_raise (sig=sig@entry=6) at<br>
../nptl/sysdeps/unix/sysv/linux/raise.c:56<br>
#1  0x00007f23cf591968 in __GI_abort () at abort.c:90<br>
#2  0x00007f23cf5d2d37 in __libc_message (do_abort=do_abort@entry=2,<br>
fmt=fmt@entry=0x7f23cf6e4d58 &quot;*** Error in `%s&#39;: %s: 0x%s ***\n&quot;) at<br>
../sysdeps/unix/sysv/linux/libc_fatal.c:196<br>
#3  0x00007f23cf5db499 in malloc_printerr (ar_ptr=0x7f23bc000020,<br>
ptr=&lt;optimized out&gt;, str=0x7f23cf6e4ea8 &quot;free(): corrupted unsorted<br>
chunks&quot;, action=3) at malloc.c:5025<br>
#4  _int_free (av=0x7f23bc000020, p=&lt;optimized out&gt;, have_lock=0) at<br>
malloc.c:3847<br>
#5  0x00007f23d0f7c6e4 in __gf_free (free_ptr=0x7f23bc0a56a0) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/mem-pool.c:356<br>
#6  0x00007f23d0f41821 in log_buf_destroy (buf=0x7f23bc0a5568) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/logging.c:358<br>
#7  0x00007f23d0f44e55 in gf_log_flush_list (copy=0x7f23c404a290,<br>
ctx=0x1ff6010) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/logging.c:1739<br>
#8  0x00007f23d0f45081 in gf_log_flush_extra_msgs (ctx=0x1ff6010, new=0)<br>
at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/logging.c:1807<br>
#9  0x00007f23d0f4162d in gf_log_set_log_buf_size (buf_size=0) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/logging.c:290<br>
#10 0x00007f23d0f41acc in gf_log_disable_suppression_before_exit<br>
(ctx=0x1ff6010) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/logging.c:444<br>
#11 0x00007f23d0f4c027 in gf_print_trace (signum=6, ctx=0x1ff6010) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/common-utils.c:922<br>
#12 0x000000000040a84a in glusterfsd_print_trace (signum=6) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/glusterfsd/src/glusterfsd.c:2316<br>
#13 &lt;signal handler called&gt;<br>
#14 0x00007f23cf590277 in __GI_raise (sig=sig@entry=6) at<br>
../nptl/sysdeps/unix/sysv/linux/raise.c:56<br>
#15 0x00007f23cf591968 in __GI_abort () at abort.c:90<br>
#16 0x00007f23cf5d2d37 in __libc_message (do_abort=2,<br>
fmt=fmt@entry=0x7f23cf6e4d58 &quot;*** Error in `%s&#39;: %s: 0x%s ***\n&quot;) at<br>
../sysdeps/unix/sysv/linux/libc_fatal.c:196<br>
#17 0x00007f23cf5dcc86 in malloc_printerr (ar_ptr=0x7f23bc000020,<br>
ptr=0x7f23bc003cd0, str=0x7f23cf6e245b &quot;malloc(): memory corruption&quot;,<br>
action=&lt;optimized out&gt;) at malloc.c:5025<br>
#18 _int_malloc (av=av@entry=0x7f23bc000020, bytes=bytes@entry=15664) at<br>
malloc.c:3473<br>
#19 0x00007f23cf5df84c in __GI___libc_malloc (bytes=15664) at malloc.c:2899<br>
#20 0x00007f23d0f3bbbf in __gf_default_malloc (size=15664) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/mem-pool.h:106<br>
#21 0x00007f23d0f3f02f in xlator_mem_acct_init (xl=0x7f23bc082b20,<br>
num_types=163) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/xlator.c:800<br>
#22 0x00007f23b90a37bf in mem_acct_init (this=0x7f23bc082b20) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/xlators/performance/open-behind/src/open-behind.c:1189<br>
#23 0x00007f23d0f3ebe8 in xlator_init (xl=0x7f23bc082b20) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/xlator.c:700<br>
#24 0x00007f23d0f8fb5f in glusterfs_graph_init (graph=0x7f23bc010570) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/graph.c:359<br>
#25 0x00007f23d0f907ac in glusterfs_graph_activate<br>
(graph=0x7f23bc010570, ctx=0x1ff6010) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/graph.c:722<br>
#26 0x000000000040af89 in glusterfs_process_volfp (ctx=0x1ff6010,<br>
fp=0x7f23bc00b0a0) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/glusterfsd/src/glusterfsd.c:2528<br>
#27 0x000000000041094c in mgmt_getspec_cbk (req=0x7f23a4004f78,<br>
iov=0x7f23a4004fb8, count=1, myframe=0x7f23a4002b88)<br>
    at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/glusterfsd/src/glusterfsd-mgmt.c:2076<br>
#28 0x00007f23d0d0617d in rpc_clnt_handle_reply (clnt=0x2077910,<br>
pollin=0x7f23bc001e80) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/rpc/rpc-lib/src/rpc-clnt.c:755<br>
#29 0x00007f23d0d066ad in rpc_clnt_notify (trans=0x2077c70,<br>
mydata=0x2077940, event=RPC_TRANSPORT_MSG_RECEIVED, data=0x7f23bc001e80)<br>
    at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/rpc/rpc-lib/src/rpc-clnt.c:923<br>
#30 0x00007f23d0d02895 in rpc_transport_notify (this=0x2077c70,<br>
event=RPC_TRANSPORT_MSG_RECEIVED, data=0x7f23bc001e80)<br>
    at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/rpc/rpc-lib/src/rpc-transport.c:525<br>
#31 0x00007f23c5b143ff in socket_event_poll_in (this=0x2077c70,<br>
notify_handled=true) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/rpc/rpc-transport/socket/src/socket.c:2504<br>
#32 0x00007f23c5b153e0 in socket_event_handler (fd=9, idx=1, gen=1,<br>
data=0x2077c70, poll_in=1, poll_out=0, poll_err=0)<br>
    at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/rpc/rpc-transport/socket/src/socket.c:2905<br>
#33 0x00007f23d0fbd3bc in event_dispatch_epoll_handler<br>
(event_pool=0x202dc40, event=0x7f23c404bea0) at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/event-epoll.c:591<br>
#34 0x00007f23d0fbd6b5 in event_dispatch_epoll_worker (data=0x2079470)<br>
at<br>
/home/jenkins/root/workspace/regression-test-with-multiplex/libglusterfs/src/event-epoll.c:668<br>
#35 0x00007f23cfd8fe25 in start_thread (arg=0x7f23c404c700) at<br>
pthread_create.c:308<br>
#36 0x00007f23cf658bad in clone () at<br>
../sysdeps/unix/sysv/linux/x86_64/clone.S:113<br>
<br>
(gdb) p victim<br>
$1 = (struct malloc_chunk *) 0x7f23bc003cc0<br>
<br>
(gdb) x/16c (char *)victim - 16<br>
0x7f23bc003cb0: 54 &#39;6&#39;  48 &#39;0&#39;  57 &#39;9&#39;  53 &#39;5&#39;  13 &#39;\r&#39; -16 &#39;\360&#39;      -83<br>
&#39;\255&#39;  -70 &#39;\272&#39;<br>
0x7f23bc003cb8: 56 &#39;8&#39;  57 &#39;9&#39;  51 &#39;3&#39;  48 &#39;0&#39;  50 &#39;2&#39;  99 &#39;c&#39;  99 &#39;c&#39;  55 &#39;7&#39;<br>
(gdb)<br>
0x7f23bc003cc0: 50 &#39;2&#39;  52 &#39;4&#39;  47 &#39;/&#39;  98 &#39;b&#39;  114 &#39;r&#39; 105 &#39;i&#39; 99 &#39;c&#39;  107 &#39;k&#39;<br>
0x7f23bc003cc8: 33 &#39;!&#39;  4 &#39;\004&#39;        115 &#39;s&#39; 101 &#39;e&#39; 99 &#39;c&#39;  117 &#39;u&#39; 114 &#39;r&#39;<br>
105 &#39;i&#39;<br>
(gdb)<br>
0x7f23bc003cd0: 116 &#39;t&#39; 121 &#39;y&#39; 46 &#39;.&#39;  99 &#39;c&#39;  97 &#39;a&#39;  112 &#39;p&#39; 97 &#39;a&#39;  98 &#39;b&#39;<br>
0x7f23bc003cd8: 105 &#39;i&#39; 108 &#39;l&#39; 105 &#39;i&#39; 116 &#39;t&#39; 121 &#39;y&#39; 44 &#39;,&#39;  115 &#39;s&#39;<br>
101 &#39;e&#39;<br>
(gdb)<br>
0x7f23bc003ce0: 99 &#39;c&#39;  117 &#39;u&#39; 114 &#39;r&#39; 105 &#39;i&#39; 116 &#39;t&#39; 121 &#39;y&#39; 46 &#39;.&#39;<br>
105 &#39;i&#39;<br>
0x7f23bc003ce8: 109 &#39;m&#39; 97 &#39;a&#39;  44 &#39;,&#39;  117 &#39;u&#39; 115 &#39;s&#39; 101 &#39;e&#39; 114 &#39;r&#39; 46 &#39;.&#39;<br>
(gdb)<br>
0x7f23bc003cf0: 115 &#39;s&#39; 119 &#39;w&#39; 105 &#39;i&#39; 102 &#39;f&#39; 116 &#39;t&#39; 46 &#39;.&#39;  109 &#39;m&#39;<br>
101 &#39;e&#39;<br>
0x7f23bc003cf8: 116 &#39;t&#39; 97 &#39;a&#39;  100 &#39;d&#39; 97 &#39;a&#39;  116 &#39;t&#39; 97 &#39;a&#39;  44 &#39;,&#39;  0 &#39;\000&#39;<br>
_______________________________________________<br>
Gluster-devel mailing list<br>
<a href="mailto:Gluster-devel@gluster.org" target="_blank">Gluster-devel@gluster.org</a><br>
<a href="https://lists.gluster.org/mailman/listinfo/gluster-devel" rel="noreferrer" target="_blank">https://lists.gluster.org/mailman/listinfo/gluster-devel</a><br>
</blockquote></div>