做者：陶建辉node
这是我在 2020 年 5 月写的一篇内部博客，当时是但愿研发和技术支持同窗可以帮助用户快速定位 Bug，解决问题。2020 年 12 月我又迭代了一版，并还针对此进行了内部的培训。这段时间我也一直在关注微信群中的提问，发现有很多用户以为分析 TDengine 的日志或任何其余分布式系统的日志是有难度的。如今将我这篇博客公开，以分析 TDengine 的日志为例，介绍一套方法，若是你能掌握，那么分析分布式系统的日志就会变得极其之简单。shell
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 控制，具体各模块的参数以及日志显示的模块名以下：url
若是嫌配置参数过多，最简单的方式，是设置 debug 的总参数 debugFlag, 这个参数设置后，除 tmr 日志外，全部模块的 debug 所有统一设置为同一个参数 debugFlag。debugFlag 的默认值为 0，当 debugFlag 为非 0 值时，将会覆盖全部的日志配置参数。
除非特殊 case, 不建议设置 util, timer 的 debugFlag 为 135，设置为 131 合适。spa
日志文件
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