[rabbitmq-users] broken cluster setup?

[Michał Gruchała]

Hi
I have a 4 node cluster (yes yes, no quorum is possible in this case) and
destroyed one node (node4).
Node4 is back now but cluster is still broken.

Issuing start_app on every node returns
Starting node '***@rabbit-1' ...
Starting node '***@rabbit-2' ...
Starting node '***@rabbit-3' ...
Starting node '***@rabbit-4' ...
Error: stop

Stopping node-4 takes ages (still waiting)
rabbit-4.atm:/# rabbitmqctl stop_app
Stopping node '***@broker-rabbit-4' ...

rabbitmqctl cluster_status issued on nodes 1,2,3 takes ages (still waiting)


report issued on node-1 returns:
Reporting server status on {{2015,7,31},{8,2,12}}

...
Status of node '***@broker-rabbit-4' ...
Error: {badarith,[{rabbit_vm,bytes,1,[]},
{rabbit_vm,'-mnesia_memory/0-lc$^0/1-0-',1,[]},
{rabbit_vm,'-mnesia_memory/0-lc$^0/1-0-',1,[]},
{rabbit_vm,mnesia_memory,0,[]},
{rabbit_vm,memory,0,[]},
{rabbit,status,0,[]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}


rabbitctl status attached


Cluster should imo recover on its own since i have
{cluster_partition_handling, autoheal}

What could be wrong in my setup?

[Michael Klishin]

Post by Michał Gruchała
I have a 4 node cluster (yes yes, no quorum is possible in this
case) and destroyed one node (node4).
Node4 is back now but cluster is still broken.
Issuing start_app on every node returns
Error: stop

It depends on the exact sequence of steps taken  but almost certainly
some nodes wait for the node you've removed but didn't tell RabbitMQ
about to return a piece of info (its memory use, according to the log below).
Then it eventually times out.

See "Breaking up a cluster" on http://www.rabbitmq.com/clustering.html: there is
a rabbitmqctl command that should be used when removing nodes from a cluster.
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

It depends on the exact sequence of steps taken but almost certainly
some nodes wait for the node you've removed but didn't tell RabbitMQ
about to return a piece of info (its memory use, according to the log below).
Then it eventually times out.

Hi
Thanks for such a quick answer.

Sentence of steps taken is as follows:
1. Machine crash simulation (xm destroy to be specific since we use xen).
2. Waited some minutes and turned machine on.
3. Issued cluster_status - no luck, hangs.
4. Issued start_app on every node (starting from 1).
5. Issued stop_app on node-4 - to see if cluster starts to work.

See "Breaking up a cluster" on http://www.rabbitmq.com/clustering.html: there
is
a rabbitmqctl command that should be used when removing nodes from a cluster.

I don't want to break a cluster. I tried to simulate hardware failure.

[Michał Gruchała]

Additional info:
I have over 100k queues, 100k consumers and more less 100 exchanges.
Still waiting for rabbitmqctl stop_app issued on node-4 to exit (Stopping
node '***@broker-rabbit-4' ...)
Seems that beam.smp on node-4 is doing nothing (uses 0 CPU, 130MB of virt
mem, network is not utilized).
Logs say nothing ;/

[Michael Klishin]

Still waiting for rabbitmqctl stop_app issued on node-4 to
Seems that beam.smp on node-4 is doing nothing (uses 0 CPU, 130MB
of virt mem, network is not utilized).
Logs say nothing ;/

Have you tried removing the node from the cluster with rabbitmqctl forget_cluster_node?

rabbitmqctl eval "rabbitmq_diagnostics:maybe_stuck()." will list processes
that seem to be making no progress.

Can you post the output of the above? (but first try properly removing the node from the cluster) 
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
Have you tried removing the node from the cluster with rabbitmqctl forget_cluster_node?

On node-1
# rabbitmqctl forget_cluster_node ***@rabbit-4
Removing node '***@rabbit-4' from cluster ...

I've waited 5 minutes but nothing happened ;/

***@rabbit-1:/home/mgruchala# rabbitmqctl eval
"rabbitmq_diagnostics:maybe_stuck()."
Error: {undef,[{rabbitmq_diagnostics,maybe_stuck,[],[]},
{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,572}]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}

Post by Michael Klishin
rabbitmqctl eval "rabbitmq_diagnostics:maybe_stuck()." will list processes
that seem to be making no progress.

On node-4 (broken one)

***@rabbit-4:/home/mgruchala# rabbitmqctl eval
"rabbitmq_diagnostics:maybe_stuck()."
Error: {undef,[{rabbitmq_diagnostics,maybe_stuck,[],[]},
{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,572}]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}

[Michael Klishin]

Post by Michał Gruchała
Error: {undef,[{rabbitmq_diagnostics,maybe_stuck,[],[]},
{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,572}]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}

rabbit_diagnostics was introduced in 3.3.5. So you're running an earlier version?
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
rabbit_diagnostics was introduced in 3.3.5. So you're running an earlier version?

Hmm

{rabbitmq_management,"RabbitMQ Management Console","3.5.3"},
{rabbitmq_management_agent,"RabbitMQ Management Agent","3.5.3"},
{rabbit,"RabbitMQ","3.5.3"},


I'm using Debian 7.8 with apt sources as follows
deb http://www.rabbitmq.com/debian/ testing main

dpkg says
rabbitmq-server 3.5.3-1

[Michael Klishin]

Post by Michał Gruchała
Error: {undef,[{rabbitmq_diagnostics,maybe_stuck,[],[]},
{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,572}]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}

it's rabbit_diagnostics, not rabbitmq_diagnostics.
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
it's rabbit_diagnostics, not rabbitmq_diagnostics.

Thx. It works now.

Node-1 is still "Removing node '***@broker-rabbit-4' from cluster ..."

[Michał Gruchała]

... and it failed ;)

Removing node '***@broker-rabbit-4' from cluster ...
Error: {failed_to_remove_node,'***@broker-rabbit-4',
{active,"Mnesia is running",
'***@broker-rabbit-4'}}

# rabbitmqctl cluster_status
Cluster status of node '***@broker-rabbit-1' ...
(waiting....)

[Michael Klishin]

Post by Michał Gruchała
Thx. It works now.
cluster ..."

node4 is waiting for its internal database to load data.

In node1, every channel is waiting on queues on node4 to confirm
that it's closing. Embarrassingly, there is no timeout for that. 

Killing node4 should unblock it. I can't tell what node4 may be stuck on
but it does explain a couple of similar reports we've seen and should be
enough to file an issue.

Would you be able to send us logs from all nodes and provide a timeline of events
that led to this state? (as detailed as possible)
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michael Klishin]

