前提
在项目开发中，设备使用了SIM7600Ce用于4G通信，基于Kawaii-MQTT提供mqtt client的维护和信息交互，且心跳包时间设置为60秒。同时，使用了NTP Auto Sync进行定期自动对时。 在PC上用C#写一个MQTT Client的小程序，记作APP，每隔100ms发送数据给设备订阅的主题发送一帧消息，同时订阅设备发出的数据。
简化描述，相当于有三个线程：
高优先级, user_mqtt_pubilsh，每秒向Broker发布1帧MQTT数据；
中优先级, mqtt_yield, kawaii-mqtt包中的内部线程，用于维护MQTT链接、处理订阅主题、Keep live保活；
低优先级, ntp_auto_sync, 定期自动对时;
问题描述
设备打印的日志显示，能收到APP发出的数据；APP也能收到来自设备的数据；表示TCP链路正常。
但是，设备偶尔会出现永远无法收到订阅消息的现象，且mqtt_yield线程不发出心跳包。但是，发送的链路一直正常，APP能收到来自设备的每秒消息。
之前在FreeRTOS下使用jiejietop提供的mqtt client，工作良好，但是并未使用jiejie发布的kawaii-mqtt client，本着找bug、彻底弄清楚的原则，怀疑是mqtt_yield线程挂了。
问题分析
使用list_timer命令打印，发现mqtt_yield线程会进入到deactivated状态。 1.mqtt_yield启动，使用sokcet 0通信；
mqtt yield
---> mqtt_read_packet
---> network_read
---> recvfrom
---> at_recvfrom
/* wait the receive semaphore */
if (rt_sem_take(sock->recv_notice, timeout) < 0)
{
/*@lchnu delete*/
LOG_E("AT socket (%d) receive timeout (%d)!", socket, timeout);*/
errno = EAGAIN;
result = -1;
goto __exit;
}
else
{
if (sock->state == AT_SOCKET_CONNECT)
{
/* get receive buffer to receiver ring buffer */
rt_mutex_take(sock->recv_lock, RT_WAITING_FOREVER);
recv_len = at_recvpkt_get(&(sock->recvpkt_list), (char *) mem, len);
rt_mutex_release(sock->recv_lock);
if (recv_len > 0)
{
break;
}
}
尚未收到MQTT数据，等待信号量sock->recv_notice，超时时间为timeout，本项目中设置为10秒。
2.等待信号量导致任务切换，进入ntp_auto_sync中, 使用socket 1通信, 并等待发送回执；
ntp_auto_sync
---> sendto_ntp_server
---> sal_sendto
---> at_send
---> sim76xx_socket_send
---> sim76xx_socket_event_recv
值得关注的是，在sim76xx_socket_send函数中,会改写sim7600 device的user_data，它用于表示socket编号。
static int sim76xx_socket_send(struct at_socket *socket, const char *buff, size_t bfsz, enum at_socket_type type)
{
int device_socket = (int) socket->user_data;
struct at_device *device = (struct at_device *) socket->device;
struct at_device_sim76xx *sim76xx = (struct at_device_sim76xx *) device->user_data;
/* set current socket for send URC event */
sim76xx->user_data = (void *) device_socket;
sim76xx->user_data的值从0变成1。
3.sim7600模块返回+CIPSEND: 1, 48,48 OK, 唤醒ntp_auto_sync线程，然后进入到等待对时结果的状态。
ntp_auto_sync
---> recvfrom
---> sal_recvfrom
---> at_recvfrom
注意，等待的是Socket 1对应的recv_notice。
4.ntp_auto_sync中的recv_notice take导致任务切换，进入到user_mqtt_pubilsh线程。
user_mqtt_pubilsh
---> mqtt_publish
---> sal_sendto
---> at_send
---> sim76xx_socket_send
显然，sim76xx->user_data的值又从1变成了0。
5.user_mqtt_pubilsh在等待AT返回OK过程中，发生任务切换，进入了mqtt_yield线程继续等待sock->recv_notice信号量。 此时，来了一帧来自NTP对时的消息，串口中断，收到+IPD XXX的数据。其实是Socket1的数据，但是进入了socket0。 由于数据不对，解析数据错误，在mqtt_packet_drain函数中，使用do-while不停地network_read。
uart isr: +IPD xxxxxx
---> urc_recv_func
---> at_recv_notice_cb
---> mqtt_packet_drain <-- |
--> network_read |
---> recvfrom |
---> at_recvfrom -
mqtt_packet_drain函数中的代码如下，为了清晰描述过程，添加了两句log。
do {
KAWAII_MQTT_LOG_E("mqtt drain data from socket %d", c->mqtt_network->socket);
read_len = network_read(c->mqtt_network, c->mqtt_read_buf, bytes2read, platform_timer_remain(timer));
KAWAII_MQTT_LOG_E("mqtt drain data %d from socket %d", read_len, c->mqtt_network->0);
if (0 != read_len) {
total_bytes_read += read_len;
if ((packet_len - total_bytes_read) >= c->mqtt_read_buf_size) {
bytes2read = c->mqtt_read_buf_size;
} else {
bytes2read = packet_len - total_bytes_read;
}
}
} while ((total_bytes_read < packet_len) && (0 != read_len)); /* read and discard all corrupted data */
KAWAII_MQTT_LOG_E("mqtt drain data down");
在下面的日志中，
at: sock 0 - rev 48表示NTP的数据进入了Socket0。
第1个mqtt drain data from socket 0表示在mqtt_packet_drain中设置10秒超时等待数据；
第2个mqtt drain data -1 from socket 0, -1表示数据接收超时;
第3个mqtt drain data from socket 0, 表示再次读取网络数据，这一步操作使得mqtt-yield线程deactivated。
[2022/3/28 23:47:32] [I/at.skt.sim76] sim: sock 1 - ipd 48
[2022/3/28 23:47:32] [I/at.skt] at: sock 1 - rev 48
[2022/3/28 23:47:32] [I/at.skt.sim76] sim: sock 1 - ipd 48
[2022/3/28 23:47:32] [I/at.skt] at: sock 1 - rev 48
[2022/3/28 23:47:38] [I/at.skt.sim76] sim: sock 0 - ipd 48
[2022/3/28 23:47:38] [I/at.skt] at: sock 0 - rev 48
[2022/3/28 23:47:38] [I/at.skt.sim76] sim: sock 0 - ipd 48
[2022/3/28 23:47:38] [I/at.skt] at: sock 0 - rev 48
[2022/3/28 23:47:38] mqtt drain data from socket 0
[2022/3/28 23:47:38] [I/at.skt.sim76] sim: sock 1 - ipd 48
[2022/3/28 23:47:38] [I/at.skt] at: sock 1 - rev 48
[2022/3/28 23:47:43] [I/at.skt.sim76] sim: sock 1 - ipd 48
[2022/3/28 23:47:48] mqtt drain data -1 from socket 0
[2022/3/28 23:47:48] mqtt drain data from socket 0
[2022/3/28 23:48:13] msh />list_timer
[2022/3/28 23:48:13] timer periodic timeout flag
[2022/3/28 23:48:13] ---------------- ---------- ---------- -----------
[2022/3/28 23:48:13] 202203271615380f 0x0000270c 0x000433c3 deactivated
[2022/3/28 23:48:13] PRODUCER 0x00000096 0x00001059 deactivated
[2022/3/28 23:48:13] STLOGGER 0x00000000 0x00000000 deactivated
[2022/3/28 23:48:13] TXLOGGER 0x00000004 0x00049656 activated
[2022/3/28 23:48:13] MQTTPBER 0x000001c9 0x00049724 activated
[2022/3/28 23:48:13] CONSUMER 0x00000064 0x000496ab activated
[2022/3/28 23:48:13] sim7600ce 0x00007530 0x00049dff activated
[2022/3/28 23:48:13] at_clnt0 0x000001e0 0x0002f7d5 deactivated
[2022/3/28 23:48:13] sd_mount 0x000000c8 0x00049667 deactivated
[2022/3/28 23:48:13] tshell 0x000007d0 0x0004876f deactivated
[2022/3/28 23:48:13] ntp_sync 0x00001388 0x0004a128 activated
[2022/3/28 23:48:13] sys_work 0x000003e8 0x000012ec deactivated
[2022/3/28 23:48:13] mmcsd_detect 0x00001388 0x000013a7 deactivated
[2022/3/28 23:48:13] tidle0 0x00000000 0x00000000 deactivated
[2022/3/28 23:48:13] current tick:0x0004968b
mqtt_packet_drain函数中发生了什么？
在drain函数中，阻塞式读取网络数据，并且通过platform_timer_remain(timer)函数提供超时时间。
read_len = network_read(c->mqtt_network, c->mqtt_read_buf, bytes2read, platform_timer_remain(timer));
记第一次打印mqtt drain data from socket 0的时刻为 T = 00秒:
在T = 00秒时刻，platform_timer_remain(timer)计算的超时时间是10秒；
在T = 10秒时刻，函数network_read超时退出，返回值为-1，所以第2次打印mqtt drain data -1 from socket 0，
在T > 10秒时刻，while条件满足，继续执行do中的函数，打印mqtt drain data from socket 0后，已经经历了至少10秒，即timer->time此时要小于系统tick，因此，platform_timer_remain(timer)计算的超时时间是0。
当再次进入到network_read后，最终进入到at_recvfrom中。
at_recvfrom函数中，当timeout为0时，会将其设置为RT_WAITING_FOREVER。
/* set AT socket receive timeout */
if ((timeout = sock->recv_timeout) == 0)
{
timeout = RT_WAITING_FOREVER;
}
else
{
timeout = rt_tick_from_millisecond(timeout);
}
6.在rt_sem_take函数内部，当sem->value不可用时，且timeout不为0，就thread suspend了，于是进入了deactivated状态。
7.由于mqtt yield的tick此时已经小于系统实际tick了，所以需要49天左右才能醒来。
解决方案
通过AT命令，使得SIM7600CE的网络数据以+RECEIVE: ,的形式返回。 修改at_device_sim76xx.c文件，在初始化函数中：
/* Configure parameters of socket with HeaderType is +RECEIVE,. */
AT_SEND_CMD(client, resp, "AT+CIPCCFG=10,0,0,1,1,0,500");
同时修改at_socket_sim76xx.c中的的urc_table，在新增的多通道函数中，不再使用sim76xx的user_data作为socket编号，其他均与urc_recv_func一样。
static struct at_urc urc_table[] =
{
{"+CIPSEND:", "rn", urc_send_func},
{"+CIPOPEN:", "rn", urc_connect_func},
{"+IPCLOSE", "rn", urc_close_func},
{"+IPD", "rn", urc_recv_func},
{"+RECEIVE", "rn", urc_recv_multi_socket_func},
};
static void urc_recv_multi_socket_func(struct at_client *client, const char *data, rt_size_t size)
{
/* get the current socket and receive buffer size by receive data */
sscanf(data, "+RECEIVE,%d,%d:",&device_socket, (int *)&bfsz);
/* get receive timeout by receive buffer length */
.......
结语
查找bug花了很久的时间。后续会继续测试该方案的稳定性，同时尝试PR kawaii-mqtt client，看看drain部分对timer的处理是否有更优的方案。
