作者：陶建辉
这是我在 2020 年 5 月写的一篇内部博客，当时是希望研发和技术支持同学能够帮助用户快速定位 Bug，解决问题。2020 年 12 月我又迭代了一版，并还针对此进行了内部的培训。这段时间我也一直在关注微信群中的提问，发现有不少用户觉得分析 TDengine 的日志或任何其他分布式系统的日志是有难度的。现在将我这篇博客公开，以分析 TDengine 的日志为例，介绍一套方法，如果你能掌握，那么分析分布式系统的日志就会变得极其之简单。
![]()
TDengine 是一个集群系统，任何一个操作，都会涉及到 APP、taosc、mnode 和 vnode 等逻辑节点。这些节点之间是通过 Socket 进行通讯的。而且在测试中，可能有多个 TDengine 实例，这让分析变得更为复杂。对于一个操作，如何将不同逻辑节点的日志匹配串通起来，高效过滤处理，成为分析问题的关键。
本文总结了一套方法，能够让大家快速找到 Bug 所在。
打开相关日志开关
TDengine 每个独立的模块都有自己的 debugFlag, 包括 taosc, dnode, vnode, mnode, tsdb, wal, sync, query, rpc, timer 等。目前每个模块的日志输出可以控制到：
- Fatal/Error，错误，日志上会显示 ERROR
- Warning，警告, 日志上会显示 WARN
- Info，重要信息
- Debug，一般信息
- Trace，非常详细且反复出现的调试信息
- Dump，原始数据
输出的日志可以控制输出到：
上述的控制全部由 debugFlag 的一个字节控制，这个字节里的 bit 图如下：
![]()
因此，如果要将 error, warning, info,debug 输出到日志文件，那么 debug 要设置为：135；如果还想输出 trace 级别的日志，那么 debug 要设置为：143；如果仅仅输出 error 和 warning, debug 设置为 131。正常情况下，建议将 debug 设置为 135 即可。
每个模块的 debug flag 的设置全部由配置文件 taos.cfg 控制，具体各模块的参数以及日志显示的模块名如下：
![]()
如果嫌配置参数过多，最简单的方式，是设置 debug 的总参数 debugFlag, 这个参数设置后，除 tmr 日志外，所有模块的 debug 全部统一设置为同一个参数 debugFlag。debugFlag 的默认值为 0，当 debugFlag 为非 0 值时，将会覆盖所有的日志配置参数。
除非特殊 case, 不建议设置 util, timer 的 debugFlag 为 135，设置为 131 合适。
日志文件
TDengine 会生成客户端以及服务器端日志，存放在日志目录里，缺省日志目录是/var/log/taos, 但可以通过修改 taos.cfg 里的配置参数 logDir 指定
- 客户端日志文件名为 taoslogY.X (因为可以运行多个客户端，因此一台机器上可以生成多个日志文件）
- 服务器端日志文件为 taosdlog.X
日志文件的大小有控制，达到一定行数（taos.cfg 里配置参数 numOfLogLines 控制）后，会生成新的日志文件。但 TDengine 仅仅保留两个日志文件，文件名以 0 或 1 结尾，交替。
日志格式：
![]()
日志文件，从左到右，分为四大块
- 时间戳，精确到微妙
- 线程 ID，因为是多线程，这个参数很重要，因为只有同一个线程输出的日志才是有时序保证的，是按设计的 flow 输出的
- 模块名，三个字母
- 每个模块输出的日志
分析日志的几大步骤
当测试或客户报告一个 Bug，无论是手动还是自动，都是执行某个具体操作发生的。这个具体操作一般都是执行一个 SQL 语句。这个问题可能是客户端导致，也可能是服务器代码导致。下面以 create table 为例，解释日志的分析，为便于聚焦解释，图中去掉时间戳。
先看客户端
最先需要查看的是客户端日志，示例截图如下：
- 先找到出问题的 SQL 语句，在客户端日志里搜索 “SQL: “，就可以看到(截图第二行）。日志里搜索“SQL result:”（截图第 11 行）, 如果成功，会显示 ”SQL result:success”, 否则会显示“SQL result: xxxx”, 其中 xxxx 是错误信息。如何快速找到失败的 SQL，需要知道大概的时间范围，SQL 语句是什么，这么搜索会很快。
- taoc 的日志数据，有个很重要的参数是 pSql，是分配给内部 SQL Obj 的一个地址。taosc 把这个地址信息放在所有 taosc 日志的最前面，紧接 TSC 之后。这个值很关键，是传统客户端与服务器日志的关键。在上面的截图中，用绿色背景标出。
- pSql 这个参数会作为 ahandle 传递至 RPC 模块，RPC 在所有消息里，都会将其打印处理（绿色背景）。因为很多模块都会调用 RPC 模块，RPC 也会把谁调用的打印出来，比如截图中，是 TSC 调用的，就会打印 RPC TSC 出来。
- RPC 会把消息 create-table 发往服务器，RPC 日志会打印出来（截图第 8 行), 告知发往到了哪个 dnode 的 End Point, 截图中显示发往了 hostname: 9be7010a917e, port 为 6030。如果有问题，那我们就需要检查这个 End Point 所在的服务器日志了。
- 能看到，RPC 模块收到了服务器的回应，但为避免转换消耗资源，日志仅仅显示了 16 进制的 IP 地址（截图第 9 行，0x20012ac)以及端口号。RPC 模块的日志很关键，因为它把各个逻辑节点串通起来。
再看服务器
分析了客户端日志，服务器日志很关键，下面仍然以 create-table 为例，请看截图:
![]()
- 从客户端日志里，找到 pSql，值是 0x5572c4fab3a0，因此在 taosdlog 里直接搜索 0x5572c4fab3a0，就可以看到截图中绿色背景的日志。因此 pSql 是将客户端与服务器日志串起来很重要的参数。
- 对于 create-table 这个具体操作而言，是有 mnode 处理。截图中，是因为创建第一张表，因此需要先创建 vnode, 然后创建 table 等系列操作，牵涉到很多模块，就不细解释。
- 最后，mnode 创建完 table, 通过 RPC 模块发回 response(截图第 52 行，最后一行），因此可以清晰的看出服务器工作正常。
注意：dnode 模块收到消息后，会根据消息类型，将消息分发到 mnode, vnode 的消息队列。然后工作线程会消费消息队列里的消息，对消息进行处理。对于 vnode 而言，里面的子模块 tsdb, wal, sync, cq 都是单线程执行的，因此在找到 pSql 之后（截图第二行），需要根据线程的 ID，顺序往下看，就能知道整个流程，很好分析。
几个关键点
- 先找到失败 SQL 语句
- 找到 pSql 的值，拷贝下来, 假设为 xxxxx
- grep “xxxxx” taoslogx.x, 找到与这条 SQL 相关的客户端日志，看能否找到问题
- 打开 taosdlog 服务器日志，搜索 pSql 的值 xxxxx, 检查时间戳，看是否是失败的那条操作
- 然后分析服务器日志
RPC 模块的消息十分关键。有一点很重要，对于每一条 RPC 消息，都会打印 parse code: xx, 这是协议解析结果，0 表示没有问题，其他值说明协议解析就不成功。但同时，消息本身还有 code: 0xXX, 这是发送方带来的错误码，一般是服务器发往客户端的，正确的话，code 是 0，否则就是报错。
另外一个日志匹配方法
客户端通过 RPC 模块发出一条消息时，日志上带有类似
sig:0x01000000:0x01000000:55893
这是 RPC 的 source ID, dest ID, 以及 transcation ID，三个参数组合在一起，能唯一标识来自一个客户端的链接。每条新消息的发送，都会将 transcation ID 加一，因此在一段时间内具有唯一性（transcation ID 是两字节，会循环的)。
1.6 版本只能依赖 sig 这个字符串将客户端与服务器日志匹配起来，但需要看很多上下文，因此麻烦，效率不够。
2.0 版将 pSql 传至服务器侧，这样客户端与服务器的日志匹配将大大加速。
熟悉日志的方法
- 首先要了解 TDengine 的设计，了解每个主要操作的流程。
- 打开所有日志开关(将 debugFlag 设为 135), 所有的 SQL 语句都执行一次，对照每条 SQL，检查对应的客户端与服务器日志。
查看客户端执行的 SQL 语句
客户端会产生很多日志，查看执行的 SQL 语句，便于分析和重复问题。找出系统到底执行了什么样的 SQL 语句，有几种方法
- 如果客户端日志打开，执行: grep “SQL: ” taoslog*, 会看到日志中所有执行的 SQL 语句。
- 如果用 taos，手工执行 SQL 语句，请在 home 目录里，查看隐藏的文件.taos_history, 里面会有 taos 执行的所有历史命令。
- 对客户端进行配置，在配置文件中，将 tscEnableRecordSql 参数设置为 1，即将客户端输入的 SQL 语句打印到单独的文件（tscnote-xxxx.0，xxxx 是 pid），与客户端日志所在目录相同。
- 对于 resetful 接口，在 taosd 的配置文件中将 httpEnableRecordSql 参数设置为 1， 会将 htpp 请求打印到单独的文件（httpnote.0），与服务端日志所在目录相同。
动态修改日志
有时不能重启服务器或客户端，但日志的设置又不正确，这个时候需要动态设置，执行如下几步：
show dnodes；// 查找每个 dnode 的 ID
alter dnode id debugFlag 143; // 设置相应的 debugFlag
其中第二步的 id 是第一步获取的。
有时需要把后续日志输出到一个新文件，方便日志的查看及搜索，执行：
alter dnode id resetlog;
有时 shell 根本链接不上，这时可以在 taosd 运行的机器，给进程发送 SIGUSR1 命令，如：
kill -SIGUSR1 pidxxx
原文首发于：https://mp.weixin.qq.com/s/LUz1niYajOR35UpOlfszIQ
