技术分享 | OceanBase 错误日志分析

作者：操盛春

技术专家，任职于爱可生，专注研究 MySQL、Ocean Base 源码。

本文来源：原创投稿

*爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

OceanBase 运行时会产生很多各种级别的日志，如果出现了错误，想要从数量繁多的错误日志中定位到错误原因，是件不太容易的事。

错误日志是我们定位错误原因的主要途径，本文我们就来聊聊怎么从 OceanBase 错误日志中找到我们想要的错误信息。

1. 日志文件

OceanBase 日志分为 3 类：

选举模块日志：存放选举模块产生的日志。
总控服务（RootService）模块日志：存放总控服务模块产生的日志。
启动、运行日志：存放除选举模块、总控服务模块之外的其它所有模块产生的日志。

每类日志又包含 2 种日志文件：

.log、.log.YYYYmmDDHHMMSS 文件中包含该类型所有级别的日志。
.log.wf、.log.wf.YYYYmmDDHHMMSS 文件中包含该类型 WARN、USER_ERROR、ERROR 3个级别的日志（需要把系统配置 enable_syslog_wf 的值设置为 true）。

每类日志都写入到对应的 .log(.log.wf) 文件中，写满 256M 之后，把 .log(.log.wf) 文件改名（加上 .YYYYmmDDHHMMSS 后缀），然后再创建新的 .log（.log.wf）文件。

通过 ls -l 查看 OceanBase 日志目录，可以看到类似如下的日志文件：

-rw-r--r-- 1 admin admin  18688919 10月  9 02:08 election.log
-rw-r--r-- 1 admin admin   4998884 10月  9 02:07 election.log.wf
-rw-r--r-- 1 admin admin  75158675 10月  9 02:08 rootservice.log
-rw-r--r-- 1 admin admin 268437081 10月  8 23:25 rootservice.log.20221008232523
-rw-r--r-- 1 admin admin  61688030 10月  9 02:08 rootservice.log.wf
-rw-r--r-- 1 admin admin 227610855 10月  8 23:25 rootservice.log.wf.20221008232523
-rw-r--r-- 1 admin admin 156856561 10月  9 02:08 observer.log
-rw-r--r-- 1 admin admin 268435919 10月  9 01:25 observer.log.20221009012502
-rw-r--r-- 1 admin admin  91282191 10月  9 02:08 observer.log.wf
-rw-r--r-- 1 admin admin 158605686 10月  9 01:25 observer.log.wf.20221009012502

2. 日志格式

按照日志错误级别不同，OceanBase 格式分为 2 种：

DEBUG、TRACE、INFO 日志记录格式

[time] log_level [module_name] file_name:fine_no [thread_id][coroutine_id][Ytraceid0-traceid1] [lt=last_log_print_time] [dc=dropped_log_count] log_data

WARN、USER_ERROR、ERROR 日志记录格式

[time] log_level [module_name] function_name (file_name:fine_no) [thread_id][coroutine_id][Ytraceid0-traceid1] [lt=last_log_print_time] [dc=dropped_log_count] log_data

2 种日志格式的不同之处是：WARN、USER_ERROR、ERROR 日志记录多了 function_name 字段。

这些日志字段中，需要重点介绍 3 个字段：

trace_id： 格式为 Ytraceid0-traceid1，例如：YB420ABA3C91-0005E98FC3148792。

一条 SQL 在整个 OBServer 集群中对应唯一的 trace_id，通过 trace_id 可以找到一条 SQL 执行过程中在整个集群中打印的所有日志。

lt： lt = last_log_print_time，写日志方式不同，此字段值表示的含义也不同：

异步写日志：该字段值表示本条日志格式化消耗的时间，格式化指的是：源码中把本条日志所有字段拼接到一起得到字符串格式内容的过程。
同步写日志：该字段值表示上一条日志从格式化到写入日志文件成功消耗的时间。根据这个写入时间和上一条日志的内容长度，能够反映出写上一条日志时的磁盘 IO 负载。

为什么记录的是上一条日志，而不是本条日志写入过程消耗的时间？

因为在格式化本条日志的时候，还不知道本条日志成功写入日志文件需要消耗多长时间，记录本条日志消耗的时间就只能留给后来者（也就是本条日志的下一条日志）去做了。

dc： dc = dropped_log_count，表示自上一条日志成功写入日志文件以来，到当前这条日志为止，中间有多少条日志（包含所有级别的日志）写入失败了，只有异步日志记录中有这个字段。

异步写入日志失败的原因有以下几种：

为日志记录分配内存失败。
格式化日志失败（格式化的定义参照前面 lt 字段异步写日志中的定义）。
每秒写入的日志量超过最大限制了。
日志内容等待加入日志队列超时，队列中最多能加入的日志数量由 MAX_BUFFER_ITEM_CNT 常量控制，固定值为 524288。

3. 分析日志

如果执行某条 SQL 出现了错误，OceanBase 会给出错误码和错误信息，有时候这个错误信息并不明确，想要找到更明确的信息，可以按照 2 个步骤进行。

