paho.mqtt.embedded掉线问题记录

1. 问题描述
2. 问题定位
3. 解决方案
4. 总结
参考

1. 问题描述

使用paho.mqtt.embedded-c库编译的应用程序在linux环境下监听topic时，过段时间会概率性地发生连接失败并重连的现象。具体表现为会打印yield -1

void loop() {
    static int count=0;
    int ret=MQTTYield(&c, 1000);
    if (SUCCESS != ret) {
        LOGI("yield:%d",ret);
        if(0 == count%reconnect_delay){
            reconnect_count++;
            if(10<reconnect_count){
                reconnect_delay=60;
            }
            count=0;
            connect_mqtt();
        }
        count++;
    } else{
        reconnect_delay=10;
        reconnect_count=0;
        count=0;
    }
}

2. 问题定位

2.1. 确定mqtt服务端是否正常

出现问题首先要缩小问题搜索范围，然后在小范围内定位问题。网络相关的首先怀疑是否是网络问题导致的，因些我首先对网络问题进行排查。具体排查方法为：

使用另外的库 mosquitto_sub 监听同一MQTT服务的同一topic，在相同情况下mosquitto_sub没有问题，可以初步判定MQTT服务本身没有问题。

2.2. 确定是库调用的问题还是库本身的问题

确定网络没有问题后，应该可以确定是是我自己写的应用程序的问题，我自己写的应用程序也有两部分：自己写的代码和库代码。先确定是自己写的代码有问题还是库代码有问题，比较好的方式就是直接使用官方例程代码看是否有问题。如果官方例程也有问题就说明是库的问题，否则就是自己写的代码有问题。

在paho.mqtt.embedded-c自带监听的sample上加入失败打印，然后监听同一MQTT服务的同一topic，发现也会打印 connect err: -1。说明问题是出自paho.mqtt.embedded-c库

int main(int argc, char** argv)
{
	...
	while (!toStop)
	{
		int ret= MQTTYield(&c, 1000);	
		if (SUCCESS != ret) {
			printf("connect err:%d\n",ret);
    	}
	}
	...
}

2.3. 跟踪查找原因

2.3.1. 跟踪代码

MQTTYield返回-1的原因只能是cycle返回值小于0
cycle返回值小于0有三种情况
1. 收到PUBLISH包
2. 收到PUBREL包
3. 收到未识别包
4. keepalive失败
分别在以上4种情况加打印，然后复现问题。发现是keepalive失败导致错误
keepalive失败的原因只能是距离上次发送和接收都超过心跳时间，且未收到心跳回复包

正常的逻辑是不会出现这种情况的，现在问题出现的机制跟时序有关了，于是继续针对时间和c->ping_outstanding的操作加打印。发现了问题：出现问题时调用keepalive发送心跳包后没有等待c->ping_outstanding复位，就马上又开始了下一次的keepalive调用。

但是是什么机制导致keepalive连续调两次呢？于是又在各个可能的地方加入打印。。。

如此增加打印-分析操作了很久，始终无法定位到原因。因为此问题本身就是概率性，又需要同时跟踪3个函数的调用时刻，并记录邻近几次调用的时间，打印就显得很有局限了。不得已我只能使用了不太熟悉的GDB

2.3.2. GDB跟踪

首先对库代码做一些修改，加入保存loop、MQTTYield、keepalive三个函数的上次调用时间和本次调用时间，然后加入-g编译选项，最后运行时在keepalive函数的rc = FAILURE;异常处打断点，出现问题后，分别查看三个函数的上次调用时间和本次调用时间

Breakpoint 1, keepalive (c=0x6088e0 <c>)
    at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/lib/paho.mqtt.embedded-c/MQTTClient-C/src/MQTTClient.c:224
224                 rc = FAILURE; /* PINGRESP not received in keepalive interval */
(gdb) p last
$1 = {tv_sec = 1586170992, tv_usec = 23165}
(gdb) p now
$2 = {tv_sec = 1586170992, tv_usec = 24068}
(gdb) up
#1  0x0000000000402065 in cycle (c=0x6088e0 <c>, timer=0x7ffffffedd30)
    at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/lib/paho.mqtt.embedded-c/MQTTClient-C/src/MQTTClient.c:331
