背景

在 “DM 同步 modify column 语句到 TiDB 5.3 踩坑一：数据乱码” 中，看到一个异常的场景，上游 mysql 一条 ddl 语句同步到下游 tidb 中，竟然出现了多条的情况：

ddl重放1.jpg

期望的情况，一条 ddl sql 同步到下游只会执行到一次，所以这是个异常行为，可能存在 bug。

仔细观察上述重放的时间间隔，三条 ddl 恰好是间隔 5 分钟依次下发过来的，所以这里首先想到可能跟某项 5 分钟的设置有关系。

这个异常行为跟 modify column 的 bug，同时出现，当时给排查问题带来很大的复杂性。

查看 dm-worker 的日志，可以看到下面的日志情况：

[2022/02/24 10:36:33.638 +08:00] [INFO] [syncer.go:2352] ["start to handle ddls in normal mode"] [task=jiyftest] [unit="binlog replication"] [event=query] [queryEventContext="{schema: sbtest2, originSQL: alter table sbtest1 modify column k varchar(255), startLocation: position: (mysql-bin.000015, 787163815), gtid-set: , currentLocation: position: (mysql-bin.000015, 787163943), gtid-set: , lastLocation: position: (mysql-bin.000015, 787163943), gtid-set: , re-sync: , needHandleDDLs: ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255), trackInfos: {originDDL: ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255), routedDDL: ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255), sourceTables: `sbtest2`.`sbtest1`, targetTables: `sbtest2`.`sbtest1`}}"]
......
......
[2022/02/24 10:41:33.667 +08:00] [ERROR] [baseconn.go:184] ["execute statement failed"] [task=jiyftest] [unit="binlog replication"] [query="ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255)"] [argument="[]"] [error="invalid connection"]
[2022/02/24 10:41:33.667 +08:00] [ERROR] [baseconn.go:191] ["rollback failed"] [task=jiyftest] [unit="binlog replication"] [query="ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255)"] [argument="[]"] [error="invalid connection"]
[2022/02/24 10:41:33.668 +08:00] [ERROR] [db.go:221] ["execute statements failed after retry"] [task=jiyftest] [unit="binlog replication"] [queries="[ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255)]"] [arguments="[]"] [error="[code=10006:class=database:scope=not-set:level=high], Message: execute statement failed: ALTER TABLE `sbtest2`.`sbtest1` MODIFY COLUMN `k` VARCHAR(255), RawCause: invalid connection"]

从 dm worker 日志上看：

2022/02/24 10:36:33.638 +08:00 开始同步 ddl 到下游 tidb。

2022/02/24 10:41:33.667 +08:00 执行中出现 invalid connection 报错。

从 tidb ddl jobs 上看：

2022/02/24 10:41:34 新的 ddl 语句被同步到 tidb 执行

这两个时间恰好对的上，也就是说 dm 同步到下游 tidb，执行 ddl 语句的过程中，执行到 5 分钟出现

invalid connection 报错，然后 dm 从失败点恢复执行了相同的 ddl。

这里的 invalid connection 是没法看到具体的原因的，是 sql.conn 的 ExecContext 函数直接报出来的错误：

baseconn.go:184
........
_, err = txn.ExecContext(tctx.Context(), query, arg...)
......
tctx.L().ErrorFilterContextCanceled("execute statement failed",
        zap.String("query", utils.TruncateString(query, -1)),
        zap.String("argument", utils.TruncateInterface(arg, -1)),
        log.ShortError(err))
......

问题排查

5 min 的设置

因为这里的问题 5 分钟太规律了，而 dm 集群配置文件中也没有做特殊配置，所以首先检查了源码中的默认配置，5 min 的都有哪些：