3.1 根据错误码找到 trace_id

因为 trace_id 在一个集群中唯一标识一条 SQL，所以第一步是从错误日志中找到 trace_id，按照以下顺序进行：

先根据错误码去 observer.log.wf 文件找 trace_id。
如果 observer.log.wf 中没找到，再去 rootservice.log.wf 文件找。
如果 rootservice.log.wf 中没找到，再去 election.log.wf 文件找。

为什么要按上面的文件顺序找 trace_id？

选举过程并不是只涉及到选举模块，还会涉及到总控服务模块（RS）、其它模块，所以选举过程中，在 observer.log.wf、rootservice.log.wf、election.log.wf 中都会产生日志记录。
总控服务提供的功能，最终也要由集群中的 OBServer 执行，整个过程除了会涉及总控服务模块，还会涉及其它模块。
鉴于以上 2 点，不管执行的是什么 SQL，都要由最终干活的角色去执行，而 observer.log.wf 中记录的就是最终干活的角色产生的日志，这里最有可能记录着错误的源头，为此先从 observer.log.wf 入手。

接下来以 OceanBase 创建资源池为例，介绍从日志文件中查找错误信息的过程：

obclient [(oceanbase)]> CREATE RESOURCE POOL mini_pool_t4 unit=mini_1,unit_num=1;
ERROR 4624 (HY000):  machine resource 'z1' is not enough to hold a new unit

创建资源池报错，错误码为 4624，先根据错误码从 observer.log.wf文件中过滤错误日志，过滤字符串的格式为：ret=-错误码（注意错误码前面的负号）。

[admin@localhost log]$ grep "ret=-4624" observer.log.wf
[2022-10-09 06:39:25.317545] WARN  [SQL.ENG] execute (ob_resource_executor.cpp:42) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=63] [dc=0] rpc proxy create resource_pool failed(ret=-4624)
[2022-10-09 06:39:25.317883] WARN  [SQL] open_cmd (ob_result_set.cpp:84) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] execute cmd failed(ret=-4624)
[2022-10-09 06:39:25.317994] WARN  [SQL] sync_open (ob_result_set.cpp:133) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=96] [dc=0] fail to exec execute()(ret=-4624)
[2022-10-09 06:39:25.353385] WARN  [SERVER] response_result (ob_sync_cmd_driver.cpp:60) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=14] [dc=0] close result set fail(cret=-4624)
[2022-10-09 06:39:25.353471] WARN  [SERVER] test_and_save_retry_state (ob_query_retry_ctrl.cpp:117) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=29] [dc=0] ddl, and errno is not OB_EAGAIN or OB_SNAPSHOT_DISCARDED or OB_ERR_PARALLEL_DDL_CONFLICT, do not need retry(client_ret=-4624, err=-4624, retry_type_=0)
[2022-10-09 06:39:25.353593] WARN  [SERVER] response_result (ob_sync_cmd_driver.cpp:64) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] result set open failed, check if need retry(ret=-4624, cli_ret=-4624, retry_ctrl_.need_retry()=0)
[2022-10-09 06:39:25.353969] WARN  [SERVER] do_process (obmp_query.cpp:674) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=9] [dc=0] execute query fail(ret=-4624, timeout_timestamp=1665298548583953)
[2022-10-09 06:39:25.354347] WARN  [SERVER] process (obmp_query.cpp:291) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=18] [dc=0] fail execute sql(sql_id="", sql=CREATE RESOURCE POOL mini_pool_t4 unit=mini_1,unit_num=1, sessid=3221633143, ret=-4624, ret="OB_MACHINE_RESOURCE_NOT_ENOUGH", need_disconnect=false)

上面过滤出来的错误日志中，YB420ABA3C91-0005E98FC5948785 就是 trace_id。

从 observer.log.wf 文件中，一般都能找到 trace_id，如果万一没找到，再依次从 rootservice.log.wf、election.log.wf 中找。

如果从上面 3 个日志文件中都没找到，那就是碰上特殊情况了，可以用报错中的错误信息依次从 observer.log.wf、rootservice.log.wf、election.log.wf 中找，例如：

[admin@localhost log]$ grep "machine resource 'z1' is not enough to hold a new unit" observer.log.wf
[2022-10-09 08:17:02.170951] WARN  log_user_error_and_warn (ob_rpc_proxy.cpp:300) [13567][2307][YB420ABA3C91-0005E98FC5C48785] [lt=7] [dc=0]  machine resource 'z1' is not enough to hold a new unit

3.2 根据 trace_id 查找错误日志

从 3.1 根据错误码找到 trace_id 小节可以看到，根据错误码或者错误信息也能过滤出很多错误日志，为什么还要多此一举，再根据 trace_id 查找错误日志？

因为通过错误码或错误信息过滤出来的日志，有可能把非常关键的日志记录给过滤掉了，而通过 trace_id 能够拿到更完整的日志。

