|
前提 在项目开发中，设备使用了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的处理是否有更优的方案。
| 
1
/6 
工商网监
湘ICP备2023018690号
2301
淘帖
48
