作者: jiyf 原文来源:https://tidb.net/blog/ec8ad0ca
【是否原创】是
【首发渠道】TiDB 社区
问题描述
在 k8s 环境进行备份的时候,不小心将 s3 的 endpoint 参数多加了个目录操作符,配置如下:
"s3": {
"bucket": "backup",
"prefix": "demo",
"endpoint": "http://minio-service.tidb-backup:9000/",
"provider": "ceph",
"secretName": "XXXXXX"
},
复制代码
在当前版本正确的配置是要把 http://minio-service.tidb-backup:9000/ 的后缀 “/” 去掉,但是问题出现的时候没有注意到。
这里主要记录下问题排查的过程,分析产生问题的原因,以及修复方法。
问题排查
结果备份就报错了,br 的报错日志如下:
I1124 03:16:23.014428 10 backup.go:93] [2021/11/24 03:16:23.014 +00:00] [WARN] [push.go:184] ["skipping disconnected stores"] [range-sn=7] [error="[BR:Common:ErrFailedToConnect]failed to connect to store: 1 with retry times:0: rpc error: code = Canceled desc = context canceled"]
I1124 03:16:23.014455 10 backup.go:93] [2021/11/24 03:16:23.014 +00:00] [WARN] [push.go:184] ["skipping disconnected stores"] [range-sn=5] [error="[BR:Common:ErrFailedToConnect]failed to connect to store: 1 with retry times:0: rpc error: code = Canceled desc = context canceled"]
....
....
I1124 03:16:24.025499 10 backup.go:93] Error: [BR:KV:ErrKVStorage]tikv storage occur I/O error
I1124 03:16:24.025624 10 backup.go:93] [2021/11/24 03:16:24.024 +00:00] [ERROR] [main.go:58] ["br failed"] [error="[BR:KV:ErrKVStorage]tikv storage occur I/O error"] [errorVerbose="[BR:KV:ErrKVStorage]tikv storage occur I/O error\"ngithub.com/pingcap/errors.AddStack\"n\"t/nfs/cache/mod/github.com/pingcap/errors@v0.11.5-0.20210425183316-da1aaba5fb63/errors.go:174\"ngithub.com/pingcap/errors.Trace\"n\"t/nfs/cache/mod/github.com/pingcap/errors@v0.11.5-0.20210425183316-da1aaba5fb63/juju_adaptor.go:15\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).BackupRange\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:477\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).BackupRanges.func1\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:429\"ngithub.com/pingcap/tidb/br/pkg/utils.(*WorkerPool).ApplyOnErrorGroup.func1\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/utils/worker.go:63\"ngolang.org/x/sync/errgroup.(*Group).Go.func1\"n\"t/nfs/cache/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57\"nruntime.goexit\"n\"t/usr/local/go/src/runtime/asm_amd64.s:1371"] [stack="main.main\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/cmd/br/main.go:58\"nruntime.main\"n\"t/usr/local/go/src/runtime/proc.go:225"]
I1124 03:16:24.035792 10 backup.go:93]
E1124 03:16:24.036468 10 manager.go:292] backup cluster tidb-test/backup-test data failed, err: cluster tidb-test/backup-test, wait pipe message failed, errMsg [2021/11/24 03:16:23.014 +00:00] [ERROR] [client.go:537] ["find leader failed"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\"ngithub.com/tikv/pd/client.(*client).GetRegion\"n\"t/nfs/cache/mod/github.com/tikv/pd@v1.1.0-beta.0.20210818112400-0c5667766690/client/client.go:977\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).findRegionLeader\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:535\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:760\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:612\"nruntime.goexit\"n\"t/usr/local/go/src/runtime/asm_amd64.s:1371"] [region=null] [stack="github.com/pingcap/tidb/br/pkg/backup.(*Client).findRegionLeader\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:537\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:760\"ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\"n\"t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/br/br/pkg/backup/client.go:612"]
复制代码
日志报错 failed to connect to store: 1 很奇怪,毕竟这个 store 反复检查之后确认都没有问题。打开报错的源码,发现这个报错是因为向 tikv 调用 grpc 请求后报错写的日志源码地址
打开 store 1 的日志,发现以下报错:
[2021/11/24 14:27:33.288 +08:00] [INFO] [endpoint.rs:824] ["run backup task"] [task="BackupTask { start_ts: TimeStamp(0), end_ts: TimeStamp(429322470170034177), start_key: 7480000000000000115F69800000000000000100, end_key: 7480000000000000115F698000000000000001FB, is_raw_kv: false, cf: \""default\"" }"]
[2021/11/24 14:27:33.303 +08:00] [ERROR] [endpoint.rs:304] ["backup save file failed"] [err_code=KV:Unknown] [err="Io(Custom { kind: Other, error: \""failed to put object Request ID: None Body: <?xml version=\"\"\""1.0\"\"\"" encoding=\"\"\""UTF-8\"\"\""?>\"\"n<Error><Code>BadRequest</Code><Message>An error occurred when parsing the HTTP request PUT at '//backup/demo/1_16_8_495c5d2e3a1901df43133318e03236d08d1c8882cdd7b452579a4fcd82ccb718_1637735253296_default.sst'</Message><Resource>//backup/demo/1_16_8_495c5d2e3a1901df43133318e03236d08d1c8882cdd7b452579a4fcd82ccb718_1637735253296_default.sst</Resource><RequestId></RequestId><HostId>f15532cf-11fa-41fb-8ae2-c9bdbc9dabbd</HostId></Error>\"" })"]
[2021/11/24 14:27:33.303 +08:00] [ERROR] [endpoint.rs:742] ["backup region failed"] [err_code=KV:Unknown] [err="Io(Custom { kind: Other, error: \""failed to put object Request ID: None Body: <?xml version=\"\"\""1.0\"\"\"" encoding=\"\"\""UTF-8\"\"\""?>\"\"n<Error><Code>BadRequest</Code><Message>An error occurred when parsing the HTTP request PUT at '//backup/demo/1_16_8_495c5d2e3a1901df43133318e03236d08d1c8882cdd7b452579a4fcd82ccb718_1637735253296_default.sst'</Message><Resource>//backup/demo/1_16_8_495c5d2e3a1901df43133318e03236d08d1c8882cdd7b452579a4fcd82ccb718_1637735253296_default.sst</Resource><RequestId></RequestId><HostId>f15532cf-11fa-41fb-8ae2-c9bdbc9dabbd</HostId></Error>\"" })"] [end_key=74800000000000000F5F72FFFFFFFFFFFFFFFF00] [start_key=74800000000000000F5F720000000000000000] [region="id: 16 start_key: 7480000000000000FF0F00000000000000F8 end_key: 7480000000000000FF1100000000000000F8 region_epoch { conf_ver: 1 version: 8 } peers { id: 17 store_id: 1 }"]
[2021/11/24 14:27:33.304 +08:00] [ERROR] [service.rs:73] ["backup canceled"] [error=RemoteStopped]
复制代码
错误日志中 “failed to put object Request ID: None Body“,难道是因为要备份的 region 没有数据,所以 body 为 0,然后 s3 接口报错?
看下这个出错的 region 16 是哪个表的数据:
$ curl http://XXXXXXXX:30040/regions/16
{
"start_key": "dIAAAAAAAAAP",
"end_key": "dIAAAAAAAAAR",
"start_key_hex": "74800000000000000f",
"end_key_hex": "748000000000000011",
"region_id": 16,
"frames": [
{
"db_name": "mysql",
"table_name": "GLOBAL_VARIABLES",
"table_id": 15,
"is_record": false,
"index_name": "PRIMARY",
"index_id": 1
},
{
"db_name": "mysql",
"table_name": "GLOBAL_VARIABLES",
"table_id": 15,
"is_record": true
}
]
}
复制代码
竟然是系统表,在低版本的 br,默认是不会备份系统表的,查看备份的命令,没有设置过滤参数:
I1124 03:16:22.647869 10 backup.go:69] Running br command with args: [backup full --pd=tidb-for-test-pd.tidb-test:2379 --storage=s3://backup/demo --s3.provider=ceph --s3.endpoint=http://minio-service.tidb-backup:9000/]
复制代码
翻看官方文档,原来当前使用的版本 5.2.0 默认已经进行系统表的备份了:
在 v5.1.0 之前,BR 备份时会过滤掉系统库 mysql.*
的表数据。自 v5.1.0 起,BR 默认备份集群内的全部数据,包括系统库 mysql.*
中的数据。但由于恢复 mysql.*
中系统表数据的技术实现尚不完善,因此 BR 默认不恢复系统库 mysql
中的表数据。
但是系统表也有数据,有数据那为什么会 body 为空报错呢?为了排除 k8s 环境影响,版本 5.2.0 影响,又做了以下测试:
物理机 5.2.0 进行 br 备份,问题同样出现
物理机 4.0.8 进行 br 备份(空集群,没有自建库表),没有问题
物理机 5.2.0 进行 br 备份,去掉后缀的目录分隔符 “/”,没有问题
物理机 4.0.8 进行 br 备份(有自建表数据),去掉后缀的目录分隔符 “/”,没有问题
物理机 4.0.8 进行 br 备份(有自建表数据),也出现问题
补充一下:备份失败时候,备份的锁文件是正常的,在 s3 备份目录下可以看到 backup.lock 文件(锁文件用来防止多个备份到同一个目录)。
问题分析
在只进行上面第 1、2、3 步测试的时候,当时确认到问题的原因是多加了目录分割符 “/”。同时怀疑 tikv 5.2.0 在访问 s3 的时候没有对这个后缀进行处理:
但是进行到第 4、第 5 测试的时候,发现其实 4.0.8 版本的 tikv 也是没有处理的,两个版本 tikv 处理逻辑是一样的。在 4.0.8 中因为没有自建表,而系统库又不进行备份,所以由于没有数据需要备份,自然就没有报错。当包含自建库表的时候,4.0.8 中带有目录分割后缀设置后,同样报错。
结合上面几个测试,那问题很可能是:
问题验证
翻开 br 创建到 s3 连接的代码,看到确实是进行了处理的:
文件:parse.go
switch u.Scheme {
...
case "s3":
...
prefix := strings.Trim(u.Path, "/")
s3 := &backup.S3{Bucket: u.Host, Prefix: prefix}
...
return &backup.StorageBackend{Backend: &backup.StorageBackend_S3{S3: s3}}, nil
...
}
复制代码
但是这个处理是放在创建 br 到 s3 连接这里处理的,在将 endpoint 参数传给 tikv 时候仍然未处理。如果把这个后缀的处理放在参数解析那里应该就可以彻底解决了。
// parseFromFlags parse S3BackendOptions from command line flags.
func (options *S3BackendOptions) parseFromFlags(flags *pflag.FlagSet) error {
var err error
options.Endpoint, err = flags.GetString(s3EndpointOption)
if err != nil {
return errors.Trace(err)
}
// 这里添加下面一行
options.Endpoint = strings.Trim(options.Endpoint, "/")
...
return nil
}
复制代码
编译后进行测试验证,问题解决了!
总结
修复方法:
由于 endpoint 作为 http/https 类型,用户出于平时使用习惯很容易在后面多加一个 “/” 符号,而且很难发现其中的差异。当错误配置后,br、tikv 的报错非常模糊,从日志很难看出问题所在,造成很大困惑。
评论