<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 14 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:Wingdings;
panose-1:5 0 0 0 0 0 0 0 0 0;}
@font-face
{font-family:Wingdings;
panose-1:5 0 0 0 0 0 0 0 0 0;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
p.MsoListParagraph, li.MsoListParagraph, div.MsoListParagraph
{mso-style-priority:34;
margin-top:0in;
margin-right:0in;
margin-bottom:0in;
margin-left:.5in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri","sans-serif";}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
/* List Definitions */
@list l0
{mso-list-id:409498970;
mso-list-type:hybrid;
mso-list-template-ids:-309016708 -1319183238 67698691 67698693 67698689 67698691 67698693 67698689 67698691 67698693;}
@list l0:level1
{mso-level-start-at:0;
mso-level-number-format:bullet;
mso-level-text:-;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:"Calibri","sans-serif";
mso-fareast-font-family:Calibri;
mso-bidi-font-family:"Times New Roman";}
@list l0:level2
{mso-level-number-format:bullet;
mso-level-text:o;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:"Courier New";}
@list l0:level3
{mso-level-number-format:bullet;
mso-level-text:\F0A7;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:Wingdings;}
@list l0:level4
{mso-level-number-format:bullet;
mso-level-text:\F0B7;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:Symbol;}
@list l0:level5
{mso-level-number-format:bullet;
mso-level-text:o;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:"Courier New";}
@list l0:level6
{mso-level-number-format:bullet;
mso-level-text:\F0A7;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:Wingdings;}
@list l0:level7
{mso-level-number-format:bullet;
mso-level-text:\F0B7;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:Symbol;}
@list l0:level8
{mso-level-number-format:bullet;
mso-level-text:o;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:"Courier New";}
@list l0:level9
{mso-level-number-format:bullet;
mso-level-text:\F0A7;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:Wingdings;}
ol
{margin-bottom:0in;}
ul
{margin-bottom:0in;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="blue" vlink="purple">
<div class="WordSection1">
<p class="MsoNormal">Hello,<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I’ve been experimenting with the new autoheal mode for handling cluster partitions and automatic synchronization for mirrored queues using servers hosted at Amazon EC2. My test setup is a two node cluster, with queue policy set to ha-mode=all
and ha-sync-mode=automatic. The servers are also configured with cluster_partition_handling set to autoheal, and sit behind an ELB for client access. The rest of the configuration is essentially the same as describe here
<a href="http://karlgrz.com/rabbitmq-highly-available-queues-and-clustering-using-amazon-ec2/">
http://karlgrz.com/rabbitmq-highly-available-queues-and-clustering-using-amazon-ec2/</a> with the main exception being that both of the RabbitMQ servers are in the same availability zone. The servers are hosted on m1.small instances running Ubuntu Linux 12.04.2
LTS.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">The client load is being generated from JMeter using a tunable number of client threads to send and receive messages at a steady rate to a mirrored queue. With the load balancer in place, the tests are run with enough threads to ensure
that both servers have active connections for both sending and receiving. The test sequence verifies that all message sent without encountering an error are also received.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">To simulate a network partition failure, I’ve been using iptables to temporarily block inbound and outbound access on one of the nodes to the single port configured for cluster communications through inet_dist_listen_min and inet_dist_listen_max
settings (min = max). Client access is not blocked during a simulated partition fault.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I’ve observed two anomalies during testing that I wasn’t expecting based on the documentation I’ve read:<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">-<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>At a sufficiently high message rate, some number of messages will be lost during the fault sequence, with the number lost tending to increase with message rate. No indication of a send error has been observed by the client program.
Based on results obtained from test logs and an independent monitor listening on trace messages from each node, it appears that as soon as the port is blocked, both nodes continue to accept published messages, but (temporarily) stop delivering messages until
the cluster heartbeat failure is detected, at which point the cluster is partitioned and the slave promotes itself to become master. In the sequences I’ve looked at, the messages that are lost all appear to be published to the original master (and final master
after a winner is selected during autoheal). Neither the start nor the end of the lost message window appear to line up with any events in the logs, other than the start occurring sometime after the port connection is blocked but before the cluster heartbeat
failure is detected, and the end occurring sometime after the detection of the cluster heartbeat failure and before the detection of the partitioned cluster after the connection is unblocked. Is message loss to be expected in this scenario?<o:p></o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">-<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>Occasionally the autoheal loser node fails to rejoin the cluster after restart. I don’t have a lot of data points on this one since it’s only happened a handful of times during overnight test iterations. During one failure, the autoheal
winner showed the log message below during recovery:<o:p></o:p></p>
<p class="MsoListParagraph"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=ERROR REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Mnesia('rabbit@oemsg-new-27b1524f'): ** ERROR ** mnesia_event got {inconsistent_database, running_partitioned_network, 'rabbit@oemsg-new-29b15241'}<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=INFO REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Autoheal request received from 'rabbit@oemsg-new-29b15241'<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=ERROR REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">** Generic server rabbit_node_monitor terminating<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">** Last message in was {autoheal_msg,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {request_start,'rabbit@oemsg-new-27b1524f'}}<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">** When Server state == {state,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {dict,1,16,16,8,80,48,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> []},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {{[],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> [[{rabbit,'rabbit@oemsg-new-29b15241'}|<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> #Ref<0.0.65.255337>]],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> [],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> ['rabbit@oemsg-new-29b15241'],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {dict,1,16,16,8,80,48,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> []},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {{[],[],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> [[<0.20953.18>|#Ref<0.0.65.232752>]],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> [],[],[],[],[],[],[],[],[],[],[],[],[]}}},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> undefined,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {winner_waiting,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> ['rabbit@oemsg-new-29b15241'],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> ['rabbit@oemsg-new-29b15241']}}<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">** Reason for termination ==<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">** {function_clause,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> [{rabbit_autoheal,handle_msg,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> [{request_start,'rabbit@oemsg-new-27b1524f'},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {winner_waiting,<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> ['rabbit@oemsg-new-29b15241'],<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> ['rabbit@oemsg-new-29b15241']},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> ['rabbit@oemsg-new-29b15241']]},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {rabbit_node_monitor,handle_info,2},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {gen_server,handle_msg,5},<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> {proc_lib,init_p_do_apply,3}]}<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=INFO REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Autoheal decision<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> * Partitions: [['rabbit@oemsg-new-29b15241'],['rabbit@oemsg-new-27b1524f']]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> * Winner: 'rabbit@oemsg-new-27b1524f'<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"> * Losers: ['rabbit@oemsg-new-29b15241']<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=INFO REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Autoheal request sent to 'rabbit@oemsg-new-27b1524f'<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=INFO REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Autoheal: I am the winner, waiting for ['rabbit@oemsg-new-29b15241'] to stop<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">However, I’ve also seen at least one other instance where the message about the node monitor terminating appeared but did not coincide with an autoheal failure. Comparing the two occurrences shows a somewhat different
log sequence around server shutdown and startup:<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">No autoheal failure:<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=WARNING REPORT==== 17-May-2013::01:58:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Non-AMQP exit reason 'shutdown'<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=ERROR REPORT==== 17-May-2013::01:58:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Mnesia('rabbit@oemsg-new-29b15241'): ** ERROR ** mnesia_event got {inconsistent_database, starting_partitioned_network, 'rabbit@oemsg-new-27b1524f'}<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=INFO REPORT==== 17-May-2013::01:58:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Starting RabbitMQ 3.1.0 on Erlang R14B04<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Copyright (C) 2007-2013 VMware, Inc.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Licensed under the MPL. See <a href="http://www.rabbitmq.com/">
http://www.rabbitmq.com/</a><o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Autoheal failure:<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=WARNING REPORT==== 17-May-2013::02:40:36 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Non-AMQP exit reason 'shutdown'<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">=INFO REPORT==== 17-May-2013::02:44:51 ===<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Starting RabbitMQ 3.1.0 on Erlang R14B04<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Copyright (C) 2007-2013 VMware, Inc.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Licensed under the MPL. See <a href="http://www.rabbitmq.com/">
http://www.rabbitmq.com/</a><o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Note that rabbitmq-server is started through an upstart job which attempts to respawn, so the long delay between shutdown and startup message may be related to multiple restart attempts of the process (nothing of
interest in the startup/shutdown logs).<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.5in">Any ideas around possible causes of this autoheal failure?<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.5in"><o:p> </o:p></p>
<p class="MsoNormal"><b><span style="font-size:10.0pt;font-family:"Arial","sans-serif"">Ray Maslinski<o:p></o:p></span></b></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Arial","sans-serif"">Senior Software Developer, Engineering</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Arial","sans-serif"">Valassis / Digital Media</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Arial","sans-serif"">Cell: 585.330.2426</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Arial","sans-serif"">maslinskir@valassis.com</span><o:p></o:p></p>
<p class="MsoNormal"><a href="http://www.valassis.com/"><span style="font-size:10.0pt;font-family:"Arial","sans-serif";color:windowtext">www.valassis.com</span></a><span style="font-size:10.0pt;font-family:"Arial","sans-serif""><o:p></o:p></span></p>
<p class="MsoNormal"><span style="color:#1F497D"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Arial","sans-serif";color:black">Creating the future of intelligent media delivery to drive your greatest success<br>
</span><span style="font-size:10.5pt;font-family:"Arial","sans-serif";color:black"><br>
</span><b><span style="font-size:10.0pt;font-family:"Arial","sans-serif";color:black">_____________________________________________________________________________</span></b><span style="font-size:10.0pt;font-family:"Arial","sans-serif";color:black"><br>
<br>
This message may include proprietary or protected information. If you are not the intended <o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Arial","sans-serif";color:black">recipient, please notify me, delete this message and do not further communicate the information <br>
contained herein without my express consent.<o:p></o:p></span></p>
<p class="MsoNormal"><o:p> </o:p></p>
</div>
</body>
</html>