Mars 通讯协议完整错误分析报告

概述

本报告对用户上传的 Mars 通讯协议日志进行深入分析，详细记录:

1. 断链事件 - 每次断链的完整过程，包括连接建立、数据发送、断开原因
2. 其他错误 - 数据库错误、配置错误、业务错误等的详细分析

日志信息:

• 文件: logs (1)_.log
• 大小: 3.6MB, 29,396 行
• 时间范围: 2026-01-11 12:06:53 ~ 14:17:27 (约2小时10分钟)
• 设备: iOS (iPhone)
• 网络: WiFi + VPN (utun4隧道)

错误统计总览

断链事件汇总

第一波断链详细分析

断链 #1 (行 10011-10012)

时间线:

13:25:46.101  开始连接，5个备选地址
13:25:46.107  连接成功 sock:14 → 47.86.xx.xx:1883 (RTT=6ms)
13:25:46.107  设置心跳超时闹钟 210秒
13:25:46.108  发送心跳包 215字节
13:25:48.550  断开连接 (仅2.4秒后!)

完整日志:

[I][13:25:46.101] complex.conn [::ffff:47.86.xx.xx]:1883
[I][13:25:46.101] complex.conn [::ffff:8.218.xxx.xxx]:1884
[I][13:25:46.101] complex.conn [::ffff:47.91.xxx.xxx]:1884
[I][13:25:46.101] complex.conn [::ffff:47.76.xxx.xxx]:1884
[I][13:25:46.107] index:0, sock:14, (47.86.xx.xx:1883), connected Rtt:6
[I][13:25:46.107] task socket connect suc sock:14, host:log.xxx.cn, ip:47.86.xx.xx, port:1883, local_ip:172.31.xxx.xxx, local_port:61691
[I][13:25:46.107] start noop synccheck taskid:4294967294, cmdid:10, next:210000
[I][13:25:46.108] task socket send sock:14, all send:215, count:1, sub send taskid:4294967294, cmdid:10
[E][13:25:48.550] noop fail timeout, interval:210000
[W][13:25:48.550] task socket close sock:14, remote disconnect, net_type:no_ssid_wifi
                  tcpi_txpackets=0x1, tcpi_txbytes=0xD7(215), tcpi_rxbytes=0x0
[I][13:25:48.551] longlink lifetime:2444ms

TCP状态分析:

• tcpi_txpackets=0x1 - 发送了1个TCP包
• tcpi_txbytes=0xD7 - 发送了215字节 (心跳包)
• tcpi_rxpackets=0x1 - 收到1个TCP包 (仅三次握手ACK)
• tcpi_rxbytes=0x0 - 没有收到任何应用层数据

结论: 连接建立后，心跳包发送成功，但服务器未响应任何数据，2.4秒后连接被断开。

断链 #2 (行 10212-10213)

时间线:

13:25:49.904  重连开始
13:25:49.905  连接成功 sock:14 → 47.86.xx.xx:1883 (RTT=1ms)
13:25:49.905  发送心跳包 215字节
13:25:52.315  断开连接 (2.4秒后)

完整日志:

[I][13:25:49.905] task socket connect suc sock:14, host:log.xxx.cn, ip:47.86.xx.xx, port:1883, local_ip:172.31.xxx.xxx, local_port:61692
[I][13:25:49.905] start noop synccheck taskid:4294967294, cmdid:10, next:210000
[I][13:25:49.905] task socket send sock:14, all send:215, count:1
[E][13:25:52.315] noop fail timeout, interval:210000
[E][13:25:52.315] task socket close sock:14, recv len: -1 errno:54(Connection reset by peer)
                  tcpi_txpackets=0x1, tcpi_txbytes=0xD7(215), tcpi_rxbytes=0x0
[I][13:25:52.315] longlink lifetime:2411ms

特殊发现: 这次是 Connection reset by peer (errno:54)，服务器主动发送了TCP RST包。

断链 #3-18 (行 10413-17573)

模式相同:

• 每次连接成功后约2-5秒断开
• TCP状态都显示：发送成功，但未收到响应数据
• 断开原因：remote disconnect 或 Connection reset by peer