[jiyf@k8s-master tiflow]$ find ./ -name "*.go" | xargs grep "5 \* time.Minute"
./dm/dm/config/checker_config.go:       DefaultBackoffRollback         = 5 * time.Minute
./dm/dm/config/checker_config.go:       DefaultBackoffMax              = 5 * time.Minute
./dm/dm/master/bootstrap.go:    waitWorkerV1Timeout = 5 * time.Minute
./dm/dm/worker/task_checker.go://       DefaultBackoffRollback         = 5 * time.Minute
./dm/dm/worker/task_checker.go://       DefaultBackoffMax              = 5 * time.Minute
./dm/pkg/backoff/backoff_test.go:               backoffMax            = 5 * time.Minute

这几个参数都不太相关，甚至把这几个参数都故意改了一下，编译测试发现问题没有变化，所以不是这几个参数的原因。

其实当时如果换个搜索方法就找到相关参数了，但是当时没有：

[jiyf@k8s-master tiflow]$ find ./ -name "*.go" | xargs grep "5m" | grep -v "_test"
./dm/openapi/gen.server.go:     "PtTr+9Yusx5mExx8oOHq0fabXXVT36BZDczkcnc1lI+fAYSXpoP0xR+AoFubti6y1oVs+M3KSbabEfu2",
./dm/openapi/gen.server.go:     "TwTP5oSG5mDk/dnimzqZt05duMIda7nn9uUDDr88h6WjV+47VbiZXUamXOpv5a8q8M7GcnPINPrhFHvd",
./dm/syncer/syncer.go:  maxDMLConnectionTimeout = "5m"
./pkg/security/test_util.go:rbVlpabn7l1JBMatCUJLHR6VWQ2MNjrOXAEUYm4xGEN+tUYyUOGl5mHFguLl3OIn

其实问题就跟那个 maxDMLConnectionTimeout 是类似的，当时没有通过 5m 搜索，没有第一时间找到影响的参数。

DDL add index

场景中 alter column 涉及到重组数据，执行时间较长，而问题的出现都是在数据量足够大，下游 ddl 执行超过 5min 情况下。

为了排除是语句的影响（毕竟下游表数据乱码了），找了同样执行时间长，需要回填数据的 add index 语句做测试。

测试发现下游 tidb，admin show ddl jobs，没有出现重放现象。

由于并发执行 add index 会直接报错，会不会是 dm 重放时候直接报错了呢：

mysql> alter table sbtest1.sbtest1 add index pad_idx(pad);
ERROR 1061 (42000): index already exist pad_idx; a background job is trying to add the same index, please check by `ADMIN SHOW DDL JOBS`

搜索 dm worker 日志，并没有类似 “index already exist” 的报错信息。

[2022/02/22 11:47:32.838 +08:00] [INFO] [syncer.go:2352] ["start to handle ddls in normal mode"] [task=jiyftest] [unit="binlog replication"] [event=query] [queryEventContext="{schema: sbtest2, originSQL: alter table sbtest1 add index pad_k(pad), startLocation: position: (mysql-bin.000013, 1035672489), gtid-set: , currentLocation: position: (mysql-bin.000013, 1035672609), gtid-set: , lastLocation: position: (mysql-bin.000013, 1035672609), gtid-set: , re-sync: , needHandleDDLs: ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`), trackInfos: {originDDL: ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`), routedDDL: ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`), sourceTables: `sbtest2`.`sbtest1`, targetTables: `sbtest2`.`sbtest1`}}"]
.......
.......
[2022/02/22 11:52:32.873 +08:00] [ERROR] [baseconn.go:184] ["execute statement failed"] [task=jiyftest] [unit="binlog replication"] [query="ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`)"] [argument="[]"] [error="invalid connection"]
[2022/02/22 11:52:32.874 +08:00] [ERROR] [baseconn.go:191] ["rollback failed"] [task=jiyftest] [unit="binlog replication"] [query="ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`)"] [argument="[]"] [error="invalid connection"]
[2022/02/22 11:52:32.874 +08:00] [ERROR] [db.go:221] ["execute statements failed after retry"] [task=jiyftest] [unit="binlog replication"] [queries="[ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`)]"] [arguments="[]"] [error="[code=10006:class=database:scope=not-set:level=high], Message: execute statement failed: ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`), RawCause: invalid connection"]
[2022/02/22 11:52:32.874 +08:00] [WARN] [error.go:93] ["ignore special error for DDL"] [task=jiyftest] [unit="binlog replication"] [DDL="ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`)"] [error="[code=10006:class=database:scope=not-set:level=high], Message: execute statement failed: ALTER TABLE `sbtest2`.`sbtest1` ADD INDEX `pad_k`(`pad`), RawCause: invalid connection"]

