br restore encrypted backup failed "Bad table magic number

[fubinzh]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Run br backup and restore, specifying encryption parameters as below

/br  backup  db "-s" "s3://tmp/br-backup-basica744c193-d3d1-4f4a-8f31-dc07172963a1?access-key=minioadmin&secret-access-key=minioadmin&endpoint=http%3a%2f%2fminio.pingcap.net%3a9000&force-path-style=true" "-u" "http://upstream-pd.brie-acceptance-tps-633695-1-121:2379" "--db" "IFRS9" "--use-backupmeta-v2" "--crypter.method" "aes128-ctr" "--crypter.key" "0123456789abcdef0123456789abcdef"

/br  restore  db "-s" "s3://tmp/br-backup-basica744c193-d3d1-4f4a-8f31-dc07172963a1?access-key=minioadmin&secret-access-key=minioadmin&endpoint=http%3a%2f%2fminio.pingcap.net%3a9000&force-path-style=true" "-u" "http://downstream-pd.brie-acceptance-tps-633695-1-121:2379" "--db" "IFRS9" "--crypter.method" "aes128-ctr" "--crypter.key" "0123456789abcdef0123456789abcdef"

2. What did you expect to see? (Required)

Restore can be successful.

3. What did you see instead (Required)

restore failed, error: "Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/b10f671b-0aa3-4914-938b-6f2c021605d0_20460_5_3231_default.sst"

# /br  restore  db "-s" "s3://tmp/br-backup-basica744c193-d3d1-4f4a-8f31-dc07172963a1?access-key=minioadmin&secret-access-key=minioadmin&endpoint=http%3a%2f%2fminio.pingcap.net%3a9000&force-path-style=true" "-u" "http://downstream-pd.brie-acceptance-tps-633695-1-121:2379" "--db" "IFR
S9" "--crypter.method" "aes128-ctr" "--crypter.key" "0123456789abcdef0123456789abcdef"
Detail BR log in /tmp/br.log.2022-02-17T02.15.31Z
Database restore <-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------> 100.00%
[2022/02/17 02:16:12.110 +00:00] [INFO] [collector.go:67] ["Database restore failed summary"] [total-ranges=1] [ranges-succeed=0] [ranges-failed=1] [split-region=450.889µs] [restore-ranges=50] [unit-name=file] [error="Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/b10f671b-0aa3-4914-938b-6f2c021605d0_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/61410545-b809-4f54-a489-82103a53816d_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/e8734dca-9ea7-46a6-ac2b-ebc0b66e629b_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/e9eac562-0bf4-4218-b8f9-e22fa41ac1f0_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/158d4eb2-bf11-499d-ab3a-c2283edfded9_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/17d525b2-10ff-4054-b462-bb49f4964746_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/076a7695-51d8-46f8-af49-f2d16bd2c1df_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/2fa5a118-9f91-49f5-966d-dc55313f3616_20460_5_3231_default.sst\"): [BR:KV:ErrKVDownloadFailed]download sst failed"] [errorVerbose="the following errors occurred:\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/b10f671b-0aa3-4914-938b-6f2c021605d0_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/61410545-b809-4f54-a489-82103a53816d_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/e8734dca-9ea7-46a6-ac2b-ebc0b66e629b_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/e9eac562-0bf4-4218-b8f9-e22fa41ac1f0_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/158d4eb2-bf11-499d-ab3a-c2283edfded9_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/17d525b2-10ff-4054-b462-bb49f4964746_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/076a7695-51d8-46f8-af49-f2d16bd2c1df_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371\n -  [BR:KV:ErrKVDownloadFailed]download sst failed\n    Engine Engine(\"Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/2fa5a118-9f91-49f5-966d-dc55313f3616_20460_5_3231_default.sst\")\n    github.com/pingcap/tidb/br/pkg/restore.(*FileImporter).downloadSST.func1\n    \t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/restore/import.go:499\n    golang.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\n    runtime.goexit\n    \t/usr/local/go/src/runtime/asm_amd64.s:1371"]
Error: Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/b10f671b-0aa3-4914-938b-6f2c021605d0_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/61410545-b809-4f54-a489-82103a53816d_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/e8734dca-9ea7-46a6-ac2b-ebc0b66e629b_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/e9eac562-0bf4-4218-b8f9-e22fa41ac1f0_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/158d4eb2-bf11-499d-ab3a-c2283edfded9_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/17d525b2-10ff-4054-b462-bb49f4964746_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/076a7695-51d8-46f8-af49-f2d16bd2c1df_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed; Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 7952868509031340309 in /var/lib/tikv/data/import/.temp/2fa5a118-9f91-49f5-966d-dc55313f3616_20460_5_3231_default.sst"): [BR:KV:ErrKVDownloadFailed]download sst failed

4. What is your TiDB version? (Required)

/ # /br -V
Release Version: v5.5.0-nightly
Git Commit Hash: 9659b93
Git Branch: heads/refs/tags/v5.5.0-nightly
Go Version: go1.16.4
UTC Build Time: 2022-02-16 06:07:49
Race Enabled: false

