Mosquitto服务器的日志分析

2018-01-08

Eclipse Mosquitto™是一款开源的（EPL/EDL licensed）消息代理服务器，它实现了MQTT协议的v3.1以及v3.1.1版本，并提供轻量级消息订阅/发布模式的服务。这使得Mosquitto非常适用于物联网领域的低功耗设备之间的消息通信，例如手机、嵌入式计算机以及像Arduino一样的微控制器。

1 准备工作

在使用Mosquitto之前，我们需要安装Mosquitto。如果不知道如何安装Mosquitto，请参考此篇文章：如何安装并使用MQTT服务器——Mosquitto。
本篇文章所使用的系统以及软件环境说明如下：

Ubuntu - 16.04 LTS
Mosquitto - v1.4.12（Mosquitto服务器没有设置用户名和密码以及SSL认证）

2 Mosquitto的启动日志

安装完毕并成功启动Mosquitto之后，我们可以看到Mosquitto的启动日志：

1515307521: mosquitto version 1.4.12 (build date 2017-06-01 13:03:46+0000) starting
1515307521: Config loaded from /mosquitto/conf/mosquitto.conf.
1515307521: Opening ipv4 listen socket on port 1883.
1515307521: Opening ipv6 listen socket on port 1883.

Mosquitto服务器的日志格式：第一列数字（例如1515307521）表示该条日志打印的Unix时间戳；第二列则是具体的日志信息。根据启动日志的最后两行信息，我们可以很清楚地知道，我们所启动的Mosquitto服务器正在监听的TCP端口为1883，这是Mosquitto服务器默认监听的TCP端口。

3 客户端建立连接、订阅消息的日志

现在使用MQTT客户端连接Mosquitto服务器（1883端口）并向服务器发起消息订阅，正常情况下我们可以看到Mosquitto服务器输出的日志如下所示：

1515309375: New connection from 172.17.0.1 on port 1883.
1515309375: New client connected from 172.17.0.1 as mqtt-client-NWq09wrg (c0, k60).
1515309375: Sending CONNACK to mqtt-client-NWq09wrg (0, 0)
1515309375: Received SUBSCRIBE from mqtt-client-NWq09wrg
1515309375: 	topic/sub/test (QoS 2)
1515309375: mqtt-client-NWq09wrg 2 topic/sub/test
1515309375: Sending SUBACK to mqtt-client-NWq09wrg

第1行日志表示MQTT客户端成功与Mosquitto服务器建立TCP连接，客户端IP为172.17.0.1，连接的TCP端口为1883。
第2行日志显示了MQTT客户端向Mosquitto服务器提交建立连接的请求（客户端调用connect接口）。日志中包含了客户端请求建立连接的一些参数，例如：

mqtt-client-NWq09wrg —— 表示客户端ID（clientId）
c0 —— 表示客户端将cleanSession标识设置为false，即不清除session
k60 —— 表示客户端将keep alive设置为60秒，即MQTT客户端与Mosquitto服务器的心跳时间间隔为60秒

第3行日志表示Mosquitto服务器接受了客户端的建立连接请求，并向客户端返回建立连接请求的响应。
第4~5行日志表示Mosquitto服务器收到了来自客户端mqtt-client-NWq09wrg订阅消息的请求，订阅的消息主题为topic/sub/test，消息质量为QoS 2（MQTT QoS说明）。
第6~7行日志表示Mosquitto服务器接受了客户端的消息订阅请求，并向客户端返回订阅请求的响应。

特别注意： Mosquitto服务器不允许有多个客户端同时使用同一个客户端ID（clientId）与其保持连接，如果有多个客户端使用了同一个客户端ID来与Mosquitto建立连接，Mosquitto服务器只保留最新的一个客户端连接并关闭旧的连接。具体日志如下所示：2~4行即为Mosquitto服务器关闭旧连接，接受新连接的过程

