0
0
0
0
专栏/.../

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

 jiyfhust  发表于  2021-11-24
原创管理与运维

【是否原创】是
【首发渠道】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 的报错非常模糊，从日志很难看出问题所在，造成很大困惑。

0
0
0
0

版权声明：本文为 TiDB 社区用户原创文章，遵循 CC BY-NC-SA 4.0 版权协议，转载请附上原文出处链接和本声明。

评论
暂无评论
问题描述问题排查问题分析问题验证总结