Post by Michael Klishin
should be
enough to file an issue.

https://github.com/rabbitmq/rabbitmq-server/issues/248
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
Killing node4 should unblock it. I can't tell what node4 may be stuck on
but it does explain a couple of similar reports we've seen and should be
enough to file an issue.

I killed beam.smp process on node-4 but it didn't help ;/
What to try next ?


Would you be able to send us logs from all nodes and provide a timeline of

Post by Michael Klishin
events
that led to this state? (as detailed as possible)

Sure. Attached.

[Michael Klishin]

Post by Michał Gruchała
I killed beam.smp process on node-4 but it didn't help ;/
What to try next ?

rabbitmqctl forget_cluster_node ***@node4 on node2 or node3.
Then restart node1 .
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
Then restart node1 .

***@rabbit-2:/home/mgruchala# rabbitmqctl forget_cluster_node
***@rabbit-4
Removing node '***@rabbit-4' from cluster ...

(waiting ;/)


Can you help me how to avoid such situations in the future ?
Maybe i did sth wrong during configuration ? Maybe we're using RabbitMQ in
a wrong way?

[Michael Klishin]

Post by Michał Gruchała
(waiting ;/)

and what does maybe_stuck output now for node2?

Post by Michał Gruchała
Can you help me how to avoid such situations in the future ?
Maybe i did sth wrong during configuration ? Maybe we're using
RabbitMQ in a wrong way?

This is not a matter of configuration. Use rabbitmq-clusterer [1], with it nodes
can come online in any order. As for the lacking timeouts, we have to introduce them.

1. https://github.com/rabbitmq/rabbitmq-clusterer
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin

Post by Michał Gruchała
(waiting ;/)

and what does maybe_stuck output now for node2?

Quite a large file....
https://drive.google.com/file/d/0B3Puee9GOhYaOUhnazBNTUR5RVU/view?usp=sharing

