写点什么

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

  • 2022 年 7 月 11 日
  • 本文字数:5328 字

    阅读完需:约 17 分钟

作者: 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 errorI1124 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.goswitch 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 的报错非常模糊,从日志很难看出问题所在,造成很大困惑。


发布于: 刚刚阅读数: 3
用户头像

TiDB 社区官网:https://tidb.net/ 2021.12.15 加入

TiDB 社区干货传送门是由 TiDB 社区中布道师组委会自发组织的 TiDB 社区优质内容对外宣布的栏目,旨在加深 TiDBer 之间的交流和学习。一起构建有爱、互助、共创共建的 TiDB 社区 https://tidb.net/

评论

发布
暂无评论
br 备份到 s3 时 endpoint  参数加目录分隔符后缀问题排查_管理与运维_TiDB 社区干货传送门_InfoQ写作社区