From fe5c337ca259742c956048d4abe05fa99a8b15fa Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sat, 30 Dec 2023 21:40:41 +0100 Subject: [PATCH 1/4] repository: StreamPack delivers blobs at most once If an error occurred while streaming a pack file, this could result in passing some of the blobs multiple times to the callback function. This significantly complicates using StreamPack correctly and is unnecessary. Retries do not change the content of a blob and thus only deliver the same result over and over again. --- internal/repository/repository.go | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/internal/repository/repository.go b/internal/repository/repository.go index f78c55e1d..97dc33fdf 100644 --- a/internal/repository/repository.go +++ b/internal/repository/repository.go @@ -881,9 +881,9 @@ type BackendLoadFn func(ctx context.Context, h backend.Handle, length int, offse const maxUnusedRange = 4 * 1024 * 1024 // StreamPack loads the listed blobs from the specified pack file. The plaintext blob is passed to -// the handleBlobFn callback or an error if decryption failed or the blob hash does not match. In -// case of download errors handleBlobFn might be called multiple times for the same blob. If the -// callback returns an error, then StreamPack will abort and not retry it. +// the handleBlobFn callback or an error if decryption failed or the blob hash does not match. +// handleBlobFn is never called multiple times for the same blob. If the callback returns an error, +// then StreamPack will abort and not retry it. func StreamPack(ctx context.Context, beLoad BackendLoadFn, key *crypto.Key, packID restic.ID, blobs []restic.Blob, handleBlobFn func(blob restic.BlobHandle, buf []byte, err error) error) error { if len(blobs) == 0 { // nothing to do @@ -945,7 +945,9 @@ func streamPackPart(ctx context.Context, beLoad BackendLoadFn, key *crypto.Key, currentBlobEnd := dataStart var buf []byte var decode []byte - for _, entry := range blobs { + for len(blobs) > 0 { + entry := blobs[0] + skipBytes := int(entry.Offset - currentBlobEnd) if skipBytes < 0 { return errors.Errorf("overlapping blobs in pack %v", packID) @@ -1008,6 +1010,8 @@ func streamPackPart(ctx context.Context, beLoad BackendLoadFn, key *crypto.Key, cancel() return backoff.Permanent(err) } + // ensure that each blob is only passed once to handleBlobFn + blobs = blobs[1:] } return nil }) From 77b1c52673a779929058d045ab87e6949f6b6478 Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sat, 30 Dec 2023 22:08:57 +0100 Subject: [PATCH 2/4] repository: test that StreamPack only delivers blobs once --- internal/repository/repository_test.go | 50 ++++++++++++++++++++------ 1 file changed, 40 insertions(+), 10 deletions(-) diff --git a/internal/repository/repository_test.go b/internal/repository/repository_test.go index bb8395436..1178a7693 100644 --- a/internal/repository/repository_test.go +++ b/internal/repository/repository_test.go @@ -5,6 +5,7 @@ import ( "context" "crypto/sha256" "encoding/json" + "errors" "fmt" "io" "math/rand" @@ -14,6 +15,7 @@ import ( "testing" "time" + "github.com/cenkalti/backoff/v4" "github.com/google/go-cmp/cmp" "github.com/klauspost/compress/zstd" "github.com/restic/restic/internal/backend" @@ -529,7 +531,9 @@ func testStreamPack(t *testing.T, version uint) { packfileBlobs, packfile := buildPackfileWithoutHeader(blobSizes, &key, compress) loadCalls := 0 - load := func(ctx context.Context, h backend.Handle, length int, offset int64, fn func(rd io.Reader) error) error { + shortFirstLoad := false + + loadBytes := func(length int, offset int64) []byte { data := packfile if offset > int64(len(data)) { @@ -541,32 +545,56 @@ func testStreamPack(t *testing.T, version uint) { if length > len(data) { length = len(data) } + if shortFirstLoad { + length /= 2 + shortFirstLoad = false + } + + return data[:length] + } + + load := func(ctx context.Context, h backend.Handle, length int, offset int64, fn func(rd io.Reader) error) error { + data := loadBytes(length, offset) + if shortFirstLoad { + data = data[:len(data)/2] + shortFirstLoad = false + } - data = data[:length] loadCalls++ - return fn(bytes.NewReader(data)) + err := fn(bytes.NewReader(data)) + if err == nil { + return nil + } + var permanent *backoff.PermanentError + if errors.As(err, &permanent) { + return err + } + // retry loading once + return fn(bytes.NewReader(loadBytes(length, offset))) } // first, test regular usage t.Run("regular", func(t *testing.T) { tests := []struct { - blobs []restic.Blob - calls int + blobs []restic.Blob + calls int + shortFirstLoad bool }{ - {packfileBlobs[1:2], 1}, - {packfileBlobs[2:5], 1}, - {packfileBlobs[2:8], 1}, + {packfileBlobs[1:2], 1, false}, + {packfileBlobs[2:5], 1, false}, + {packfileBlobs[2:8], 1, false}, {[]restic.Blob{ packfileBlobs[0], packfileBlobs[4], packfileBlobs[2], - }, 1}, + }, 1, false}, {[]restic.Blob{ packfileBlobs[0], packfileBlobs[len(packfileBlobs)-1], - }, 2}, + }, 2, false}, + {packfileBlobs[:], 1, true}, } for _, test := range tests { @@ -593,6 +621,7 @@ func testStreamPack(t *testing.T, version uint) { } loadCalls = 0 + shortFirstLoad = test.shortFirstLoad err = repository.StreamPack(ctx, load, &key, restic.ID{}, test.blobs, handleBlob) if err != nil { t.Fatal(err) @@ -605,6 +634,7 @@ func testStreamPack(t *testing.T, version uint) { }) } }) + shortFirstLoad = false // next, test invalid uses, which should return an error t.Run("invalid", func(t *testing.T) { From dac350817081b59e72325834161f880fa46576cb Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sat, 30 Dec 2023 22:39:26 +0100 Subject: [PATCH 3/4] restore: only report errors for blobs that actually failed to load Previously, errors would be reported for all blobs of a packfile that failed to stream. Now, only the not yet processed blobs are reported. --- internal/restorer/filerestorer.go | 17 +++++++++- internal/restorer/filerestorer_test.go | 44 ++++++++++++++++++++++++++ 2 files changed, 60 insertions(+), 1 deletion(-) diff --git a/internal/restorer/filerestorer.go b/internal/restorer/filerestorer.go index 3bb7489ba..1fc74c7f0 100644 --- a/internal/restorer/filerestorer.go +++ b/internal/restorer/filerestorer.go @@ -246,7 +246,10 @@ func (r *fileRestorer) downloadPack(ctx context.Context, pack *packInfo) error { return err } + // track already processed blobs for precise error reporting + processedBlobs := restic.NewBlobSet() err := repository.StreamPack(ctx, r.packLoader, r.key, pack.id, blobList, func(h restic.BlobHandle, blobData []byte, err error) error { + processedBlobs.Insert(h) blob := blobs[h.ID] if err != nil { for file := range blob.files { @@ -292,7 +295,19 @@ func (r *fileRestorer) downloadPack(ctx context.Context, pack *packInfo) error { }) if err != nil { - for file := range pack.files { + // only report error for not yet processed blobs + affectedFiles := make(map[*fileInfo]struct{}) + for _, blob := range blobList { + if processedBlobs.Has(blob.BlobHandle) { + continue + } + blob := blobs[blob.ID] + for file := range blob.files { + affectedFiles[file] = struct{}{} + } + } + + for file := range affectedFiles { if errFile := sanitizeError(file, err); errFile != nil { return errFile } diff --git a/internal/restorer/filerestorer_test.go b/internal/restorer/filerestorer_test.go index aa9a2392d..94b068159 100644 --- a/internal/restorer/filerestorer_test.go +++ b/internal/restorer/filerestorer_test.go @@ -317,3 +317,47 @@ func testPartialDownloadError(t *testing.T, part int) { rtest.OK(t, err) verifyRestore(t, r, repo) } + +func TestFatalDownloadError(t *testing.T) { + tempdir := rtest.TempDir(t) + content := []TestFile{ + { + name: "file1", + blobs: []TestBlob{ + {"data1-1", "pack1"}, + {"data1-2", "pack1"}, + }, + }, + { + name: "file2", + blobs: []TestBlob{ + {"data2-1", "pack1"}, + {"data2-2", "pack1"}, + {"data2-3", "pack1"}, + }, + }} + + repo := newTestRepo(content) + + loader := repo.loader + repo.loader = func(ctx context.Context, h backend.Handle, length int, offset int64, fn func(rd io.Reader) error) error { + // only return half the data to break file2 + return loader(ctx, h, length/2, offset, fn) + } + + r := newFileRestorer(tempdir, repo.loader, repo.key, repo.Lookup, 2, false, nil) + r.files = repo.files + + var errors []string + r.Error = func(s string, e error) error { + // ignore errors as in the `restore` command + errors = append(errors, s) + return nil + } + + err := r.restoreFiles(context.TODO()) + rtest.OK(t, err) + + rtest.Assert(t, len(errors) == 1, "unexpected number of restore errors, expected: 1, got: %v", len(errors)) + rtest.Assert(t, errors[0] == "file2", "expected error for file2, got: %v", errors[0]) +} From 100872308f938d285fc4759c47b713d8e189d14f Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sun, 7 Jan 2024 11:06:42 +0100 Subject: [PATCH 4/4] add changelog for better restore error reporting --- changelog/unreleased/pull-4624 | 11 +++++++++++ 1 file changed, 11 insertions(+) create mode 100644 changelog/unreleased/pull-4624 diff --git a/changelog/unreleased/pull-4624 b/changelog/unreleased/pull-4624 new file mode 100644 index 000000000..fbdbb1558 --- /dev/null +++ b/changelog/unreleased/pull-4624 @@ -0,0 +1,11 @@ +Bugfix: Correct restore progress information if an error occurs + +If an error occurred while restoring a snapshot, this could cause the restore +progress bar to show incorrect information. In addition, if a data file could +not be loaded completely, then errors would also be reported for some already +restored files. + +We have improved the error reporting of the restore command to be more accurate. + +https://github.com/restic/restic/pull/4624 +https://forum.restic.net/t/errors-restoring-with-restic-on-windows-server-s3/6943