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

kkpeter · 2022 年6 月 23 日 07:58

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"]