Post by Michael Klishin
This is not a matter of configuration. Use rabbitmq-clusterer [1], with it nodes
can come online in any order. As for the lacking timeouts, we have to introduce them.
1. https://github.com/rabbitmq/rabbitmq-clusterer

Thanks. Will try.
Do you think i messed up some order of commands?

[Michael Klishin]

Post by Michał Gruchała
Do you think i messed up some order of commands?

We have some ideas about what may have happened. They are primarily
implementation limitations.

For example, see "some important caveats" in the Restarting Clusters
section: http://www.rabbitmq.com/clustering.html

I'd suggest doing a rolling restart *as described in the above section*
and giving rabbitmq-clusterer a try (with 3.5.4) in the future.

node2 "maybe_stuck" output does not reveal anything, and also lists about 40%
the total processes. Sounds like its sampling interval is too small for this
many processes.

It's not clear to us why `forget_cluster_node` even with the node being down
still has to wait. 
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
I'd suggest doing a rolling restart *as described in the above section*
and giving rabbitmq-clusterer a try (with 3.5.4) in the future.

Thanks. It worked.
cluster_status claims all nodes are up and in the same partition.
Testing exchange / queue (durable) haven't been lost.

I'm going to wait a couple of minutes and crash node-2 to see if this
strange situation will happen again :)

--
Michał Gruchała

[Michał Gruchała]

Post by Michał Gruchała
I'm going to wait a couple of minutes and crash node-2 to see if this
strange situation will happen again :)

node-2 was destroyed and started again (after few minutes of being down).