从日志上看：

dm 执行中，从开始执行，5min 后，同样报了 invalid connection 错误（排除语句影响）
出现错误后有一条 ignore special error for DDL 的警告日志

推断：

这个 5min invalid connection 问题是已知问题，毕竟重现也不是难事
在对这个问题的处理上，对于 add index 执行了忽略错误处理的方式

翻开代码，看到以下部分，对于添加索引、外键约束等，出现这个错误是忽略的，只打印一条 warn 日志：

error.go:L87
......
......
                handle := func() {

                        tctx.L().Warn("ignore special error for DDL", zap.String("DDL", ddl2), log.ShortError(err))
                        err2 := conn.ResetConn(tctx) // also reset the `invalid connection` for later use.
                        if err2 != nil {
                                tctx.L().Warn("reset connection failed", log.ShortError(err2))
                        }
                }

                switch v := stmt.(type) {
                case *ast.AlterTableStmt:
                        // ddls should be split with only one spec
                        if len(v.Specs) > 1 {
                                return err
                        } else if v.Specs[0].Tp == ast.AlterTableAddConstraint {
                                // only take effect on `ADD INDEX`, no UNIQUE KEY and FOREIGN KEY
                                // UNIQUE KEY may affect correctness, FOREIGN KEY should be filtered.
                                // ref https://github.com/pingcap/tidb/blob/3cdea0dfdf28197ee65545debce8c99e6d2945e3/ddl/ddl_api.go#L1929-L1948.
                                switch v.Specs[0].Constraint.Tp {
                                case ast.ConstraintKey, ast.ConstraintIndex:
                                        handle()
                                        return nil // ignore the error
                                }
                        }
                case *ast.CreateIndexStmt:
                        handle()
                        return nil // ignore the error
                }
......
......

连接池参数

在尝试了很多种方法，都没有把问题定位出来，会不会是连接池参数问题呢：

通过日志打印出，dm 到下游 tidb 所有连接池参数：

    //db, _ := sql.Open("mysql", "root:@tcp(ip:port)/?charset=utf8mb4&interpolateParams=true&maxAllowedPacket=0&tidb_txn_mode='optimistic'")
    db, _ := sql.Open("mysql", "root:@tcp(ip:port)/?charset=utf8mb4&interpolateParams=true&maxAllowedPacket=0&readTimeout=5m&sql_mode='NO_AUTO_VALUE_ON_ZERO%2CNO_ENGINE_SUBSTITUTION%2CALLOW_INVALID_DATES%2CIGNORE_SPACE%2CONLY_FULL_GROUP_BY'")
    //db, _ := sql.Open("mysql", "root:@tcp(ip:port)/?charset=utf8mb4&interpolateParams=true&maxAllowedPacket=0&readTimeout=1m&sql_mode='NO_AUTO_VALUE_ON_ZERO%2CNO_ENGINE_SUBSTITUTION%2CALLOW_INVALID_DATES%2CIGNORE_SPACE%2CONLY_FULL_GROUP_BY'&tidb_txn_mode='optimistic'")
    //db, _ := sql.Open("mysql", "root:@tcp(ip:port)/?charset=utf8mb4&interpolateParams=true&maxAllowedPacket=0&readTimeout=1m&tidb_txn_mode='optimistic'&sql_mode='NO_AUTO_VALUE_ON_ZERO%2CNO_ENGINE_SUBSTITUTION%2CALLOW_INVALID_DATES%2CIGNORE_SPACE%2CONLY_FULL_GROUP_BY'&tidb_skip_utf8_check='OFF'")
    
    从上面已经能看到 5m 的参数设置了，但是 readTimeout 这个变量不太理解用途，深刻学习了一把 readTimeout 这个变量参数