331         if (keepalive(c) != SUCCESS) {
(gdb) up
#2  0x0000000000402117 in MQTTYield (c=0x6088e0 <c>, timeout_ms=1000)
    at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/lib/paho.mqtt.embedded-c/MQTTClient-C/src/MQTTClient.c:358
358             if (cycle(c, &timer) < 0)
(gdb) p last
$3 = {tv_sec = 1586170991, tv_usec = 23897}
(gdb) p now
$4 = {tv_sec = 1586170992, tv_usec = 23218}
(gdb) up
#3  0x0000000000401426 in loop () at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/common/mqtt_embedded.c:138
138         int ret=MQTTYield(&c, 1000);
(gdb) p last
$5 = {tv_sec = 1586170989, tv_usec = 22031}
(gdb) p now
$6 = {tv_sec = 1586170991, tv_usec = 23895}
(gdb) down
#2  0x0000000000402117 in MQTTYield (c=0x6088e0 <c>, timeout_ms=1000)
    at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/lib/paho.mqtt.embedded-c/MQTTClient-C/src/MQTTClient.c:358
358             if (cycle(c, &timer) < 0)
(gdb) p timer
$7 = {end_time = {tv_sec = 1586170992, tv_usec = 23896}}
(gdb) p timeout_ms
$8 = 1000
(gdb) down
#1  0x0000000000402065 in cycle (c=0x6088e0 <c>, timer=0x7ffffffedd30)
    at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/lib/paho.mqtt.embedded-c/MQTTClient-C/src/MQTTClient.c:331
331         if (keepalive(c) != SUCCESS) {
(gdb) p *timer
$9 = {end_time = {tv_sec = 1586170992, tv_usec = 23896}}
(gdb) p packet_type
$10 = 0
(gdb) down
#0  keepalive (c=0x6088e0 <c>)
    at /mnt/d/svn/ai_face/trunk/tcp_nat/nat_core/lib/paho.mqtt.embedded-c/MQTTClient-C/src/MQTTClient.c:224
224                 rc = FAILURE; /* PINGRESP not received in keepalive interval */
(gdb) p now
$11 = {tv_sec = 1586170992, tv_usec = 24068}
(gdb) p last
$12 = {tv_sec = 1586170992, tv_usec = 23165}
(gdb) p c->last_sent
$13 = {end_time = {tv_sec = 1586171022, tv_usec = 23215}}
(gdb) p c->last_received
$14 = {end_time = {tv_sec = 1586170991, tv_usec = 3225}}

把各函数调用时间整理如下表：

函数	上次调用时间	本次调用时间
`loop`	1586170989.22031	1586170991.23895
`MQTTYield`	1586170991.23897	1586170992.23218
`keepalive`	1586170992.23165	1586170992.24068

可以看出，loop函数的两次调用时间间隔1S，与期望的逻辑一致；MQTTYield函数的两次调用时间间隔1S，与期望的逻辑一致；keepalive函数的两次调用时间间隔9mS，时间非常短。为什么会出现这种情况（keepalive多调用了一次）呢？

在函数MQTTYield中有这一句，可能出现多次调用cycle，cycle会调用keepalive

int MQTTYield(MQTTClient* c, int timeout_ms)
{
    ...
    do
    {
        if (cycle(c, &timer) < 0)
        {
            rc = FAILURE;
            break;
        }
  	} while (!TimerIsExpired(&timer));
	...
}

继续跟踪cycle中调用的readPacket方法，发现读socket操作采用了超时阻塞机制。

int linux_read(Network* n, unsigned char* buffer, int len, int timeout_ms)
{
	struct timeval interval = {timeout_ms / 1000, (timeout_ms % 1000) * 1000};
	if (interval.tv_sec < 0 || (interval.tv_sec == 0 && interval.tv_usec <= 0))
	{
		interval.tv_sec = 0;
		interval.tv_usec = 100;
	}

	setsockopt(n->my_socket, SOL_SOCKET, SO_RCVTIMEO, (char *)&interval, sizeof(struct timeval));

	int bytes = 0;
	while (bytes < len)
	{
		int rc = recv(n->my_socket, &buffer[bytes], (size_t)(len - bytes), 0);
		...
	}
	return bytes;
}

经过一番冥思苦想，嗯。。。问题可能就出在这里。

MQTTYield中的while是一种超时机制，linux_read中的socket读也是一种超时机制，但这两种超时的时刻并没有完全的同步。这样就存在一种极端情况：linux_read超时已到，但MQTTYield超时还示到，这时两者会相差很短的时间（这里抓到的是9mS）。MQTTYield会马上启动下一次cycle，而上一次cycle恰好刚刚发送了心跳包，处于等待1S内心跳回复中。但因为突然多调了一次cycle，keepalive认为在等待1S内心跳回复时间内没有收到心跳回复。

3. 解决方案

去掉MQTTYield中的while循环，只用其中一个超时机制
减少发送心跳的间隔为原来的一半，这样keepalive在还没有进行等待1S内心跳回复时就把c->ping_outstanding复位，就不会认为在等待心跳回复时间内没有收到心跳回复

后来我在paho.mqtt.embedded-c源码的issue中搜索此类问题，确实也有人发现了这个问题，维护人员也给了解决方案。但是比较奇怪的是，这个问题在2018年12月已经解决了，却在2010年4月还没有合入主干版本

4. 总结

出现问题后，先在官方源码ISSUE上搜索，可能已经有人提问并已经解决了。这样可以节省自己定位问题和解决问题的时间（不过这次也间接地提升了我自己定位问题的能力）
定位问题时，我还是习惯于使用打印来查看。这种方式一般一次无法定位到准确位置，而且每次修改都需要重新编译代码，效率很低。后来没办法才使用了神器GDB，因为我对GDB不熟，所以不用GDB，这是我的思维惯性，后面要强制让自己多用GDB，用高效的工具来解决问题