***@rabbit-2:/home/mgruchala# rabbitmqctl status
Status of node '***@rabbit-2' ...
Error: {badarith,[{rabbit_vm,bytes,1,[]},
{rabbit_vm,'-mnesia_memory/0-lc$^0/1-0-',1,[]},
{rabbit_vm,'-mnesia_memory/0-lc$^0/1-0-',1,[]},
{rabbit_vm,mnesia_memory,0,[]},
{rabbit_vm,memory,0,[]},
{rabbit,status,0,[]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}

After couple of minutes it started working

***@rabbit-2/home/mgruchala# rabbitmqctl status
Status of node '***@rabbit-2' ...
[{pid,2180},
{running_applications,[{rabbit,"RabbitMQ","3.5.3"},
{os_mon,"CPO CXC 138 46","2.2.9"},
{xmerl,"XML parser","1.3.1"},
{mnesia,"MNESIA CXC 138 12","4.7"},
{sasl,"SASL CXC 138 11","2.2.1"},
{stdlib,"ERTS CXC 138 10","1.18.1"},
{kernel,"ERTS CXC 138 10","2.15.1"}]},
{os,{unix,linux}},
{erlang_version,"Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:2:2]
[async-threads:30] [kernel-poll:true]\n"},
{memory,[{total,827524800},
{connection_readers,11753288},
{connection_writers,44318448},
{connection_channels,171090776},
{connection_other,150751192},
{queue_procs,166568592},
{queue_slave_procs,0},
{plugins,0},
{other_proc,0},
{mnesia,169453048},
{mgmt_db,0},
{msg_index,565824},
{other_ets,22105400},
{binary,3935752},
{code,15329677},
{atom,561761},
{other_system,74101492}]},
{alarms,[]},
{listeners,[{clustering,25672,"::"},{amqp,5672,"::"}]},
{vm_memory_high_watermark,0.7},
{vm_memory_limit,17667167436},
{disk_free_limit,50000000},
{disk_free,9514098688},
{file_descriptors,[{total_limit,65436},
{total_used,8},
{sockets_limit,58890},
{sockets_used,6}]},
{processes,[{limit,1048576},{used,102089}]},
{run_queue,0},
{uptime,222}]


cluster_status - frozen as previously ;/

[Michael Klishin]

Post by Michał Gruchała
Error: {badarith,[{rabbit_vm,bytes,1,[]},
{rabbit_vm,'-mnesia_memory/0-lc$^0/1-0-',1,[]},
{rabbit_vm,'-mnesia_memory/0-lc$^0/1-0-',1,[]},
{rabbit_vm,mnesia_memory,0,[]},
{rabbit_vm,memory,0,[]},
{rabbit,status,0,[]},
{rpc,'-handle_call_call/6-fun-0-',5,
[{file,"rpc.erl"},{line,203}]}]}

T his is very suspicious. For some reason, RabbitMQ cannot calculate
a breakdown of RAM usage (tripping up on its internal database).

Can you post SASL log around the time you tried running rabbitmqctl status (on rabbit-2)?
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
Can you post SASL log around the time you tried running rabbitmqctl status (on rabbit-2)?

There is nothing new in sasl log ;/

general log says

=INFO REPORT==== 31-Jul-2015::16:35:59 ===
Starting RabbitMQ 3.5.3 on Erlang R15B01
Copyright (C) 2007-2014 GoPivotal, Inc.
Licensed under the MPL. See http://www.rabbitmq.com/

=INFO REPORT==== 31-Jul-2015::16:35:59 ===
node : ***@rabbit-2
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.config
cookie hash : xxx
log : /var/log/rabbitmq/***@rabbit-2.log
sasl log : /var/log/rabbitmq/***@rabbit-2-sasl.log
database dir : /var/lib/rabbitmq/mnesia/***@rabbit-2

=INFO REPORT==== 31-Jul-2015::16:35:59 ===
Memory limit set to 16848MB of 24069MB total.

=INFO REPORT==== 31-Jul-2015::16:35:59 ===
Disk free limit set to 50MB

=INFO REPORT==== 31-Jul-2015::16:35:59 ===
Limiting to approx 65436 file handles (58890 sockets)

=INFO REPORT==== 31-Jul-2015::16:36:53 ===
Priority queues enabled, real BQ is rabbit_variable_queue


=INFO REPORT==== 31-Jul-2015::16:36:53 ===
msg_store_transient: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 31-Jul-2015::16:36:53 ===
msg_store_persistent: using rabbit_msg_store_ets_index to provide index

=WARNING REPORT==== 31-Jul-2015::16:36:53 ===
msg_store_persistent: rebuilding indices from scratch

=INFO REPORT==== 31-Jul-2015::16:36:54 ===
started TCP Listener on [::]:5672

=INFO REPORT==== 31-Jul-2015::16:36:54 ===
rabbit on node '***@broker-rabbit-1' up

=INFO REPORT==== 31-Jul-2015::16:36:54 ===
Server startup complete; 0 plugins started.

=INFO REPORT==== 31-Jul-2015::16:36:54 ===
accepting AMQP connection <0.3358.0> (172.16.202.49:24872 ->
172.16.202.47:5672)

[Michael Klishin]

Post by Michał Gruchała
There is nothing new in sasl log ;/

What Erlang/OTP version do you run? Can you please confirm that it is 64 bit? 
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin
What Erlang/OTP version do you run? Can you please confirm that it is 64
bit?

Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:2:2] [async-threads:0]
[kernel-poll:false]

(cluster_status still doesn;t work)

[Michael Klishin]

Post by Michał Gruchała
Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:2:2] [async-threads:0]
[kernel-poll:false]

hm, and you have kernel polling (efficient I/O API provided by the OS)
disabled. What OS/distribution is this on?

Can you upgrade to 17.5? 
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michał Gruchała]

Post by Michael Klishin

Post by Michał Gruchała
Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:2:2] [async-threads:0]
[kernel-poll:false]

hm, and you have kernel polling (efficient I/O API provided by the OS)
disabled. What OS/distribution is this on?

To be honest i don;t know how to check it ;/

Debian 7.8

Post by Michael Klishin
Can you upgrade to 17.5?

Will try and let you know, on monday probably.

Have a nice weekend.

[Michael Klishin]

Post by Michał Gruchała
Debian 7.8

that's Wheezy as far as I understand.

Erlang Solutions has a 64 bit package for it: 
http://packages.erlang-solutions.com/site/esl/esl-erlang/FLAVOUR_1_esl/esl-erlang_17.5-1~debian~wheezy_amd64.deb
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michael Klishin]

Post by Michael Klishin
Can you upgrade to 17.5?

I forgot to mention that all nodes must have the same major version (Erlang Versions Across the Cluster
in http://www.rabbitmq.com/clustering.html).

You can find packages for many OSes and distributions on
https://www.erlang-solutions.com/downloads/download-erlang-otp

We also provide a minimalistic RPM of 17.x:
(just enough to run RabbitMQ, helps avoid RPM dependency hell)
http://www.rabbitmq.com/releases/erlang/ 
--
MK

Staff Software Engineer, Pivotal/RabbitMQ