RabbitMQ Network Partitions 服务日志对比

如果你一直使用RabbitMQ作为业务的消息中间件，难免会遇到网络分区（Network Partitions）的故障，也许你当时会束手无策，一脸懵逼，不过希望在看完这篇文章之后，能给你一点解决网络分区的思路。

RabbitMQ中所有节点状态的变更都会记录在日志当中，日志默认地址为：$RABBITMA_HOME/var/log/rabbitmq/rabbit@node*.log。所以当网络分区发生的时候可以根据日志内容来推测出当时发生网络分区的原因，进而据此优化你的业务逻辑，增强应用的鲁棒性。

本文只展示在模拟发生网络分区前后的日志对比，方便在查看日志的时候可以提供一个参考。

本文之后的RabbitMQ集群有两个节点组成，分别为rabbit@node1和rabbit@node2。
模拟网络分区的方法：关闭node2节点的网卡（ifdown eth0），之后再恢复。注：测试采用的两个节点都是单网卡的。
网络分区的恢复方法：关闭node2节点（rabbitmqctl stop）,之后再恢复node节点（rabbitmq-server -detached）即可恢复网络分区。
网络分区的查看方式：rabbitmqctl cluster_status命令之后查看partititons中是否有相关节点信息。或者也可以通过WebUI的方式查看。

具体执行步骤以及两个节点的日志对比如下所示。
1.在node2上执行ifdown eth0。
node1中打印日志如下

=ERROR REPORT==== 24-Jun-2017::17:08:55 ===
** Node 'rabbit@node2' not responding **
** Removing (timedout) connection **

=INFO REPORT==== 24-Jun-2017::17:08:55 ===
rabbit on node 'rabbit@node2' down

=INFO REPORT==== 24-Jun-2017::17:08:55 ===
node 'rabbit@node2' down: net_tick_timeout

node2打印日志：

NG REPORT==== 24-Jun-2017::17:35:31 ===
epmd does not know us, re-registering rabbit at port 25672

=ERROR REPORT==== 24-Jun-2017::17:36:00 ===
** Node 'rabbit@node1' not responding **
** Removing (timedout) connection **

=INFO REPORT==== 24-Jun-2017::17:36:00 ===
rabbit on node 'rabbit@node1' down

=INFO REPORT==== 24-Jun-2017::17:36:00 ===
node 'rabbit@node1' down: net_tick_timeout

之后如果不执行任何操作，node2每隔1min会打印日志(忽略下面的具体日期)：

NG REPORT==== 24-Jun-2017::xx:xx:xx ===
epmd does not know us, re-registering rabbit at port 25672

2.在node2上执行ifup eth0。
node1之后打印日志如下：

=INFO REPORT==== 24-Jun-2017::17:10:32 ===
node 'rabbit@node2' up

=ERROR REPORT==== 24-Jun-2017::17:10:32 ===
Mnesia('rabbit@node1'): ** ERROR ** mnesia_event got {inconsistent_database, running_partitioned_network, 'rabbit@node2'}

node2打印日志：

=INFO REPORT==== 24-Jun-2017::17:42:21 ===
node 'rabbit@node1' up

=ERROR REPORT==== 24-Jun-2017::17:42:21 ===
Mnesia('rabbit@node2'): ** ERROR ** mnesia_event got {inconsistent_database, running_partitioned_network, 'rabbit@node1'}

3.此时在node1上执行rabbitmqctl cluster_status可以看到：

[root@node1 ~]# rabbitmqctl cluster_status
Cluster status of node 'rabbit@node1' ...
[{nodes,
     [{disc,
          ['rabbit@node1','rabbit@node2']}]},
 {running_nodes,['rabbit@node1']},
 {cluster_name,<<"rabbit@node1">>},
 {partitions,
     [{'rabbit@node1',['rabbit@node2']}]}]

4.此时在node2上执行rabbitmqctl cluster_status可以看到：

[root@node2 ~]# rabbitmqctl cluster_status
Cluster status of node 'rabbit@node2' ...
[{nodes,
     [{disc,
          ['rabbit@node1','rabbit@node2']}]},
 {running_nodes,['rabbit@node2']},
 {cluster_name,<<"rabbit@node1">>},
 {partitions,
     [{'rabbit@node2',['rabbit@node1']}]}]

此时可以判断已经出现了网络分区，之后恢复网络分区。

5.在node2上执行rabbitmqctl stop之后。
可以看到node1的日志：

=INFO REPORT==== 24-Jun-2017::17:25:11 ===
rabbit on node 'rabbit@node2' down

=INFO REPORT==== 24-Jun-2017::17:25:12 ===
Keep rabbit@node2 listeners: the node is already back

=INFO REPORT==== 24-Jun-2017::17:25:13 ===
node 'rabbit@node2' down: connection_closed

note2中的日志：

=INFO REPORT==== 24-Jun-2017::17:56:21 ===
Stopping RabbitMQ

=INFO REPORT==== 24-Jun-2017::17:56:21 ===
stopped TCP Listener on [::]:5672

=INFO REPORT==== 24-Jun-2017::17:56:21 ===
Stopped RabbitMQ application

=INFO REPORT==== 24-Jun-2017::17:56:21 ===
Halting Erlang VM

6.在node2上执行rabbitmq-server -detached以恢复网络分区。
此时node1的日志为：

=INFO REPORT==== 24-Jun-2017::17:58:27 ===
node 'rabbit@node2' up

=INFO REPORT==== 24-Jun-2017::17:58:27 ===
rabbit on node 'rabbit@node2' up

此时node2的日志为：

ERROR REPORT==== 24-Jun-2017::17:58:55 ===
Mnesia('rabbit@node2'): ** ERROR ** mnesia_event got {inconsistent_database, starting_partitioned_network, 'rabbit@node1'}

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
Starting RabbitMQ 3.5.7 on Erlang 19.1
Copyright (C) 2007-2015 Pivotal Software, Inc.
Licensed under the MPL.  See http://www.rabbitmq.com/

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
node           : rabbit@node2
home dir       : /root
config file(s) : /opt/rabbitmq/sbin/../etc/rabbitmq/rabbitmq.config (not found)
cookie hash    : VCwbL3S9/ydrGgVsrLjVkA==
log            : /opt/rabbitmq/sbin/../var/log/rabbitmq/rabbit@node2.log
sasl log       : /opt/rabbitmq/sbin/../var/log/rabbitmq/rabbit@node2-sasl.log
database dir   : /opt/rabbitmq/sbin/../var/lib/rabbitmq/mnesia/rabbit@node2

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
Memory limit set to 392MB of 980MB total.

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
Disk free limit set to 50MB

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
Limiting to approx 924 file handles (829 sockets)

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
FHC read buffering:  ON
FHC write buffering: ON

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
Priority queues enabled, real BQ is rabbit_variable_queue

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
msg_store_transient: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
msg_store_persistent: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
started TCP Listener on [::]:5672

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
rabbit on node 'rabbit@node2' up

=INFO REPORT==== 24-Jun-2017::17:58:55 ===
Server startup complete; 0 plugins started.

此时可以在任何一个节点中输入rabbitmqctl cluster_status命令
之后可以看到：

[root@node1 ~]# rabbitmqctl cluster_status
Cluster status of node 'rabbit@node1' ...
[{nodes,[{disc,['rabbit@node1', 'rabbit@node2']}]},
 {running_nodes,['rabbit@node2','rabbit@node1']},
 {cluster_name,<<"rabbit@node1">>},
 {partitions,[]}]

只要看到partitions中没有任何节点信息即表示网络分区消失。