br 备份到 s3 时 endpoint 参数加目录分隔符后缀问题排查

【是否原创】是
【首发渠道】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 &#39;//backup/demo/1_16_8_495c5d2e3a1901df43133318e03236d08d1c8882cdd7b452579a4fcd82ccb718_1637735253296_default.sst&#39;</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 &#39;//backup/demo/1_16_8_495c5d2e3a1901df43133318e03236d08d1c8882cdd7b452579a4fcd82ccb718_1637735253296_default.sst&#39;</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 影响,又做了以下测试:

  1. 物理机 5.2.0 进行 br 备份,问题同样出现
  2. 物理机 4.0.8 进行 br 备份(空集群,没有自建库表),没有问题
  3. 物理机 5.2.0 进行 br 备份,去掉后缀的目录分隔符 “/”,没有问题
  4. 物理机 4.0.8 进行 br 备份(有自建表数据),去掉后缀的目录分隔符 “/”,没有问题
  5. 物理机 4.0.8 进行 br 备份(有自建表数据),也出现问题

补充一下:备份失败时候,备份的锁文件是正常的,在 s3 备份目录下可以看到 backup.lock 文件(锁文件用来防止多个备份到同一个目录)。

  • backup.lock 文件是 br 开始执行备份的时候在 s3 创建的
  • 备份数据是各个 tikv 发送到 s3 上的

问题分析

在只进行上面第 1、2、3 步测试的时候,当时确认到问题的原因是多加了目录分割符 “/”。同时怀疑 tikv 5.2.0 在访问 s3 的时候没有对这个后缀进行处理:

  • 在 4.0.8 和 5.2.0 两个版本,br 文件锁都成功创建了,那么说明这个目录分隔符 br 创建文件锁都处理了
  • 在 4.0.8 版本的 tikv 没有出现问题,5.2.0 tikv 出现问题,那很有可能是 5.2.0 缺少了这部分逻辑

但是进行到第 4、第 5 测试的时候,发现其实 4.0.8 版本的 tikv 也是没有处理的,两个版本 tikv 处理逻辑是一样的。在 4.0.8 中因为没有自建表,而系统库又不进行备份,所以由于没有数据需要备份,自然就没有报错。当包含自建库表的时候,4.0.8 中带有目录分割后缀设置后,同样报错。

结合上面几个测试,那问题很可能是:

  • br 访问 s3 的时候是处理的
  • br 向 tikv 发送 rpc 请求备份的参数中,没有处理,同时 tikv 也没有处理

问题验证

翻开 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
}

编译后进行测试验证,问题解决了!

总结

修复方法:

  • br 在参数解析的时候就进行 endpoint 后缀的处理
  • 在添加上面处理后,移除(不再需要) br 连接到 s3 时候对 endpoint 后缀处理

由于 endpoint 作为 http/https 类型,用户出于平时使用习惯很容易在后面多加一个 “/” 符号,而且很难发现其中的差异。当错误配置后,br、tikv 的报错非常模糊,从日志很难看出问题所在,造成很大困惑。

1赞