根据 trace_id 查找错误日志，也一样先从 observer.log.wf 中开始找，如果找到了能够确定错误原因的信息，就此结束，否则再接着到 rootservice.log.wf、election.log.wf 中找。

这一步的流程就是通过 grep trace_id 从各个 .log.wf 文件中找到错误日志，不展开举例了。

4. 存在的问题

实际使用过程中，有时候并不能通过 Oceanbase 的错误日志找到明确的错误原因，这种情况下要找到错误原因，就只能靠我们的经验了。

根据前面介绍的步骤，从错误日志中找到蛛丝马迹，然后按照猜测-验证流程，一点一点排查。

例如：OBServer 集群用以下 SQL 进行 BOOTSTRAP 选举，报 Timeout 错误，最终就不能通过错误日志直接定位到原因：

obclient [(none)]> ALTER SYSTEM BOOTSTRAP ZONE 'z1' SERVER 'xx.xx.xx.xx:2882',ZONE 'z2' SERVER 'xx.xx.xx.xx:2882',ZONE 'z3' SERVER 'xx.xx.xx.xx:2882';
ERROR 4012 (HY000): Timeout

通过多轮猜测-验证流程确定错误原因之后，反过来查看错误日志，发现最接近实际情况的日志如下：

[2022-10-09 09:05:32.052665] WARN  [BOOTSTRAP] execute_bootstrap (ob_bootstrap.cpp:759) [16840][446][YB420ABA3C91-0005EA9633379D17] [lt=21] [dc=0] failed to wait all rs online(ret=-4622)

错误日志中的 failed to wait all rs online，说明 BOOTSTRAP 操作正在等待所有 RootService 服务上线。

这个问题是由于集群中 3 个 OBServer 实例启动时，-z 参数都是 z1，而 BOOTSTRAP 指定的 RootService 服务器的 zone 却是 z1、z2、z3。

3 个 RootService 服务器都启动了，端口也是正常监听状态，OceanBase 却没有识别出来，错误日志中也就没能准确的记录错误信息了。

5. 两点期待

在日志方面，对于即将正式出品的 OB 4.0 版本有两点期待:

期待 1：如果 OceanBase 能够准确识别错误产生的原因，并记录到日志中，对于我们日常运维将会非常有帮助。

期待 2：.log.wf 文件中的错误日志记录，目前不能体现触发打印日志的方法之间的调用层级关系，不方便直接找到最后一个被调用的方法产生的错误日志。

如果能够在每条错误日志中记录触发打印当前日志的方法的调用层级，我们运维过程中就能够快速找到产生错误的方法，从而提升定位错误原因的效率。

调用层级类似下面这种形式（process、do_process 等方法前面的序号）：

[admin@localhost log]$ grep "YB420ABA3C91-0005E98FC5948785" observer.log.wf
[2022-10-09 06:39:25.317429] WARN  3.2.1.1.1 log_user_error_and_warn (ob_rpc_proxy.cpp:300) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=5] [dc=0]  machine resource 'z1' is not enough to hold a new unit
[2022-10-09 06:39:25.317545] WARN  [SQL.ENG] 3.2.1.1 execute (ob_resource_executor.cpp:42) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=63] [dc=0] rpc proxy create resource_pool failed(ret=-4624)
[2022-10-09 06:39:25.317883] WARN  [SQL] 3.2.1 open_cmd (ob_result_set.cpp:84) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] execute cmd failed(ret=-4624)
[2022-10-09 06:39:25.317994] WARN  [SQL] 3.2 sync_open (ob_result_set.cpp:133) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=96] [dc=0] fail to exec execute()(ret=-4624)
[2022-10-09 06:39:25.353385] WARN  [SERVER] 3 response_result (ob_sync_cmd_driver.cpp:60) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=14] [dc=0] close result set fail(cret=-4624)
[2022-10-09 06:39:25.353471] WARN  [SERVER] 3.1 test_and_save_retry_state (ob_query_retry_ctrl.cpp:117) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=29] [dc=0] ddl, and errno is not OB_EAGAIN or OB_SNAPSHOT_DISCARDED or OB_ERR_PARALLEL_DDL_CONFLICT, do not need retry(client_ret=-4624, err=-4624, retry_type_=0)
[2022-10-09 06:39:25.353593] WARN  [SERVER] 3 response_result (ob_sync_cmd_driver.cpp:64) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] result set open failed, check if need retry(ret=-4624, cli_ret=-4624, retry_ctrl_.need_retry()=0)
[2022-10-09 06:39:25.353969] WARN  [SERVER] 2 do_process (obmp_query.cpp:674) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=9] [dc=0] execute query fail(ret=-4624, timeout_timestamp=1665298548583953)
[2022-10-09 06:39:25.354347] WARN  [SERVER] 1 process (obmp_query.cpp:291) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=18] [dc=0] fail execute sql(sql_id="", sql=CREATE RESOURCE POOL mini_pool_t4 unit=mini_1,unit_num=1, sessid=3221633143, ret=-4624, ret="OB_MACHINE_RESOURCE_NOT_ENOUGH", need_disconnect=false)