典型日志模式:

[I] 连接成功 sock:XX → 47.86.xx.xx:1883
[I] 发送心跳包 215字节
[E] noop fail timeout (2-5秒后)
[W] task socket close, remote disconnect
    tcpi_txbytes=0xD7, tcpi_rxbytes=0x0

第二波断链详细分析

断链 #19 (行 17831)

时间线:

13:33:22.361  开始连接
13:33:22.362  连接成功 sock:51 → 47.86.xx.xx:1883 (RTT=2ms)
13:33:22.363  发送心跳包 215字节
13:33:24.605  发送业务数据 taskid:201, cgi:/im, 58字节
13:33:24.809  断开连接 (2.4秒后)

完整日志:

[I][13:33:22.362] task socket connect suc sock:51, host:log.xxx.cn, ip:47.86.xx.xx, port:1883, local_ip:172.31.xxx.xxx, local_port:61773
[I][13:33:22.363] start noop synccheck taskid:4294967294, cmdid:10, next:210000
[I][13:33:22.363] task socket send sock:51, all send:215, count:1
[I][13:33:24.605] PROTO -> TASK taskid:201 cmdid:11 cgi:/im, topic:GPGI, body size:43
[I][13:33:24.605] task socket send sock:51, all send:58, count:1, sub send taskid:201, cmdid:11, /im
[E][13:33:24.809] noop fail timeout, interval:210000
[W][13:33:24.809] task socket close sock:51, remote disconnect
                  tcpi_txpackets=0x2, tcpi_txbytes=0x111(273), tcpi_rxbytes=0x0

TCP状态分析:

• tcpi_txpackets=0x2 - 发送了2个TCP包
• tcpi_txbytes=0x111 - 发送了273字节 (215+58，心跳+业务数据)
• tcpi_rxbytes=0x0 - 仍然没有收到任何应用层数据

业务影响:

[W][13:33:24.810] task error, taskid:0, cmdid:0, error_type:4, error_code:-10090
[W][13:33:24.810] task end retry long cmdid:11, err(4, -10090, -1), cgi:/im, taskid:201

IP被禁用现象

在第二波断链后，系统开始禁用失败的IP:

[W][13:33:26.214] ip:47.86.xx.xx, port:80, is ban!! (ban time:1080000ms = 18分钟)

到第三波时禁用时间增加:

[W][13:42:55.638] ip:47.86.xx.xx, port:80, is ban!! (ban time:1800000ms = 30分钟)

第三波断链详细分析

断链 #20 (行 20485)

时间线:

13:42:54.079  开始连接
13:42:54.081  连接成功 sock:40 → 47.86.xx.xx:1883 (RTT=2ms)
13:42:54.081  发送心跳包 215字节
13:42:54.681  发送业务数据 taskid:211, cgi:/im, 58字节
13:42:56.472  断开连接 (2.4秒后)

完整日志:

[E][13:42:56.472] noop fail timeout, interval:210000
[W][13:42:56.473] task socket close sock:40, remote disconnect, net_type:no_ssid_wifi
                  tcpi_txpackets=0x2, tcpi_txbytes=0x111(273), tcpi_rxbytes=0x0
[I][13:42:56.473] longlink lifetime:2392ms
[W][13:42:56.474] task error, taskid:0, cmdid:0, error_type:4, error_code:-10090
[W][13:42:56.474] task end retry long cmdid:11, err(4, -10090, -1), cgi:/im, taskid:211

短连接也受影响

短连接断链 (行 20493):

[I][13:42:55.059] task socket send sock:62, taskid:212, cgi:/im, http len:513
[E][13:42:57.501] task socket close sock:62, taskid:212, cgi:/im, remote disconnect
                  nread:0, nwrite:Undefined error: 0
                  tcpi_txbytes=0x201(513), tcpi_rxbytes=0x0
[W][13:42:57.502] task end retry short cmdid:11, err(4, -10090, -1), cgi:/im, taskid:212

Connection Reset 详细分析 (9次)

Reset #1 (行 10213)