编写测试程序，依次测试上面的连接池参数，把问题成功复现了（readTimeout=30s）：

[jiyf@k8s-master t2]$ ./t2
[mysql] 2022/02/24 16:33:09 packets.go:37: read tcp XXXXXXX:58076->XXXXX:XXXX: i/o timeout
2022/02/24 16:33:09 err:invalid connection
2022/02/24 16:33:09 time cost: 30.027857599

问题分析

var (   
        // MaxDDLConnectionTimeoutMinute also used by SubTask.ExecuteDDL.
        MaxDDLConnectionTimeoutMinute = 5
        
        maxDMLConnectionTimeout = "5m"
        maxDDLConnectionTimeout = fmt.Sprintf("%dm", MaxDDLConnectionTimeoutMinute)
)

func (s *Syncer) createDBs(ctx context.Context) error {
        ......
        // baseConn for ddl
        dbCfg = s.cfg.To
        dbCfg.RawDBCfg = config.DefaultRawDBConfig().SetReadTimeout(maxDDLConnectionTimeout)

        var ddlDBConns []*dbconn.DBConn
        s.ddlDB, ddlDBConns, err = dbconn.CreateConns(s.tctx, s.cfg, &dbCfg, 2)
        if err != nil {
                dbconn.CloseUpstreamConn(s.tctx, s.fromDB)
                dbconn.CloseBaseDB(s.tctx, s.toDB)
                return err
        }
        ......
}

从代码里就能看的很明白了，这里 ddl 的 ReadTimeout 设置的固定值 5min。

当下游 tidb 执行 ddl 超过 5min 时候，tidb server 就会断开，dm 连接收到 invalid connection 错误。

read timeout

dsn readtimeout 这个参数是 go-sql-driver 的参数，用于设置从 server 端读取数据的超时时间，下面三个分别对应连接超时、读超时、写超时三个参数。

https://github.com/go-sql-driver/mysql/blob/217d05049e5a88d529b9a2d5fe5675120831efab/dsn.go#L51

	Timeout          time.Duration     // Dial timeout
	ReadTimeout      time.Duration     // I/O read timeout
	WriteTimeout     time.Duration     // I/O write timeout

当读取数据超时时候，就会断开 tcp 连接，上层收到 invalid connetion 错误。

https://github.com/go-sql-driver/mysql/blob/217d05049e5a88d529b9a2d5fe5675120831efab/packets.go#L115

			if mc.cfg.ReadTimeout != 0 {
				err = conn.SetReadDeadline(time.Now().Add(mc.cfg.ReadTimeout))
			}

ignore special error for DDL

如前面代码所示，对于执行耗时较久的 DDL，例如 add index，外键约束等，dm 将出现的错误给忽略了。

对于 alter column 需要重组数据的情况，同样需要耗时很久，没有特殊处理，这里暴露出了问题。

这个特殊忽略应该是有问题的，掩盖了问题的真实原因。

invalid connection

这个报错，对于帮助排查问题帮助甚微，具体什么原因断开的连接，仍然看不出来。

[mysql] 2022/02/24 16:33:09 packets.go:37: read tcp XXXXXXX:58076->XXXXX:XXXX: i/o timeout
2022/02/24 16:33:09 err:invalid connection

第一条报错，更有帮助一些，但是这个是由 mysql client 包报出来的，并没有打印到 dm worker 日志中。

总结

这个问题是 DM 和 TiDB 两个 bug 密切配合产生的：

TiDB 5.3.0 并发 modify column 的 bug，需要的条件是并发执行
DM 设置 read timeout 导致 TiDB server 断开连接，每隔 5min 重新同步 DDL，创造并发条件

配合太完美了！！

DM 相关问题的 iss: https://github.com/pingcap/tiflow/issues/4689

DM 同步 modify column 语句到 TiDB 5.3 踩坑二：DDL 语句重放

背景