学会查看 RabbitMQ日志

如果在使用RabbitMQ的过程中出现了异常情况，通过翻阅RabbitMQ的服务日志可以让你在处理异常的过程中事半功倍。RabbitMQ日志中会有明确的事件日期、事件内容以及事件等级等。RabbitMQ的日志默认存放在$RABBITMQ_HOME/var/log/rabbitmq目录下。本问主要从RabbitMQ服务开启、RabbitMQ服务关闭以及RabbitMQ集群搭建的角度来举例说明RabbitMQ的日志的一些查看思路。

各位读者实际使用的RabbitMQ版本各有差异，这里我们挑选一个偏旧版本（3.6.2）来统筹说明，以期不会有太大的偏差。所幸各个版本的日志大致相同，也会有略微变化。读者需要培养一种使用服务日志来解决问题的思路，本文只做抛砖引玉之用。

启动RabbitMQ服务

启动RabbitMQ服务可以使用rabbitmq-server -detached命令，这个命令会顺带启动Erlang虚拟机和RabbitMQ应用服务，而rabbitmqctl start_app用来启动RabbitMQ应用服务。注意RabbitMQ应用服务启动的前提是Erlang虚拟机是运转正常的。首先这里来看下在执行完rabbitmq-server -detached命令其相应的服务日志是什么。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
1Starting RabbitMQ 3.6.2 on Erlang 19.1

2Copyright (C) 2007-2016 Pivotal Software, Inc.

3Licensed under the MPL.  See http://www.rabbitmq.com/

4

5=INFO REPORT==== 3-Jul-2017::10:52:08 ===

6node           : rabbit@node1

7home dir       : /root

8config file(s) : /opt/rabbitmq/etc/rabbitmq/rabbitmq.config (not found)

9cookie hash    : VCwbL3S9/ydrGgVsrLjVkA==

10log            : /opt/rabbitmq/var/log/rabbitmq/rabbit@node1.log

11sasl log       : /opt/rabbitmq/var/log/rabbitmq/rabbit@node1-sasl.log

12database dir   : /opt/rabbitmq/var/lib/rabbitmq/mnesia/rabbit@node1

13

14=INFO REPORT==== 3-Jul-2017::10:52:09 ===

15Memory limit set to 3148MB of 7872MB total.

16

17=INFO REPORT==== 3-Jul-2017::10:52:09 ===

18Disk free limit set to 50MB

19

20=INFO REPORT==== 3-Jul-2017::10:52:09 ===

21Limiting to approx 924 file handles (829 sockets)

22

23=INFO REPORT==== 3-Jul-2017::10:52:09 ===

24FHC read buffering:  OFF

25FHC write buffering: ON

26

27=INFO REPORT==== 3-Jul-2017::10:52:09 ===

28Database directory at /opt/rabbitmq/var/lib/rabbitmq/mnesia/rabbit@node1 is empty. Initialising from scratch...

29

30=INFO REPORT==== 3-Jul-2017::10:52:10 ===

31Priority queues enabled, real BQ is rabbit_variable_queue

32

33=INFO REPORT==== 3-Jul-2017::10:52:10 ===

34Adding vhost '/'

35

36=INFO REPORT==== 3-Jul-2017::10:52:10 ===

37Creating user 'guest'

38

39=INFO REPORT==== 3-Jul-2017::10:52:10 ===

40Setting user tags for user 'guest' to [administrator]

41

42=INFO REPORT==== 3-Jul-2017::10:52:10 ===

43Setting permissions for 'guest' in '/' to '.*', '.*', '.*'

44

45=INFO REPORT==== 3-Jul-2017::10:52:10 ===

46msg_store_transient: using rabbit_msg_store_ets_index to provide index

47

48=INFO REPORT==== 3-Jul-2017::10:52:10 ===

49msg_store_persistent: using rabbit_msg_store_ets_index to provide index

50

51=WARNING REPORT==== 3-Jul-2017::10:52:10 ===

52msg_store_persistent: rebuilding indices from scratch

53

54=INFO REPORT==== 3-Jul-2017::10:52:10 ===

55started TCP Listener on [::]:5672

56

57=INFO REPORT==== 3-Jul-2017::10:52:10 ===

58Server startup complete; 0 plugins started.

59

这段日志包含了RabbitMQ的版本号、Erlang的版本号、RabbitMQ服务节点名称、cookie的hash值、RabbitMQ配置文件地址、内存限制、磁盘限制、默认账户guest的创建以及权限配置等等。如果是安装了rabbitmq_management插件的话，在启动rabbitmq的时候会多打印一些日志：

1
2
3
4
5
6
7
8
9
1=INFO REPORT==== 3-Jul-2017::10:57:05 ===

2Server startup complete; 6 plugins started.

