tidb v5.4.1 集群使用br 备份出来的文件无法恢复

🪐 TiDB 技术问题 备份&数据迁移
,
1

【 TiDB 使用环境】生产\测试环境\ POC
【 TiDB 版本】
【遇到的问题】
在tidb v5.4.1 集群使用br v5.4.1 备份出的数据无法恢复!!

image
image1322×132 37.4 KB

image
image2555×826 1010 KB

【复现路径】做过哪些操作出现的问题

在tidb v5.4.1 集群使用br v5.4.1 备份恢复， 必现 !!!
【问题现象及影响】

集群备份文件无法使用， 集群无法备份恢复 ! 参考下下面的帖子， 有人遇到同样的问题
BR备份报错：[pd] fetch pending tso requests error - #21，来自 qizheng

若提问为性能优化、故障排查类问题，请下载脚本运行。终端输出的打印结果，请务必全选并复制粘贴上传。

2

BR 备份这个有人帮忙看下嘛

3

备份处理的文件放在什么位置？ 集群中的所有tikv 都能访问备份文件吗？

4

us3, 所有的tikv 都可以访问的

v4.0.14 集群是没有问题的

5

image 看着是没法读这个目录文件

6

不是没法读取这个目录， 是无法读取.sst 文件, 因为备份出来的.sst文件 size 是0

image
image2157×43 114 KB

image
image
image1452×124 86 KB

但是下面的这个temp 文件是有size 的，而且刚好是br expect size

image
image1272×29 21.9 KB

我把 temp 文件和sst文件的文件名互换下就可以恢复成功

8

测试没有复现。
备份文件大小是 0，备份log里 有错误信息吗？

9

重新跑一遍备份. 还是一样的问题么？sst 大小还是 0 吗？

10

br 备份显示的是success

11

同样的结果

12

能换个备份目录试一下吗？

13

每次备份都是新的备份目录

15

测试了没问题，
能把 备份 和回复 的日志完整发一下吗？
这个集群是低版本升级上来的吗？

16

不是升级上来的，是直接创建的

17

那 能把 备份 和恢复 的日志完整发一下吗？

18

稍等下，我在整理日志

19

br 备份

备份命令

v5.4.1/br backup full --pd=10.x.139.xxx:10003 -f '*.*' -f '!mysql.*'  -f '!INFORMATION_SCHEMA.*' -f '!METRICS_SCHEMA.*' -f '!PERFORMANCE_SCHEMA.*' -f '!tidb_loader.*' --checksum=true --storage=local:///mnt/positive_volume/peter_test_20220623001 --log-file=scripts/bac
kup1.log

log输出