时间: 13:25:52.315
sock: 14
服务器: 47.86.xx.xx:1883
错误: errno:54(Connection reset by peer)
发送: 215字节, 接收: 0字节
连接时长: 2.4秒

Reset #2 (行 16746)

时间: 13:28:42.539
sock: 51
服务器: 47.86.xx.xx:1883
错误: errno:54(Connection reset by peer)
发送: 215字节, 接收: 0字节

Reset #3 (行 18416) - 短连接

时间: 13:33:32.676
sock: 61
taskid: 202
cgi: /im
错误: Connection reset by peer
发送: 513字节, 接收: 0字节

Reset #4 (行 20140)

时间: 13:33:58.365
sock: 51
服务器: 47.86.xx.xx:1883
错误: errno:54(Connection reset by peer)
发送: 303字节(0x12F), 接收: 0字节

Reset #5 (行 22102)

时间: 13:43:15.207
sock: 70
服务器: 47.86.xx.xx:1883
错误: errno:54(Connection reset by peer)
发送: 239字节(0xEF), 接收: 0字节

Reset #6 (行 22490) - 短连接

时间: 13:43:17.790
sock: 75
taskid: 224
cgi: /im
错误: Connection reset by peer
发送: 513字节, 接收: 0字节

Reset #7 (行 23961)

时间: 13:43:53.181
sock: 55
服务器: 47.86.xx.xx:1883
错误: errno:54(Connection reset by peer)
发送: 215字节, 接收: 0字节

Reset #8 (行 24169)

时间: 13:43:58.171
sock: 55
服务器: 47.86.xx.xx:1883
错误: errno:54(Connection reset by peer)
发送: 215字节, 接收: 0字节

Reset #9 (行 25117) - 短连接

时间: 13:47:25.713
sock: 61
taskid: 235
cgi: /route
错误: Connection reset by peer
发送: 695字节(0x2B7), 接收: 0字节

关键发现

1. 所有断链的共同特征

2. TCP状态分析

所有断链的TCP状态都显示:

tcpi_txpackets >= 1      # 发送包数 ≥ 1
tcpi_txbytes > 0         # 发送字节数 > 0
tcpi_rxpackets = 1       # 只收到TCP握手的ACK
tcpi_rxbytes = 0         # 没有收到任何应用层数据
tcpi_txretransmitbytes = 0  # 无重传

3. 断开原因分布

4. 问题发生时间规律

第一波: 13:25:48 开始 (应用运行约1小时19分钟后)
第二波: 13:33:24 开始 (距第一波约8分钟)
第三波: 13:42:56 开始 (距第二波约10分钟)

根因分析

最可能的原因: VPN隧道导致的数据包丢失

证据链:

1. TCP三次握手成功 (rxpackets=1)
2. 客户端数据发送成功 (txbytes > 0, txretransmitbytes = 0)
3. 但没有收到任何服务器响应 (rxbytes = 0)
4. 服务器在约2秒后主动断开连接

推断:

• VPN隧道可能在TCP握手后出现了数据通道问题
• 客户端发送的数据可能没有到达服务器
• 或者服务器的响应没有通过VPN隧道返回客户端
• 服务器等待约2秒后检测到客户端无响应，主动断开连接

其他可能原因

1. 服务器端主动拒绝: 服务器收到请求后主动发送RST
2. 中间设备干扰: 防火墙或负载均衡器拦截了数据
3. VPN NAT超时: VPN的NAT表项超时导致后续数据无法传输

给技术团队的排查建议

服务端排查

1. 检查 47.86.xx.xx:1883 在 13:25:46~13:47:30 时间段的连接日志
2. 确认是否收到了客户端的心跳包 (215字节)
3. 确认服务器是否发送了响应数据
4. 检查是否有安全策略导致连接被重置

客户端排查

1. 让用户关闭VPN测试连接稳定性
2. 抓包分析数据是否真正发送到服务器
3. 检查VPN应用的配置和日志

网络排查

1. 检查VPN隧道的MTU设置
2. 检查是否有数据包分片问题
3. 检查VPN服务器的负载情况

附录: 服务器地址列表

其他错误详细分析

1. 长连接主机为空 (longlink host empty) - 行 325