3 * rabbitmq_management

4 * rabbitmq_management_agent

5 * rabbitmq_web_dispatch

6 * webmachine

7 * mochiweb

8 * amqp_client

9

当然还包括一些统计值信息的初始化日志，类似如下日志。

1
2
3
4
1=INFO REPORT==== 3-Jul-2017::10:57:05 ===

2Statistics garbage collector started for table {aggr_queue_stats_fine_stats,

3                                                5000}.

4

与aggr_queue_stats_fine_stats日志一起的还有aggr_queue_stats_deliver_get，aggr_queue_stats_queue_msg_counts，channel_stats，connection_stats等等几十种。对于这些统计值，不同的版本可能略有差异，一般情况下对此无需过多探究。

如果你是使用rabbitmqctl stop_app命令关闭的RabbitMQ应用服务，那么你在使用rabbitmqctl start_app命令开启RabbitMQ应用服务的时候的启动日志和rabbitmq-server的启动日志相同。

关闭RabbitMQ服务

如果使用rabbitmqctl stop命令，会将Erlang虚拟机一同关闭，而rabbitmqctl stop_app只关闭RabbitMQ应用服务，在关闭的时候要多加注意之间的区别。下面先看一下rabbitmqctl stop_app所对应的服务日志：

1
2
3
4
5
6
7
8
9
1=INFO REPORT==== 3-Jul-2017::10:54:01 ===

2Stopping RabbitMQ

3

4=INFO REPORT==== 3-Jul-2017::10:54:01 ===

5stopped TCP Listener on [::]:5672

6

7=INFO REPORT==== 3-Jul-2017::10:54:01 ===

8Stopped RabbitMQ application

9

如果采用rabbitmqctl stop来进行关闭操作，则会多出下面的日志信息，即关闭Erlang虚拟机。

1
2
3
1=INFO REPORT==== 3-Jul-2017::10:54:01 ===

2Halting Erlang VM

3

建立集群

建立集群也是一种常用的操作。这里举例将节点rabbit@node2与rabbit@node1组成一个集群，有关如何建立RabbitMQ集群的细节可以参考RabbitMQ的安装及集群搭建方法。
首先在节点rabbit@node2中执行rabbitmq-server -detached开启Erlang VM以及RabbitMQ应用服务，之后再执行rabbitmqctl stop_app来关闭RabbitMQ应用服务，具体的日志可以参考前面的内容。之后需要重置节点rabbit@node2中的数据rabbitmqctl reset，相应的在节点rabbit@node2上的日志如下：

1
2
3
1=INFO REPORT==== 3-Jul-2017::11:25:01 ===

2Resetting Rabbit

3

在rabbit@node2节点上执行rabbitmqctl join_clcuster rabbit@node1将其加入到rabbit@node1中以组成一个集群，相应的在rabbit@node2节点中会打印日志：

1
2
3
1=INFO REPORT==== 3-Jul-2017::11:30:46 ===

2Clustering with [rabbit@node1] as disc node

3

与此同时在rabbit@node1中会有日志：

1
2
3
1=INFO REPORT==== 3-Jul-2017::11:30:56 ===

2node rabbit@node2 up

3

最后重启rabbit@node2节点，至于rabbit@node2中此时的日志可以参考前面的rabbitmq-server -detached或者rabbitmqctl start_app的启动日志。而此时在rabbit@node1节点中会有日志如下：

1
2
3
1=INFO REPORT==== 3-Jul-2017::11:45:14 ===

2rabbit on node rabbit@node2 up

3

如果此时在rabbit@node2节点上执行rabbitmqctl stop_app的动作，那么在rabbit@node1节点中会有如下信息：

1
2
3
4
5
6
1=INFO REPORT==== 3-Jul-2017::11:54:01 ===

2rabbit on node rabbit@node2 down

3

4=INFO REPORT==== 3-Jul-2017::11:54:01 ===

5Keep rabbit@node2 listeners: the node is already back

6

通过上面的日志你可以看出某个RabbitMQ节点在某个时段的关闭启动的动作。可以通过尝试各种的操作以收集相应的服务日志，之后组成一个知识集，这个知识集不单指一个日志列表，可以通过后期的强化训练掌握其规律，让这个知识集了然于心。在真正遇到异常故障的时候可以通过查看服务日志来迅速的定位问题的根本，之后再采取相应的措施以解决问题。

这里博主有个心得，仅供参考，在执行任何RabbitMQ操作之前，都会打开一个新的窗口运行tail -f
$RABBITMQ_HOME/var/log/rabbitmq/rabbit@
$HOSTNAME.log -n 200命令来实时查看相应操作所对应的服务日志是什么，久而久之即可在脑海中建立一个相对完备的“知识集”。