[2022/06/23 15:49:52.165 +08:00] [INFO] [info.go:49] ["Welcome to Backup & Restore (BR)"] [release-version=v5.4.1] [git-hash=be484475e76b3aaa2cad520111353c3327db35fa] [git-branch=heads/refs/tags/v5.4.1] [go-version=go1.16.4] [utc-build-time="2022-05-07 01:26:52"] [race-enabled=false]
[2022/06/23 15:49:52.165 +08:00] [INFO] [common.go:634] [arguments] [__command="br backup full"] [checksum=true] [filter="[*.*,!mysql.*,!grafana_ucloud.*,!INFORMATION_SCHEMA.*,!METRICS_SCHEMA.*,!PERFORMANCE_SCHEMA.*,!tidb_loader.*]"] [log-file=/root/wakanda/action/scripts/backup1.log] [pd="[10.9.139.114:10003]"] [storage=local:///mnt/positive_volume/peter_test_20220623001]
[2022/06/23 15:49:52.165 +08:00] [INFO] [conn.go:244] ["new mgr"] [pdAddrs=10.9.139.114:10003]
[2022/06/23 15:49:52.166 +08:00] [INFO] [client.go:352] ["[pd] create pd client with endpoints"] [pd-address="[10.9.139.114:10003]"]
[2022/06/23 15:49:52.168 +08:00] [INFO] [base_client.go:331] ["[pd] update member urls"] [old-urls="[http://10.9.139.114:10003]"] [new-urls="[http://10.9.139.114:10003,http://10.9.59.162:10001,http://10.9.98.126:10001]"]
[2022/06/23 15:49:52.168 +08:00] [INFO] [base_client.go:349] ["[pd] switch leader"] [new-leader=http://10.9.139.114:10003] [old-leader=]
[2022/06/23 15:49:52.168 +08:00] [INFO] [base_client.go:104] ["[pd] init cluster id"] [cluster-id=7111513361699399115]
[2022/06/23 15:49:52.168 +08:00] [INFO] [client.go:648] ["[pd] tso dispatcher created"] [dc-location=global]
[2022/06/23 15:49:52.168 +08:00] [INFO] [conn.go:219] ["checked alive KV stores"] [aliveStores=3] [totalStores=3]
[2022/06/23 15:49:52.168 +08:00] [INFO] [client.go:352] ["[pd] create pd client with endpoints"] [pd-address="[10.9.139.114:10003]"]
[2022/06/23 15:49:52.170 +08:00] [INFO] [base_client.go:331] ["[pd] update member urls"] [old-urls="[http://10.9.139.114:10003]"] [new-urls="[http://10.9.139.114:10003,http://10.9.59.162:10001,http://10.9.98.126:10001]"]
[2022/06/23 15:49:52.170 +08:00] [INFO] [base_client.go:349] ["[pd] switch leader"] [new-leader=http://10.9.139.114:10003] [old-leader=]
[2022/06/23 15:49:52.170 +08:00] [INFO] [base_client.go:104] ["[pd] init cluster id"] [cluster-id=7111513361699399115]
[2022/06/23 15:49:52.170 +08:00] [INFO] [client.go:648] ["[pd] tso dispatcher created"] [dc-location=global]
[2022/06/23 15:49:52.171 +08:00] [INFO] [tidb.go:72] ["new domain"] [store=tikv-7111513361699399115] ["ddl lease"=1s] ["stats lease"=-1ns] ["index usage sync lease"=0s]
[2022/06/23 15:49:52.201 +08:00] [INFO] [domain.go:169] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=90] ["start time"=19.366697ms]
[2022/06/23 15:49:52.203 +08:00] [INFO] [domain.go:432] ["full load and reset schema validator"]
[2022/06/23 15:49:52.203 +08:00] [INFO] [ddl.go:347] ["[ddl] start DDL"] [ID=42873ba9-210a-4e16-a578-263031accb45] [runWorker=false]
[2022/06/23 15:49:52.205 +08:00] [INFO] [backup.go:261] ["get newCollationEnable for check during restore"] [newCollationEnable=False]
[2022/06/23 15:49:52.205 +08:00] [INFO] [client.go:93] ["new backup client"]
[2022/06/23 15:49:53.552 +08:00] [INFO] [client.go:137] ["backup encode timestamp"] [BackupTS=434102755263774721]
[2022/06/23 15:49:53.552 +08:00] [INFO] [backup.go:295] ["current backup safePoint job"] [safePoint="{ID=br-678461d8-cca3-48bd-9503-0bd2cba2fe2e,TTL=5m0s,BackupTime=\"2022-06-23 15:49:53.505 +0800 CST\",BackupTS=434102755263774721}"]
[2022/06/23 15:49:53.559 +08:00] [INFO] [client.go:505] ["backup started"] [range-sn=2] [startKey=7480000000000000A55F720000000000000000] [endKey=7480000000000000A55F72FFFFFFFFFFFFFFFF00] [rateLimit=0] [concurrency=4]
[2022/06/23 15:49:53.559 +08:00] [INFO] [client.go:505] ["backup started"] [range-sn=0] [startKey=7480000000000000A85F720000000000000000] [endKey=7480000000000000A85F72FFFFFFFFFFFFFFFF00] [rateLimit=0] [concurrency=4]
[2022/06/23 15:49:53.559 +08:00] [INFO] [client.go:505] ["backup started"] [range-sn=1] [startKey=7480000000000000A85F69800000000000000100] [endKey=7480000000000000A85F698000000000000001FB] [rateLimit=0] [concurrency=4]
[2022/06/23 15:49:53.561 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=0] [store-id=4] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=0] [store-id=5] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=0] [store-id=1] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=1] [store-id=4] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=1] [store-id=5] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=2] [store-id=1] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=2] [store-id=4] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=1] [store-id=1] ["retry time"=0]
[2022/06/23 15:49:53.562 +08:00] [INFO] [client.go:918] ["try backup"] [range-sn=2] [store-id=5] ["retry time"=0]
[2022/06/23 15:49:53.730 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=0] [store-id=4] [retry-time=0]
[2022/06/23 15:49:53.731 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=1] [store-id=4] [retry-time=0]
[2022/06/23 15:49:53.731 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=2] [store-id=4] [retry-time=0]
[2022/06/23 15:49:53.737 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=0] [store-id=5] [retry-time=0]
[2022/06/23 15:49:53.737 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=1] [store-id=5] [retry-time=0]
[2022/06/23 15:49:53.737 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=2] [store-id=5] [retry-time=0]
[2022/06/23 15:49:54.295 +08:00] [INFO] [client.go:986] ["range backed up"] [range-sn=1] [store-id=1] [small-range-start-key=7480000000000000A85F69800000000000000100] [small-range-end-key=7480000000000000A85F698000000000000001FB]
[2022/06/23 15:49:54.295 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=1] [store-id=1] [retry-time=0]
[2022/06/23 15:49:54.295 +08:00] [INFO] [client.go:527] ["finish backup push down"] [range-sn=1] [small-range-count=1]
[2022/06/23 15:49:54.295 +08:00] [INFO] [client.go:547] ["time range backed up"] [range-sn=1] [StartVersion=0] [EndVersion=434102755263774721]
[2022/06/23 15:49:54.295 +08:00] [INFO] [client.go:499] ["backup range finished"] [range-sn=1] [take=735.420384ms]
[2022/06/23 15:49:54.303 +08:00] [INFO] [client.go:986] ["range backed up"] [range-sn=0] [store-id=1] [small-range-start-key=7480000000000000A85F720000000000000000] [small-range-end-key=7480000000000000A85F72FFFFFFFFFFFFFFFF00]
[2022/06/23 15:49:54.303 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=0] [store-id=1] [retry-time=0]
[2022/06/23 15:49:54.303 +08:00] [INFO] [client.go:527] ["finish backup push down"] [range-sn=0] [small-range-count=1]
[2022/06/23 15:49:54.303 +08:00] [INFO] [client.go:547] ["time range backed up"] [range-sn=0] [StartVersion=0] [EndVersion=434102755263774721]
[2022/06/23 15:49:54.303 +08:00] [INFO] [client.go:499] ["backup range finished"] [range-sn=0] [take=744.182395ms]
[2022/06/23 15:49:54.311 +08:00] [INFO] [client.go:986] ["range backed up"] [range-sn=2] [store-id=1] [small-range-start-key=7480000000000000A55F720000000000000000] [small-range-end-key=7480000000000000A55F72FFFFFFFFFFFFFFFF00]
[2022/06/23 15:49:54.311 +08:00] [INFO] [client.go:968] ["backup streaming finish"] [range-sn=2] [store-id=1] [retry-time=0]
[2022/06/23 15:49:54.311 +08:00] [INFO] [client.go:527] ["finish backup push down"] [range-sn=2] [small-range-count=1]
[2022/06/23 15:49:54.311 +08:00] [INFO] [client.go:547] ["time range backed up"] [range-sn=2] [StartVersion=0] [EndVersion=434102755263774721]
[2022/06/23 15:49:54.311 +08:00] [INFO] [client.go:499] ["backup range finished"] [range-sn=2] [take=752.129861ms]
[2022/06/23 15:49:54.311 +08:00] [INFO] [client.go:484] ["Backup Ranges"] [take=2.173µs]
[2022/06/23 15:49:54.311 +08:00] [INFO] [metafile.go:562] ["write metas finished"] [type=datafile]
[2022/06/23 15:49:54.311 +08:00] [INFO] [metafile.go:602] ["finish the write metas"] [item=3] [type=datafile] [costs=752.409758ms]
[2022/06/23 15:49:54.312 +08:00] [INFO] [worker.go:73] ["table checksum start"] [db=peter] [table=runoob_tbl]
[2022/06/23 15:49:54.312 +08:00] [INFO] [worker.go:73] ["table checksum start"] [db=test] [table=tidb_demo]
[2022/06/23 15:49:54.312 +08:00] [INFO] [worker.go:73] ["table checksum finished"] [db=peter] [table=runoob_tbl] [Crc64Xor=8328212611495905372] [TotalKvs=266] [TotalBytes=17024] [take=548.769µs]
[2022/06/23 15:49:54.312 +08:00] [INFO] [worker.go:73] ["table checksum finished"] [db=test] [table=tidb_demo] [Crc64Xor=2923342626563082014] [TotalKvs=4] [TotalBytes=186] [take=827.985µs]
[2022/06/23 15:49:54.312 +08:00] [INFO] [schema.go:137] ["backup checksum"] [take=949.132µs]
[2022/06/23 15:49:54.312 +08:00] [INFO] [metafile.go:562] ["write metas finished"] [type=schema]
[2022/06/23 15:49:54.312 +08:00] [INFO] [metafile.go:602] ["finish the write metas"] [item=5] [type=schema] [costs=965.519µs]
[2022/06/23 15:49:54.313 +08:00] [INFO] [metafile.go:622] ["save backup meta"] [size=5887]
[2022/06/23 15:49:54.364 +08:00] [INFO] [validate.go:78] ["checksum success"] [db=test] [table=tidb_demo]
[2022/06/23 15:49:54.364 +08:00] [INFO] [validate.go:78] ["checksum success"] [db=peter] [table=runoob_tbl]
[2022/06/23 15:49:54.364 +08:00] [ERROR] [client.go:752] ["[pd] fetch pending tso requests error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]context canceled: context canceled"] [stack="github.com/tikv/pd/client.(*client).handleDispatcher\
\t/go/pkg/mod/github.com/tikv/pd@v1.1.0-beta.0.20211118054146-02848d2660ee/client/client.go:752"]
[2022/06/23 15:49:54.364 +08:00] [INFO] [client.go:666] ["[pd] exit tso dispatcher"] [dc-location=global]
[2022/06/23 15:49:54.364 +08:00] [ERROR] [client.go:752] ["[pd] fetch pending tso requests error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]context canceled: context canceled"] [stack="github.com/tikv/pd/client.(*client).handleDispatcher\
\t/go/pkg/mod/github.com/tikv/pd@v1.1.0-beta.0.20211118054146-02848d2660ee/client/client.go:752"]
[2022/06/23 15:49:54.364 +08:00] [INFO] [client.go:666] ["[pd] exit tso dispatcher"] [dc-location=global]
[2022/06/23 15:49:54.364 +08:00] [INFO] [collector.go:68] ["Full backup success summary"] [total-ranges=3] [ranges-succeed=3] [ranges-failed=0] [backup-checksum=959.257µs] [backup-fast-checksum=398.25µs] [backup-total-regions=3] [backup-total-ranges=3] [total-take=2.199371094s] [BackupTS=434102755263774721] [total-kv=270] [total-kv-size=17.21kB] [average-speed=7.825kB/s] [backup-data-size(after-compressed)=7.109kB] [Size=7109]