时间: 12:07:08.644

时间线:

12:07:08.640  数据库版本设置完成 (version 45)
12:07:08.642  打开用户数据库
12:07:08.643  GetMessageTimeline 获取消息时间线
12:07:08.643  Connect: log.xxx.cn 开始连接
12:07:08.643  RequestRoute isRouting 正在路由中
12:07:08.643  短连接任务开始 taskid:2, cgi:/route
12:07:08.644  make sure longlink connect 确保长连接
12:07:08.644  -> GetLongLinkItems 获取长连接地址
12:07:08.644  [ERROR] longlink host empty ← 错误发生!
12:07:08.644  <- GetLongLinkItems +0 (返回0个地址)
12:07:08.658  [ERROR] vecaddr empty 导致socket创建失败

完整日志:

[I][12:07:08.640] Set db version:45
[E][12:07:08.642] open db /var/mobile/Containers/Data/Application/6C54****4501/Documents/35ce****79af/D5F5****2442/data
[I][12:07:08.643] GetMessageTimeline node:, head:0, recvHead:0, readHead:0, groupHead:0, friendRequestHead:0
[I][12:07:08.643] Connect: log.xxx.cn
[I][12:07:08.643] RequestRoute isRouting
[I][12:07:08.643] task start long short taskid:2, cmdid:11, need_authed:false, cgi:/route
[I][12:07:08.643] make sure longlink connect
[I][12:07:08.644] -> GetLongLinkItems
[E][12:07:08.644] longlink host empty.
[I][12:07:08.644] <- GetLongLinkItems +0
[I][12:07:08.644] task socket dns ip: proxytype:0 useproxy:false

根因分析:

• 应用启动时，长连接服务器地址列表尚未配置
• 需要先通过短连接的 /route 接口获取长连接服务器地址
• 这是正常的启动时序，不是严重错误

后续恢复:

12:07:08.859  短连接 /route 请求成功，获取到服务器地址
12:07:08.860  SetLongLink server addr: log.xxx.cn:1883, im.xxx.com:1884

2. 地址列表为空 (vecaddr empty) - 行 555

时间: 12:07:08.658

时间线:

12:07:08.644  longlink host empty (无服务器地址)
12:07:08.644  task socket dns ip 开始DNS解析
12:07:08.657  输出网络栈信息 (VPN网络环境)
12:07:08.658  [ERROR] task socket close sock:-1 vecaddr empty
12:07:08.658  connect status from:1 to:4 (连接失败)
12:07:08.658  onConnectionStatusChanged:-4 (通知连接失败)

完整日志:

[I][12:07:08.657] ipstack log:
  defaultgateway6:::10.0.0.0
  defaultgateway:10.220.xxx.xxx
  dns server0:AF_INET, 8.8.8.8
  interface name:pdp_ip0, AF_INET, ip:10.220.xxx.xxx
  interface name:en0, AF_INET, ip:192.168.xx.xx
  interface name:utun4, AF_INET, ip:172.31.xxx.xxx ← VPN接口
[E][12:07:08.658] task socket close sock:-1 vecaddr empty
[I][12:07:08.658] connect status from:1 to:4, nettype:1
[W][12:07:08.658] task error, taskid:0, cmdid:0, error_type:3, error_code:-10606
[I][12:07:08.658] ReportLongIP _is_success=false, ip=, port=0

网络环境信息:

• WiFi接口: en0, IP: 192.168.xx.xx
• 蜂窝接口: pdp_ip0, IP: 10.220.xxx.xxx
• VPN接口: utun4, IP: 172.31.xxx.xxx ← 当前使用
• DNS服务器: 8.8.8.8

根因分析:

• 这是 longlink host empty 的直接后果
• 没有服务器地址，无法创建socket连接
• sock:-1 表示socket未成功创建
• 是启动时序的正常现象，等待路由请求完成后自动恢复

3. 数据库唯一约束错误 (UNIQUE constraint failed) - 行 1248-1768

时间: 12:07:10.419 ~ 12:07:10.850 (集中在0.4秒内)

触发场景:

12:07:10.403  PROTO -> TASK errorcode:0
12:07:10.403  PROTO -> TASK business code:255 (需要处理更多数据)
12:07:10.405  response data size 497345 (收到497KB数据)
12:07:10.417  PullMessage success size:497345 count:2279 (拉取2279条消息)
12:07:10.419  [ERROR] UNIQUE constraint failed: t_message._uid ← 开始报错
12:07:10.422  [ERROR] UNIQUE constraint failed: t_message._uid
... (连续10次)
12:07:10.850  [ERROR] UNIQUE constraint failed: t_message._uid

完整日志:

[I][12:07:10.405] PROTO -> response data size 497345
[I][12:07:10.417] PROTO -> PullMessage success size:497345 count:2279
[E][12:07:10.419] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.422] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.446] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.475] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.477] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.477] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[I][12:07:10.548] MessageTimeline 530532722563612801
...
[I][12:07:10.760] response data size 488511
[I][12:07:10.766] PullMessage success size:488511 count:1708
[E][12:07:10.834] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.834] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.846] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19
[E][12:07:10.850] finalize_db err:UNIQUE constraint failed: t_message._uid, code:19

根因分析:

• 表 t_message 的 _uid 字段有唯一约束
• 服务器下发的消息中存在重复的消息ID
• 可能原因:
  1. 客户端时间线不正确，导致服务器重复下发已存在的消息
  2. 服务端消息去重逻辑问题
  3. 客户端本地消息未正确清理

影响程度: 中等

• 不影响网络连接
• 可能导致部分消息无法入库
• 用户可能看到消息丢失或重复

4. 群组ID为空 (empty groupIds) - 行 1328

时间: 12:07:10.573

时间线:

12:07:10.561  task start long short taskid:9, cmdid:11, cgi:/im (拉取消息任务)
12:07:10.561  PROTO -> TASK topic:GPGM (GetPreviousGroupMessages)
12:07:10.564  task socket connect success sock:60
12:07:10.564  task socket send sock:60, http len:513
12:07:10.573  [ERROR] empty groupIds or duplicate ids ← 错误发生
12:07:10.574  get user info refresh 79ae****9efc

完整日志:

[I][12:07:10.561] PROTO -> TASK after package:taskid:9 cmdid:11 cgi:/im send_only:0
  type:48
  topic:GPGM
  body size:36
[I][12:07:10.564] task socket connect success sock:60, taskid:9, cgi:/im
[I][12:07:10.564] task socket send sock:60, taskid:9, cgi:/im, http len:513
[E][12:07:10.573] error!!!! empty groupIds or duplicate ids
[E][12:07:10.574] get user info refresh 79ae****9efc, 0,ver:1

根因分析:

• 在处理群组相关请求时，传入的群组ID列表为空或存在重复
• 可能是业务逻辑问题，在调用群消息接口前未正确验证参数
• 代码位置: business.cc 第 3758 行

影响程度: 低

• 单次业务调用失败
• 不影响整体连接稳定性

5. 用户信息刷新 (getUserInfo refresh) - 55+次

时间分布: 12:07:10 ~ 13:27:31 (持续约80分钟)

典型日志:

[E][12:07:10.574] get user info refresh 79ae****9efc, 0,ver:1
[E][12:07:10.871] get user info refresh 35ce****79af, 0,ver:1
[E][12:08:52.010] get user info refresh fd8a****c555, 1,ver:0
[E][13:10:09.589] get user info refresh wfc_file_transfer, 0,ver:1
[E][13:10:13.426] get user info refresh 35ce****79af, 1,ver:0
[E][13:27:31.895] get user info refresh 32bf****057a, 1,ver:0

参数解析:

• 第二个数字 (0或1): 可能表示是否强制刷新
• ver: 当前本地缓存的用户信息版本号

根因分析:

• 本地缓存的用户信息过期或版本不匹配
• 需要从服务器重新获取最新用户信息
• 这是正常的业务逻辑，不是错误

影响程度: 低

• 标记为 [E] 但实际上是业务正常流程
• 会触发网络请求获取用户信息
• 可能在弱网环境下增加请求数量

错误影响评估

报告生成时间: 2026-01-11

日志详情