分析客户端协议栈日志

本章节是为支持现场及研发工程师所准备的，目的是能够快速解决现场问题，或者提供准确有效的现场信息供后方分析解决。

1. 日志的抓取和解压

抓取就不说了，各个平台都有抓取日志的方法，请参考文档中的方法。日志格式是微信的xlog格式，解压方式请从微信mars上查找。

2. 日志的及时性

xlog日志会先写入到一个内存映射文件中，当存储达到一定量后再刷入xlog日志文件中。有时无法连接但日志量又非常少时，可能xlog日志为空。此时需要多做一些操作直到写入数据为止。

3. 需要记录操作时间

凡是看过xlog日志的都会发现，日志内容非常繁多，如果没有时间相当于大海捞针。所以当遇到问题时，一定记录操作时间。提交日志时把日志和操作步骤和操作时间一并提交，操作时间精确到分钟就可以了。

4. TASK

mars的网络操作都是以Task为单位进行处理的，下面是一个task在发出前的日志：

[日期/文件/行号等][PROTO -> TASK after package:taskid:4 cmdid:11 channel_id:0 channel_select:3 cgi:/im send_only:0 need_authed:1 limit_flow:0 limit_frequency:0 network_status_sensitive:0 channel_strategy:1 priority:3 retry_count:-1 server_process_cost:-1 total_timetout:-1
type:48
topic:UPUI
body size:29

从上面日志看到taskid是4；channel_select是3，1是短连接，2是长连接，3是都有可能；type是固定48，后面可能会去掉；topic是请求的主题，主题列表可以参考 https://gitee.com/wfchat/im-server/blob/wildfirechat/broker/src/main/java/win/liyufan/im/IMTopic.java 专业版稍微多一些，但这个应该够查询问题了；最后就是包的大小。

下一步就是发起网络请求了，如果是长连接就无需建立连接，如果是短链接，还需要连接过程。上一步得到taskid后就可以用taskid来搜索这个task的完整生命周期，比如上面的日志taskid是4，那么搜索：

taskid:4

当然如果允许足够长时间，这个taskid还是可能会重复的，可以根据时间来判断是否是同一个task。如果task失败了，还会重试一次，taskid保持不变。

如果是短链接服务，可以看到DNS的字样，每次短链接建立之前都会先进行域名解析，这个时候就要看一下域名对不对（是不是对应的节点），解析出来的IP地址对不对（是不是对应的IP），下面会建立连接，看看IP+端口是否正确。

当task到达IM服务并得到响应之后，会打印出来执行结果

[日期/文件/行号等][PROTO -> TASK(taskid:4 cmdid:11 channel_id:0 channel_select:3 cgi:/im send_only:0 need_authed:1 limit_flow:0 limit_frequency:0 network_status_sensitive:0 channel_strategy:1 priority:3 retry_count:-1 server_process_cost:-1 total_timetout:-1
type:48
topic:UPUI
body size:29
) has response
[日期/文件/行号等][PROTO -> TASK errorcode:0
[日期/文件/行号等][PROTO -> TASK business code:0(0success, otherwise failure)
[日期/文件/行号等][PROTO -> response data size 26

前面还是task的打印信息，has response表示是从服务返回的响应，如果网络问题未能到达IM服务会是其他错误；TASK business code:0是业务的代码，代码列表请参考 https://gitee.com/wfchat/im-server/blob/wildfirechat/common/src/main/java/cn/wildfirechat/common/ErrorCode.java ；这之后根据task的内容不同，还是打印出更多信息，比如route任务会打印出来从服务器返回的节点地址和端口，如果是拉取消息任务，会打印多少条。

如果task未能到达IM服务会得到如下日志：

[日期/文件/行号等][task end callback  long cmdid:11, err(9, -1, -15), svr(80.251.218.41:1882, DNSIP, 80.251.218.41), cli(, , n:SIMULATOR, sig:0), cost(s:0, r:0, c:0, rw:0), all:70422, retry:0, cgi:/im, taskid:48, tid:105553140744192
[日期/文件/行号等][PROTO -> TASK DESCRIPTIONS:taskid:48 cmdid:11 channel_id:0 channel_select:2 cgi:/im send_only:0 need_authed:1 limit_flow:0 limit_frequency:0 network_status_sensitive:0 channel_strategy:0 priority:3 retry_count:-1 server_process_cost:-1 total_timetout:-1
type:48
topic:MS
body size:38
 end with orror:-1

第一行会打印任务结束的信息，包括taskid，去连接的服务器信息（ip，端口等），还有个重要的信息err，包含3部分，只关注前两个，第一个是_err_type，第二个是对应errtype下的错误码。错误类型包括如下：

//error type
enum ErrCmdType {
    kEctOK = 0,
    kEctFalse = 1,
    kEctDial = 2,
    kEctDns = 3,
    kEctSocket = 4,
    kEctHttp = 5,
    kEctNetMsgXP = 6,
    kEctEnDecode = 7,
    kEctServer = 8,
    kEctLocal = 9,
  kEctCanceld = 10,
};

错误码包括如下：


//error code
enum {
    kEctLocalTaskTimeout = -1,
    kEctLocalTaskRetry = -2,
    kEctLocalStartTaskFail = -3,
    kEctLocalAntiAvalanche = -4,
    kEctLocalChannelSelect = -5,
    kEctLocalNoNet = -6,
    kEctLocalCancel = -7,
    kEctLocalClear = -8,
    kEctLocalReset = -9,
    kEctLocalTaskParam = -12,
    kEctLocalCgiFrequcencyLimit = -13,
    kEctLocalChannelID = -14,

};

// -600 ~ -500
enum {
    kEctLongFirstPkgTimeout = -500,
    kEctLongPkgPkgTimeout = -501,
    kEctLongReadWriteTimeout = -502,
   // kEctLongTaskTimeout = -503,
};

// -600 ~ -500
enum {
    kEctHttpFirstPkgTimeout = -500,
    kEctHttpPkgPkgTimeout = -501,
    kEctHttpReadWriteTimeout = -502,
  //  kEctHttpTaskTimeout = -503,
};

// -20000 ~ -10000
enum {
    kEctSocketNetworkChange = -10086,
    kEctSocketMakeSocketPrepared = -10087,
    kEctSocketWritenWithNonBlock = -10088,
    kEctSocketReadOnce = -10089,
    kEctSocketShutdown = -10090,
    kEctSocketRecvErr = -10091,
    kEctSocketSendErr = -10092,
    kEctSocketNoopTimeout = -10093,
    kEctSocketNoopAlarmTooLate = -10094,
    kEctSocketUserBreak = -10095,

    kEctHttpSplitHttpHeadAndBody = -10194,
    kEctHttpParseStatusLine = -10195,

    kEctNetMsgXPHandleBufferErr = -10504,

    kEctDnsMakeSocketPrepared = -10606,
};

上面日志中error type是9，也就是kEctLocal，是客户端本地网络出现了问题，-1是时间超时，长时间无法进行联网，这个是端开网络测试的。

5. 日志启动开始的流程

我们一般都是从setAuthInfo搜索开始看日志，这个日志是上层调用connect打印出来的第一个重要日志，能够看出协议栈的编译时间，是否使用国密（sm4），是否使用AES256，用户ID，token的前20个字符。

[日期/文件/行号等][business.cc, setAuthInfo, 4226][protocol revision:8b415985, build time:2024-07-04 11:52:59, use sm4:false, aes256:false, userId:000000000000033333, token:Uf8upEYWW85fFl757WhG

下一行会打印出来sqlite数据库的位置，位置中包含了当前设备的clientId。

[日期/文件/行号等][open db /var/mobile/Containers/Data/Application/01F9374E-F26C-4FAD-ADA6-3412B8EA3804/Documents/000000000000033333/F11D0280-8B16-4B02-XXXX-3562DFAEDAC5/data

在下面是打开数据库和数据库升级(如果是首次安装或者数据库有升级)。

[日期/文件/行号等][DB2.cc, Open, 544][open db done
[日期/文件/行号等][DB2.cc, Upgrade, 1023][DB current version:44

之后就是task执行了，第一个重要的task就是ROUTE，这个task至关重要，是个短链接task，检查一下task请求的地址端口域名解析等情况，如果从服务器返回，0是成功，1是token不匹配，7是当前客户端被踢，8是用户被封禁，22是未授权等。如果是成功，task下面会打印出

[日期/文件/行号等][task set longlink server addr, host:im.wildfirechat.cn port:1883 debugip:

从日志可以看到长连接的地址和端口，短链接的地址和端口未能打出（后面会加），只能从后面短链接的任务中来看了。

6. 日志的有效期

mars日志以天为分割存储，存储最近5天的日志，超过5天会自动删除。

如何分析客户端协议栈日志