RT-Thread-SIM7600多Sokcet通信bug和解决方案RT-Thread问答社区

SIM7600多Sokcet通信bug和解决方案

5.00

发布于 2022-03-29 18:09:33 浏览：1933 订阅该版

[tocm]

## 前提

在项目开发中，设备使用了SIM7600Ce用于4G通信，基于Kawaii-MQTT提供mqtt client的维护和信息交互，且心跳包时间设置为60秒。同时，使用了NTP Auto Sync进行定期自动对时。

在PC上用C#写一个MQTT Client的小程序，记作APP，每隔100ms发送数据给设备订阅的主题发送一帧消息，同时订阅设备发出的数据。

简化描述，相当于有三个线程：

1. 高优先级, user_mqtt_pubilsh，每秒向Broker发布1帧MQTT数据；
2. 中优先级, mqtt_yield, kawaii-mqtt包中的内部线程，用于维护MQTT链接、处理订阅主题、Keep live保活；
3. 低优先级, 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通信；
```bash
mqtt yield
  ---> mqtt_read_packet
    ---> network_read
      ---> recvfrom
        ---> at_recvfrom
```
        
```c
/* 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通信, 并等待发送回执；

```bash
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编号。`

```c
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线程，然后进入到等待对时结果的状态。

```bash
ntp_auto_sync
  ---> recvfrom
    ---> sal_recvfrom
      ---> at_recvfrom
```

`注意，等待的是Socket 1对应的recv_notice。`

4.ntp_auto_sync中的recv_notice take导致任务切换，进入到user_mqtt_pubilsh线程。

```bash
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。

```bash
uart isr: +IPD xxxxxx
  ---> urc_recv_func
    ---> at_recv_notice_cb
	  ---> mqtt_packet_drain <-- |
	    --> network_read         |
            ---> recvfrom        |
              ---> at_recvfrom  -
```

mqtt_packet_drain函数中的代码如下，为了清晰描述过程，添加了两句log。

```c
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。`

```bash
[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)`函数提供超时时间。

```c
read_len = network_read(c->mqtt_network, c->mqtt_read_buf, bytes2read, platform_timer_remain(timer));
```

记第一次打印mqtt drain data from socket 0的时刻为 T = 00秒:

1. 在T = 00秒时刻，`platform_timer_remain(timer)计算的超时时间是10秒`；

2. 在T = 10秒时刻，函数network_read超时退出，返回值为-1，所以第2次打印mqtt drain data -1 from socket 0，

3. 在T > 10秒时刻，while条件满足，继续执行do中的函数，打印mqtt drain data from socket 0后，已经经历了至少10秒，即timer->time此时要小于系统tick，因此，`platform_timer_remain(timer)计算的超时时间是0。`

4. 当再次进入到network_read后，最终进入到at_recvfrom中。

5. at_recvfrom函数中，当timeout为0时，会将其设置为`RT_WAITING_FOREVER`。

```c
/* 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: <link num>,<data length>的形式返回。
修改at_device_sim76xx.c文件，在初始化函数中：

```c
/* Configure parameters of socket with HeaderType is +RECEIVE,<link num>.<data length> */
        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一样。

```c
static struct at_urc urc_table[] =
{
    {"+CIPSEND:",      "\r\n",           urc_send_func},
    {"+CIPOPEN:",      "\r\n",           urc_connect_func},
    {"+IPCLOSE",       "\r\n",           urc_close_func},
    {"+IPD",           "\r\n",           urc_recv_func},
    {"+RECEIVE",       "\r\n",           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的处理是否有更优的方案。