控制台输出

Full backup <----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------> 100.00%
Checksum <-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------> 100.00%
[2022/06/23 15:49:54.364 +08:00] [INFO] [collector.go:67] ["Full backup success summary"] [total-ranges=3] [ranges-succeed=3] [ranges-failed=0] [backup-checksum=959.257µs] [backup-fast-checksum=398.25µs] [backup-total-regions=3] [backup-total-ranges=3] [total-take=2.199371094s] [BackupTS=434102755263774721] [total-kv=270] [total-kv-size=17.21kB] [average-speed=7.825kB/s] [backup-data-size(after-compressed)=7.109kB] [Size=7109]
20

备份的文件结果

image
image1230×163 56 KB

21

BR restore 日志输出

[2022/06/23 15:55:29.727 +08:00] [INFO] [info.go:49] ["Welcome to Backup & Restore (BR)"] [release-version=v5.4.1] [git-hash=be484475e76b3aaa2cad520111353c3327db35fa] [git-branch=heads/refs/tags/v5.4.1] [go-version=go1.16.4] [utc-build-time="2022-05-07 01:26:52"] [race-enabled=false]
[2022/06/23 15:55:29.727 +08:00] [INFO] [common.go:634] [arguments] [__command="br restore full"] [checksum=true] [filter="[*.*,!mysql.*,!grafana_ucloud.*,!INFORMATION_SCHEMA.*,!METRICS_SCHEMA.*,!PERFORMANCE_SCHEMA.*,!tidb_loader.*]"] [log-file=/root/wakanda/action/scripts/restore1.log] [pd="[10.9.139.114:10003]"] [storage=local:///mnt/positive_volume/peter_test_20220623001]
[2022/06/23 15:55:29.728 +08:00] [INFO] [conn.go:244] ["new mgr"] [pdAddrs=10.9.139.114:10003]
[2022/06/23 15:55:29.728 +08:00] [INFO] [client.go:352] ["[pd] create pd client with endpoints"] [pd-address="[10.9.139.114:10003]"]
[2022/06/23 15:55:29.730 +08:00] [INFO] [base_client.go:331] ["[pd] update member urls"] [old-urls="[http://10.9.139.114:10003]"] [new-urls="[http://10.9.139.114:10003,http://10.9.59.162:10001,http://10.9.98.126:10001]"]
[2022/06/23 15:55:29.730 +08:00] [INFO] [base_client.go:349] ["[pd] switch leader"] [new-leader=http://10.9.139.114:10003] [old-leader=]
[2022/06/23 15:55:29.730 +08:00] [INFO] [base_client.go:104] ["[pd] init cluster id"] [cluster-id=7111513361699399115]
[2022/06/23 15:55:29.730 +08:00] [INFO] [client.go:648] ["[pd] tso dispatcher created"] [dc-location=global]
[2022/06/23 15:55:29.731 +08:00] [INFO] [conn.go:219] ["checked alive KV stores"] [aliveStores=3] [totalStores=3]
[2022/06/23 15:55:29.731 +08:00] [INFO] [client.go:352] ["[pd] create pd client with endpoints"] [pd-address="[10.9.139.114:10003]"]
[2022/06/23 15:55:29.732 +08:00] [INFO] [base_client.go:331] ["[pd] update member urls"] [old-urls="[http://10.9.139.114:10003]"] [new-urls="[http://10.9.139.114:10003,http://10.9.59.162:10001,http://10.9.98.126:10001]"]
[2022/06/23 15:55:29.732 +08:00] [INFO] [base_client.go:349] ["[pd] switch leader"] [new-leader=http://10.9.139.114:10003] [old-leader=]
[2022/06/23 15:55:29.732 +08:00] [INFO] [base_client.go:104] ["[pd] init cluster id"] [cluster-id=7111513361699399115]
[2022/06/23 15:55:29.732 +08:00] [INFO] [client.go:648] ["[pd] tso dispatcher created"] [dc-location=global]
[2022/06/23 15:55:29.733 +08:00] [INFO] [tidb.go:72] ["new domain"] [store=tikv-7111513361699399115] ["ddl lease"=1s] ["stats lease"=-1ns] ["index usage sync lease"=0s]
[2022/06/23 15:55:29.761 +08:00] [INFO] [domain.go:169] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=93] ["start time"=14.948217ms]
[2022/06/23 15:55:29.763 +08:00] [INFO] [domain.go:432] ["full load and reset schema validator"]
[2022/06/23 15:55:29.763 +08:00] [INFO] [ddl.go:347] ["[ddl] start DDL"] [ID=481e89fc-99cb-41f7-a8c7-c41bf1efd5c2] [runWorker=true]
[2022/06/23 15:55:29.763 +08:00] [INFO] [manager.go:189] ["start campaign owner"] [ownerInfo="[ddl] /tidb/ddl/fg/owner"]
[2022/06/23 15:55:29.764 +08:00] [INFO] [ddl.go:336] ["[ddl] start delRangeManager OK"] ["is a emulator"=false]
[2022/06/23 15:55:29.764 +08:00] [INFO] [ddl_worker.go:156] ["[ddl] start DDL worker"] [worker="worker 1, tp general"]
[2022/06/23 15:55:29.765 +08:00] [WARN] [sysvar_cache.go:54] ["sysvar cache is empty, triggering rebuild"]
[2022/06/23 15:55:29.765 +08:00] [INFO] [ddl_worker.go:156] ["[ddl] start DDL worker"] [worker="worker 2, tp add index"]
[2022/06/23 15:55:29.767 +08:00] [INFO] [manager.go:189] ["start campaign owner"] [ownerInfo="[stats] /tidb/stats/owner"]
[2022/06/23 15:55:29.769 +08:00] [INFO] [manager.go:189] ["start campaign owner"] [ownerInfo="[stats] /tidb/stats/owner"]
[2022/06/23 15:55:29.898 +08:00] [INFO] [client.go:210] ["load backupmeta"] [databases=2] [jobs=0]
[2022/06/23 15:55:29.903 +08:00] [INFO] [import.go:249] ["multi ingest support"] [support=true]
[2022/06/23 15:55:29.907 +08:00] [WARN] [restore.go:603] ["set max-index-length to max(3072*4) to skip check index length in DDL"]
[2022/06/23 15:55:29.915 +08:00] [INFO] [ddl_worker.go:322] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:172, Type:create schema, State:none, SchemaState:queueing, SchemaID:171, TableID:0, RowCount:0, ArgLen:1, start time: 2022-06-23 15:55:29.904 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/06/23 15:55:29.917 +08:00] [INFO] [ddl.go:572] ["[ddl] start DDL job"] [job="ID:172, Type:create schema, State:none, SchemaState:queueing, SchemaID:171, TableID:0, RowCount:0, ArgLen:1, start time: 2022-06-23 15:55:29.904 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="/*from(br)*/CREATE DATABASE /*!32312 IF NOT EXISTS*/ `peter` /*!40100 DEFAULT CHARACTER SET utf8mb4 */"]
[2022/06/23 15:55:29.927 +08:00] [INFO] [domain.go:138] ["diff load InfoSchema success"] [currentSchemaVersion=93] [neededSchemaVersion=94] ["start time"=862.231µs] [phyTblIDs="[]"] [actionTypes="[]"]
[2022/06/23 15:55:30.419 +08:00] [INFO] [ddl.go:635] ["[ddl] DDL job is finished"] [jobID=172]
[2022/06/23 15:55:30.419 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/06/23 15:55:30.424 +08:00] [INFO] [client.go:456] ["start create tables"]
[2022/06/23 15:55:30.424 +08:00] [INFO] [restore.go:433] ["range and file prepared"] ["file count"=3] ["range count"=3]
[2022/06/23 15:55:30.424 +08:00] [INFO] [client.go:526] ["table created"] [speed="3417.11 ops/s"] [table=tidb_demo] [database=test]
[2022/06/23 15:55:30.424 +08:00] [INFO] [util.go:236] ["merge and validate file"] [database=test] [table=tidb_demo] [Files(total)=2] [File(write)=2] [File(default)=0] [Region(total)=2] ["Regoin(keys avg)"=2] ["Region(bytes avg)"=93] [Merged(regions)=2] ["Merged(keys avg)"=2] ["Merged(bytes avg)"=93]
[2022/06/23 15:55:30.424 +08:00] [INFO] [client.go:713] ["switch to import mode at beginning"]
[2022/06/23 15:55:30.427 +08:00] [INFO] [pd.go:415] ["pause scheduler successful at beginning"] [name="[balance-region-scheduler,balance-leader-scheduler,balance-hot-region-scheduler]"]
[2022/06/23 15:55:30.429 +08:00] [INFO] [pd.go:423] ["pause configs successful at beginning"] [cfg="{\"enable-location-replacement\":\"false\",\"leader-schedule-limit\":12,\"max-merge-region-keys\":0,\"max-merge-region-size\":0,\"max-pending-peer-count\":2147483647,\"max-snapshot-count\":40,\"region-schedule-limit\":40}"]
[2022/06/23 15:55:30.429 +08:00] [INFO] [client.go:307] ["reset pd timestamp"] [ts=434102755263774721]
[2022/06/23 15:55:30.430 +08:00] [INFO] [client.go:796] ["Start to validate checksum"]
[2022/06/23 15:55:30.433 +08:00] [INFO] [ddl_worker.go:322] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:174, Type:create table, State:none, SchemaState:queueing, SchemaID:171, TableID:173, RowCount:0, ArgLen:1, start time: 2022-06-23 15:55:30.411 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/06/23 15:55:30.436 +08:00] [INFO] [ddl.go:572] ["[ddl] start DDL job"] [job="ID:174, Type:create table, State:none, SchemaState:queueing, SchemaID:171, TableID:173, RowCount:0, ArgLen:1, start time: 2022-06-23 15:55:30.411 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="/*from(br)*/CREATE TABLE `runoob_tbl` (\
  `runoob_id` int(11) NOT NULL AUTO_INCREMENT,\
  `runoob_title` varchar(100) NOT NULL,\
  `runoob_author` varchar(40) NOT NULL,\
  `submission_date` date DEFAULT NULL,\
  PRIMARY KEY (`runoob_id`) /*T![clustered_index] CLUSTERED */\
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin"]
[2022/06/23 15:55:30.454 +08:00] [INFO] [domain.go:138] ["diff load InfoSchema success"] [currentSchemaVersion=94] [neededSchemaVersion=95] ["start time"=2.037614ms] [phyTblIDs="[173]"] [actionTypes="[8]"]
[2022/06/23 15:55:30.939 +08:00] [INFO] [ddl.go:635] ["[ddl] DDL job is finished"] [jobID=174]
[2022/06/23 15:55:30.943 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/06/23 15:55:30.944 +08:00] [INFO] [client.go:526] ["table created"] [speed="3.85 ops/s"] [table=runoob_tbl] [database=peter]
[2022/06/23 15:55:30.944 +08:00] [INFO] [util.go:236] ["merge and validate file"] [database=peter] [table=runoob_tbl] [Files(total)=1] [File(write)=1] [File(default)=0] [Region(total)=1] ["Regoin(keys avg)"=266] ["Region(bytes avg)"=17024] [Merged(regions)=1] ["Merged(keys avg)"=266] ["Merged(bytes avg)"=17024]
[2022/06/23 15:55:30.944 +08:00] [INFO] [util.go:209] ["all range generated"]
[2022/06/23 15:55:30.944 +08:00] [INFO] [batcher.go:362] ["sending batch lastly on close"] [size=3]
[2022/06/23 15:55:30.944 +08:00] [INFO] [batcher.go:325] ["restore batch start"] [ranges="{total=3,ranges=\"[\\\"[7480000000000000A85F69800000000000000100, 7480000000000000A85F698000000000000001FB)\\\",\\\"[7480000000000000A85F720000000000000000, 7480000000000000A85F72FFFFFFFFFFFFFFFF00)\\\",\\\"[7480000000000000A55F720000000000000000, 7480000000000000A55F72FFFFFFFFFFFFFFFF00)\\\"]\",totalFiles=3,totalKVs=270,totalBytes=17210,totalSize=17210}"] [tables="[`test`.`tidb_demo`,`peter`.`runoob_tbl`]"]
[2022/06/23 15:55:30.944 +08:00] [INFO] [pipeline_items.go:205] ["restore batch: waiting ranges"] [range=0]
[2022/06/23 15:55:30.945 +08:00] [INFO] [split.go:118] ["get split keys for region"] [len=3] [region=316]
[2022/06/23 15:55:30.945 +08:00] [INFO] [split.go:121] ["split regions"] [region="{ID=316,startKey=endKey=epoch=\"conf_ver:5 version:165 \",peers=\"id:317 store_id:1 ,id:318 store_id:4 ,id:319 store_id:5 \"}"] [keys="{total=3,keys=\"[7480000000000000A85F698000000000000001FB,7480000000000000A85F72FFFFFFFFFFFFFFFF00,7480000000000000AD5F72FFFFFFFFFFFFFFFF00]\"}"] [ranges="{total=3,ranges=\"[\\\"[7480000000000000A85F69800000000000000100, 7480000000000000A85F698000000000000001FB)\\\",\\\"[7480000000000000A85F720000000000000000, 7480000000000000A85F72FFFFFFFFFFFFFFFF00)\\\",\\\"[7480000000000000A55F720000000000000000, 7480000000000000A55F72FFFFFFFFFFFFFFFF00)\\\"]\",totalFiles=3,totalKVs=270,totalBytes=17210,totalSize=17210}"]
[2022/06/23 15:55:30.950 +08:00] [INFO] [split.go:149] ["scattered regions"] [count=3]
[2022/06/23 15:55:30.950 +08:00] [INFO] [split.go:163] ["start to wait for scattering regions"] [regions=3] [take=5.889332ms]
[2022/06/23 15:55:31.052 +08:00] [INFO] [split.go:175] ["waiting for scattering regions done"] [regions=3] [take=102.253223ms]
[2022/06/23 15:56:01.114 +08:00] [ERROR] [import.go:367] ["download file failed"] [files="{total=1,files=\"[1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst]\",totalKVs=2,totalBytes=72,totalSize=1597}"] [region="{ID=328,startKey=endKey=7480000000000000FFA85F698000000000FF000001FB00000000FB,epoch=\"conf_ver:5 version:168 \",peers=\"id:329 store_id:1 ,id:330 store_id:4 ,id:331 store_id:5 \"}"] [startKey=7480000000000000FFA85F698000000000FF0000010000000000FB] [endKey=7480000000000000FFA85F698000000000FF000001FB00000000FB] [error="Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/b7863b3d-0bbb-4450-a3d1-ebd9689e2fe7_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/d0056d79-9710-490b-aa79-b9f9723fbc63_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/119c13ba-e28b-4b83-80b2-16bafa5597f1_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/6f8f80d4-8cdb-4da6-8479-f82dc2e31901_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/ccfe7a83-ad46-47d3-9954-76eb5c75efc6_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/dfdb7c4f-fa49-4181-9902-2b98227def53_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/cc9db575-1158-4403-9931-133d343895ac_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed; Cannot read local:///mnt/positive_volume/peter_test_20220623001/1_316_165_4d7ca7e2fde4633c1fff5060831e06c2b059251cc964120b643707e782a778ba_1655970593901_write.sst into /data/import/.temp/68cf7536-7408-4557-94af-dc15e02750f1_328_5_168_write.sst: downloaded size 0, expected 1597: [BR:KV:ErrKVDownloadFailed]download sst failed"] [stack="github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).Import.func1\
\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:367\
github.com/pingcap/tidb/br/pkg/utils.WithRetry\
\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/utils/retry.go:58\
github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).Import\
\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:298\
github.com/pingcap/tidb/br/pkg/restore.(*Client).RestoreFiles.func2\
\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/client.go:643\
github.com/pingcap/tidb/br/pkg/utils.(*WorkerPool).ApplyOnErrorGroup.func1\
\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/utils/worker.go:73\
golang.org/x/sync/errgroup.(*Group).Go.func1\
\t/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57"]
22

备份到 TiKV 本地目录，会产生 tmp 文件吗