[fubinzh]

The error log of this bug is similar to previously fixed bug: #30225

[joccau]

• This case "br_encryption_aes128_ctr_backupmeta_v2" failed only, but others case about crypt has successful result.
• This case succeed when reproducing this case.

[fubinzh]

It failed again during the daily CI today, refer to https://tcms.pingcap.net/dashboard/executions/plan/633883

[YuJuncen]

Can we download the SST file 076a7695-51d8-46f8-af49-f2d16bd2c1df_20460_5_3231_default.sst?

[fubinzh]

Can we download the SST file 076a7695-51d8-46f8-af49-f2d16bd2c1df_20460_5_3231_default.sst?

@YuJuncen please get it from http://172.16.5.66:9000/tmp/fubin/17884e0d-7863-4f36-8119-f45ab83385ca_308_5_78_default.sst?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=IGJERMI9YK8YO1SPZD3B%2F20220221%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20220221T013211Z&X-Amz-Expires=604799&X-Amz-Security-Token=eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJhY2Nlc3NLZXkiOiJJR0pFUk1JOVlLOFlPMVNQWkQzQiIsImV4cCI6MTY0NTQxMDcwNywicG9saWN5IjoiY29uc29sZUFkbWluIn0.ehj94OZNZpFvmXJsQ2MCJfCKSEs8mEvW7jH2jX305K_EhozPWaz5T-kCOEoKF1jzgqHYTYVtgDFMb_iF2Kxr2A&X-Amz-SignedHeaders=host&versionId=null&X-Amz-Signature=511ba8fe2ac03e40b6253b6c512926cb192fc8f708af9d10d9e3b011ec14db67

/ # /br restore db "-s" "s3://tmp/br-backup-basica744c193-d3d1-4f4a-8f31-dc07172963a1?access-key=minioadmin&secret-access-key=minioadmin&endpoint=http%3a%2f%2fminio.pingcap.net%3a9000&force-path-style=true" "-u" "http://
dst-tidb-pd.fb-br-placement-master-m4zqc:2379" "--db" "IFRS9" "--crypter.method" "aes128-ctr" "--crypter.key" "0123456789abcdef0123456789abcdef"
Detail BR log in /tmp/br.log.2022-02-21T01.22.36Z
Database restore <---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------> 100.00%
[2022/02/21 01:23:15.488 +00:00] [INFO] [collector.go:67] ["Database restore failed summary"] [total-ranges=1] [ranges-succeed=0] [ranges-failed=1] [split-region=367.472µs] [restore-ranges=50] [unit-name=file] [error="Engine Engine("Corruption: Bad table magic number: expected 9863518390377041911, found 1458627345096634236 in /var/lib/tikv/data/import/.temp/4ba1b937-1b89-4242-8b22-efdbc7b9846f_308_5_78_default.sst"):

[fubinzh]

3 of 5 recent daily CI since 2022/02/17 failed for this case (please refer to https://tcms.pingcap.net/dashboard/executions/plan?query=brie-acceptance%40main&page=1&pageSize=20) , please triage it with high priority, thanks.

[YuJuncen]

I've checked those files, and found out that:

1. the corrupted file 17884e0d-7863-4f36-8119-f45ab83385ca_308_5_78_default.sstThe ORIGINAL file) was decrypted from the file 1_4444_469_698ec964e67db64231a7ef85ed6f26c4a7ae18101004ff243765a5e9445af12d_1645037214310_default.sst (the ENCRYPTED file).

2. the meta of the encrypted file shows that its sha256 should be that... So there isn't file corruption.

{
  "sha256": "0a409a13ff6d3b4d494b176e09563cf7827e137598db58a6c08097100db43ed8",
  "start_key": "7480000000000002ee5f72fa00000000567b49",
  "end_key": "7480000000000002ee5f72fc0000000052935d",
  "name": "1_4444_469_698ec964e67db64231a7ef85ed6f26c4a7ae18101004ff243765a5e9445af12d_1645037214310_default.sst",
  "end_version": 431236630631415800,
  "crc64xor": 2619387936646232000,
  "total_kvs": 139709,
  "total_bytes": 44761977,
  "cf": "default",
  "size": 17236528,
  "cipher_iv": "Ynuhu60Tafw0q9q5otBa7g=="
}

3. ...and, the decrypt result using openssl enc -aes-128-ctr -iv 627ba1bbad1369fc34abdab9a2d05aee -K '0123456789abcdef0123456789abcdef' -d -in ~/Downloads/1_4444_469_698ec964e67db64231a7ef85ed6f26c4a7ae18101004ff243765a5e9445af12d_1645037214310_default.sst -out 1444.decoded.sst generated the same file of the original file.
4. The other file (1_1456....sst) is fine.

I guess the file should already be incorrect when we backing up. 🤔

[fubinzh]

close it, the issue is fixed in master.