1515314560: New connection from 172.17.0.1 on port 1883.
1515314560: Client mqtt-client-NWq09wrg already connected, closing old connection.
1515314560: Client mqtt-client-NWq09wrg disconnected.
1515314560: New client connected from 172.17.0.1 as mqtt-client-NWq09wrg (c1, k60).
1515314560: Sending CONNACK to mqtt-client-NWq09wrg (0, 0)
1515314560: Received SUBSCRIBE from mqtt-client-NWq09wrg
1515314560: 	topic/sub/test (QoS 2)
1515314560: mqtt-client-NWq09wrg 2 topic/sub/test
1515314560: Sending SUBACK to mqtt-client-NWq09wrg

4 客户端与Mosquitto保持心跳的日志

MQTT客户端成功与Mosquitto服务器建立连接后，会按照连接时设置的keep alive时间间隔定时向服务器发送心跳请求数据包——PINGREQ；服务器收到客户端的心跳请求数据包后，正常情况下会向客户端回复心跳响应数据包——PINGRESP。心跳日志如下所示：

1 2	1515313742: Received PINGREQ from mqtt-client-NWq09wrg 1515313742: Sending PINGRESP to mqtt-client-NWq09wrg

5 客户端主动取消订阅、断开连接的日志

MQTT客户端分别调用unsubscribe接口和disconnect接口来向服务器发送取消消息主题订阅的请求（UNSUBSCRIBE）和请求断开与服务器连接的请求（DISCONNECT）时，Mosquitto服务器输出的日志如下所示：

1515315086: Received UNSUBSCRIBE from mqtt-client-NWq09wrg
1515315086: 	topic/sub/test
1515315086: mqtt-client-NWq09wrg topic/sub/test
1515315086: Received DISCONNECT from mqtt-client-NWq09wrg
1515315086: Client mqtt-client-NWq09wrg disconnected.

6 发布消息的日志

MQTT客户端调用publish接口向Mosquitto服务器发布消息（使用QoS 2），服务器输出的日志如下所示：

1515317711: Received PUBLISH from mqtt-client-NWq09wrg (d0, q2, r0, m1, 'topic/pub/test', ... (62 bytes))
1515317711: Sending PUBREC to mqtt-client-NWq09wrg (Mid: 1)
1515317711: Received PUBREL from mqtt-client-NWq09wrg (Mid: 1)
1515317711: Sending PUBCOMP to mqtt-client-NWq09wrg (Mid: 1)

QoS 2为MQTT协议最高等级的消息服务质量，这意味着每条发布的消息都会先存储在发送方和接收方本地，直到已处理此消息为止。消息的发送方和接收方通过一系列的来回握手的过程来确认消息是否已经被成功处理，以上的日志就表示着这个握手的过程：
第1行日志：表示Mosquitto服务器接收到了客户端mqtt-client-NWq09wrg发布的消息，日志包含了一些与发布的消息相关的参数：

d —— 表示MQTT协议报头的DUP字段
q —— 表示MQTT的消息服务质量QoS，这里q2即所发布消息的QoS为2
r —— 表示MQTT的retain标识，
m —— 表示消息ID（messageId：MQTT发布的每条消息都有一个唯一的messageId，亦即Mid），这里所发布消息的ID为1
topic/pub/test —— 所发布消息的主题
(62 bytes) —— 表示所发布消息的大小，单位字节

第2行日志：表示Mosquitto服务器向客户端（消息发布方）回复收到发布消息的响应（PUBREC），告诉客户端此条消息已经成功收到并暂时缓存在Mosquitto服务器本地。
第3行日志：表示客户端成功收到服务器的发布消息响应（PUBREC），并向Mosquitto服务器发起释放消息的请求（PUBREL）。
第4行日志：表示Mosquitto服务器收到客户端的释放消息请求（PUBREL）后，向客户端返回消息成功发布的响应（PUBCOMP），客户端收到此响应后，才会认为该条消息成功发布并删除该条消息的本地缓存。
对于QoS为2的消息，其发布过程都会经历以上四个阶段：消息预发布（PUBLISH） –> 消息预发布确认（PUBREC） –> 消息释放（PUBREL） –> 消息成功发布（PUBCOMP）；
而对于QoS为0或者1的消息，其发布过程则比较简单，没有这么复杂的过程，所以QoS为2的消息是最耗时也最耗资源的。