Replace restore progress bars with periodic ui.Progress lines
Restore and verify no longer use schollz/progressbar. Instead they emit a periodic status line every 15 s via ui.Writer.Progress, matching the cadence and shape of the snapshot create scanner output. The lines include files done, byte counts, throughput in bits/sec, elapsed, absolute ETA, and remaining duration — same conventions as snapshot create. The progressbar dependency, the newProgressBar/isTerminal helpers, and the unused printfStderr helper are removed; go.mod loses schollz/progressbar plus its colorstring and uniseg transitive deps. Adds --debug timing instrumentation throughout the restore hot path so the next slow-restore report can pinpoint which stage is the bottleneck. Per-file: file-chunks query, output Create, per-chunk blob DB lookups, cache get/put, blob download, chunk write, sweeper call. Per-blob-download: fetch-setup (Get + Stat) vs read+decrypt+decompress vs close-and-verify. FetchBlob splits the Storage.Get and Storage.Stat round-trips so an expensive size-stat is visible separately.
This commit is contained in:
3
go.mod
3
go.mod
@@ -18,7 +18,6 @@ require (
|
||||
github.com/johannesboyne/gofakes3 v0.0.0-20250603205740-ed9094be7668
|
||||
github.com/klauspost/compress v1.18.1
|
||||
github.com/rclone/rclone v1.72.1
|
||||
github.com/schollz/progressbar/v3 v3.19.0
|
||||
github.com/spf13/afero v1.15.0
|
||||
github.com/spf13/cobra v1.10.1
|
||||
github.com/stretchr/testify v1.11.1
|
||||
@@ -186,7 +185,6 @@ require (
|
||||
github.com/mattn/go-colorable v0.1.14 // indirect
|
||||
github.com/mattn/go-isatty v0.0.20 // indirect
|
||||
github.com/mattn/go-runewidth v0.0.19 // indirect
|
||||
github.com/mitchellh/colorstring v0.0.0-20190213212951-d06e56a500db // indirect
|
||||
github.com/mitchellh/go-homedir v1.1.0 // indirect
|
||||
github.com/mitchellh/mapstructure v1.5.0 // indirect
|
||||
github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect
|
||||
@@ -217,7 +215,6 @@ require (
|
||||
github.com/relvacode/iso8601 v1.7.0 // indirect
|
||||
github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect
|
||||
github.com/rfjakob/eme v1.1.2 // indirect
|
||||
github.com/rivo/uniseg v0.4.7 // indirect
|
||||
github.com/ryanuber/go-glob v1.0.0 // indirect
|
||||
github.com/ryszard/goskiplist v0.0.0-20150312221310-2dfbae5fcf46 // indirect
|
||||
github.com/sabhiram/go-gitignore v0.0.0-20210923224102-525f6e181f06 // indirect
|
||||
|
||||
8
go.sum
8
go.sum
@@ -202,8 +202,6 @@ github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UF
|
||||
github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
|
||||
github.com/cevatbarisyilmaz/ara v0.0.4 h1:SGH10hXpBJhhTlObuZzTuFn1rrdmjQImITXnZVPSodc=
|
||||
github.com/cevatbarisyilmaz/ara v0.0.4/go.mod h1:BfFOxnUd6Mj6xmcvRxHN3Sr21Z1T3U2MYkYOmoQe4Ts=
|
||||
github.com/chengxilo/virtualterm v1.0.4 h1:Z6IpERbRVlfB8WkOmtbHiDbBANU7cimRIof7mk9/PwM=
|
||||
github.com/chengxilo/virtualterm v1.0.4/go.mod h1:DyxxBZz/x1iqJjFxTFcr6/x+jSpqN0iwWCOK1q10rlY=
|
||||
github.com/chilts/sid v0.0.0-20190607042430-660e94789ec9 h1:z0uK8UQqjMVYzvk4tiiu3obv2B44+XBsvgEJREQfnO8=
|
||||
github.com/chilts/sid v0.0.0-20190607042430-660e94789ec9/go.mod h1:Jl2neWsQaDanWORdqZ4emBl50J4/aRBBS4FyyG9/PFo=
|
||||
github.com/chzyer/logex v1.1.10/go.mod h1:+Ywpsq7O8HXn0nuIou7OrIPyXbp3wmkHB+jjWRnGsAI=
|
||||
@@ -599,8 +597,6 @@ github.com/miekg/dns v1.1.41 h1:WMszZWJG0XmzbK9FEmzH2TVcqYzFesusSIB41b8KHxY=
|
||||
github.com/miekg/dns v1.1.41/go.mod h1:p6aan82bvRIyn+zDIv9xYNUpwa73JcSh9BKwknJysuI=
|
||||
github.com/mitchellh/cli v1.0.0/go.mod h1:hNIlj7HEI86fIcpObd7a0FcrxTWetlwJDGcceTlRvqc=
|
||||
github.com/mitchellh/cli v1.1.0/go.mod h1:xcISNoH86gajksDmfB23e/pu+B+GeFRMYmoHXxx3xhI=
|
||||
github.com/mitchellh/colorstring v0.0.0-20190213212951-d06e56a500db h1:62I3jR2EmQ4l5rM/4FEfDWcRD+abF5XlKShorW5LRoQ=
|
||||
github.com/mitchellh/colorstring v0.0.0-20190213212951-d06e56a500db/go.mod h1:l0dey0ia/Uv7NcFFVbCLtqEBQbrT4OCwCSKTEv6enCw=
|
||||
github.com/mitchellh/go-homedir v1.1.0 h1:lukF9ziXFxDFPkA1vsr5zpc1XuPDn/wFntq5mG+4E0Y=
|
||||
github.com/mitchellh/go-homedir v1.1.0/go.mod h1:SfyaCUpYCn1Vlf4IUYiD9fPX4A5wJrkLzIz1N1q0pr0=
|
||||
github.com/mitchellh/go-wordwrap v1.0.0/go.mod h1:ZXFpozHsX6DPmq2I0TCekCxypsnAUbP2oI0UX1GXzOo=
|
||||
@@ -705,8 +701,6 @@ github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec h1:W09IVJc94
|
||||
github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec/go.mod h1:qqbHyh8v60DhA7CoWK5oRCqLrMHRGoxYCSS9EjAz6Eo=
|
||||
github.com/rfjakob/eme v1.1.2 h1:SxziR8msSOElPayZNFfQw4Tjx/Sbaeeh3eRvrHVMUs4=
|
||||
github.com/rfjakob/eme v1.1.2/go.mod h1:cVvpasglm/G3ngEfcfT/Wt0GwhkuO32pf/poW6Nyk1k=
|
||||
github.com/rivo/uniseg v0.4.7 h1:WUdvkW8uEhrYfLC4ZzdpI2ztxP1I582+49Oc5Mq64VQ=
|
||||
github.com/rivo/uniseg v0.4.7/go.mod h1:FN3SvrM+Zdj16jyLfmOkMNblXMcoc8DfTHruCPUcx88=
|
||||
github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
|
||||
github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ=
|
||||
github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc=
|
||||
@@ -721,8 +715,6 @@ github.com/sabhiram/go-gitignore v0.0.0-20210923224102-525f6e181f06 h1:OkMGxebDj
|
||||
github.com/sabhiram/go-gitignore v0.0.0-20210923224102-525f6e181f06/go.mod h1:+ePHsJ1keEjQtpvf9HHw0f4ZeJ0TLRsxhunSI2hYJSs=
|
||||
github.com/samber/lo v1.52.0 h1:Rvi+3BFHES3A8meP33VPAxiBZX/Aws5RxrschYGjomw=
|
||||
github.com/samber/lo v1.52.0/go.mod h1:4+MXEGsJzbKGaUEQFKBq2xtfuznW9oz/WrgyzMzRoM0=
|
||||
github.com/schollz/progressbar/v3 v3.19.0 h1:Ea18xuIRQXLAUidVDox3AbwfUhD0/1IvohyTutOIFoc=
|
||||
github.com/schollz/progressbar/v3 v3.19.0/go.mod h1:IsO3lpbaGuzh8zIMzgY3+J8l4C8GjO0Y9S69eFvNsec=
|
||||
github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529 h1:nn5Wsu0esKSJiIVhscUtVbo7ada43DJhG55ua/hjS5I=
|
||||
github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg65j358z/aeFdxmN0P9QXhEzd20vsDc=
|
||||
github.com/sergi/go-diff v1.0.0/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=
|
||||
|
||||
@@ -6,9 +6,11 @@ import (
|
||||
"encoding/hex"
|
||||
"fmt"
|
||||
"io"
|
||||
"time"
|
||||
|
||||
"filippo.io/age"
|
||||
"sneak.berlin/go/vaultik/internal/blobgen"
|
||||
"sneak.berlin/go/vaultik/internal/log"
|
||||
)
|
||||
|
||||
// hashVerifyReader wraps a blobgen.Reader and verifies the double-SHA-256 hash
|
||||
@@ -75,19 +77,34 @@ func (v *Vaultik) FetchAndDecryptBlob(ctx context.Context, blobHash string, expe
|
||||
}
|
||||
|
||||
// FetchBlob downloads a blob and returns a reader for the encrypted data.
|
||||
// Times the Storage.Get and Storage.Stat round-trips separately at
|
||||
// debug level so we can see whether the size-only Stat (which is an
|
||||
// extra request on every fetch) is hurting throughput.
|
||||
func (v *Vaultik) FetchBlob(ctx context.Context, blobHash string, expectedSize int64) (io.ReadCloser, int64, error) {
|
||||
blobPath := fmt.Sprintf("blobs/%s/%s/%s", blobHash[:2], blobHash[2:4], blobHash)
|
||||
|
||||
t0 := time.Now()
|
||||
rc, err := v.Storage.Get(ctx, blobPath)
|
||||
getDur := time.Since(t0)
|
||||
if err != nil {
|
||||
return nil, 0, fmt.Errorf("downloading blob %s: %w", blobHash[:16], err)
|
||||
}
|
||||
|
||||
t0 = time.Now()
|
||||
info, err := v.Storage.Stat(ctx, blobPath)
|
||||
statDur := time.Since(t0)
|
||||
if err != nil {
|
||||
_ = rc.Close()
|
||||
return nil, 0, fmt.Errorf("stat blob %s: %w", blobHash[:16], err)
|
||||
}
|
||||
|
||||
log.Debug("FetchBlob round-trips",
|
||||
"hash", blobHash[:16],
|
||||
"ms_storage_get", getDur.Milliseconds(),
|
||||
"ms_storage_stat", statDur.Milliseconds(),
|
||||
"expected_size", expectedSize,
|
||||
"stat_size", info.Size,
|
||||
)
|
||||
|
||||
return rc, info.Size, nil
|
||||
}
|
||||
|
||||
@@ -14,22 +14,13 @@ import (
|
||||
|
||||
"filippo.io/age"
|
||||
"github.com/dustin/go-humanize"
|
||||
"github.com/schollz/progressbar/v3"
|
||||
"github.com/spf13/afero"
|
||||
"golang.org/x/term"
|
||||
"sneak.berlin/go/vaultik/internal/blobgen"
|
||||
"sneak.berlin/go/vaultik/internal/database"
|
||||
"sneak.berlin/go/vaultik/internal/log"
|
||||
"sneak.berlin/go/vaultik/internal/types"
|
||||
)
|
||||
|
||||
const (
|
||||
// progressBarWidth is the character width of the progress bar display.
|
||||
progressBarWidth = 40
|
||||
// progressBarThrottle is the minimum interval between progress bar redraws.
|
||||
progressBarThrottle = 100 * time.Millisecond
|
||||
)
|
||||
|
||||
// RestoreOptions contains options for the restore operation
|
||||
type RestoreOptions struct {
|
||||
SnapshotID string
|
||||
@@ -193,14 +184,21 @@ func (v *Vaultik) restoreAllFiles(
|
||||
// are all already restored.
|
||||
sweeper := newRestoreSweeper(v.ctx, repos, blobCache, v.Config.BlobSizeLimit.Int64()/100)
|
||||
|
||||
// Calculate total bytes for progress bar
|
||||
// Calculate total bytes expected for percentage / ETA arithmetic.
|
||||
var totalBytesExpected int64
|
||||
for _, file := range files {
|
||||
totalBytesExpected += file.Size
|
||||
}
|
||||
|
||||
// Create progress bar if output is a terminal
|
||||
bar := v.newProgressBar("Restoring", totalBytesExpected)
|
||||
v.UI.Begin("Restoring %s files (%s) to %s.",
|
||||
v.UI.Count(len(files)),
|
||||
v.UI.Size(totalBytesExpected),
|
||||
v.UI.Path(opts.TargetDir))
|
||||
|
||||
// Periodic progress output, matching the snapshot create cadence.
|
||||
startTime := time.Now()
|
||||
lastStatusTime := startTime
|
||||
const statusInterval = 15 * time.Second
|
||||
|
||||
for i, file := range files {
|
||||
if v.ctx.Err() != nil {
|
||||
@@ -215,10 +213,6 @@ func (v *Vaultik) restoreAllFiles(
|
||||
v.UI.Error("Failed to restore %s: %v. Skipping (--skip-errors).", v.UI.Path(file.Path.String()), err)
|
||||
result.FilesFailed++
|
||||
result.FailedFiles = append(result.FailedFiles, file.Path.String())
|
||||
// Update progress bar even on failure
|
||||
if bar != nil {
|
||||
_ = bar.Add64(file.Size)
|
||||
}
|
||||
continue
|
||||
}
|
||||
|
||||
@@ -226,12 +220,12 @@ func (v *Vaultik) restoreAllFiles(
|
||||
// all referencing files are done.
|
||||
sweeper.fileRestored(file.ID.String())
|
||||
|
||||
// Update progress bar
|
||||
if bar != nil {
|
||||
_ = bar.Add64(file.Size)
|
||||
if time.Since(lastStatusTime) >= statusInterval {
|
||||
v.printRestoreProgress(i+1, len(files), result.BytesRestored, totalBytesExpected, startTime)
|
||||
lastStatusTime = time.Now()
|
||||
}
|
||||
|
||||
// Progress logging (for non-terminal or structured logs)
|
||||
// Structured progress log for --verbose / JSON consumers.
|
||||
if (i+1)%100 == 0 || i+1 == len(files) {
|
||||
log.Info("Restore progress",
|
||||
"files", fmt.Sprintf("%d/%d", i+1, len(files)),
|
||||
@@ -240,11 +234,47 @@ func (v *Vaultik) restoreAllFiles(
|
||||
}
|
||||
}
|
||||
|
||||
if bar != nil {
|
||||
_ = bar.Finish()
|
||||
return result, nil
|
||||
}
|
||||
|
||||
// printRestoreProgress emits a periodic restore-phase status line via
|
||||
// the UI writer, mirroring scanner.printProcessingProgress so the two
|
||||
// long-running commands have the same on-screen rhythm.
|
||||
func (v *Vaultik) printRestoreProgress(filesDone, totalFiles int, bytesDone, totalBytes int64, startTime time.Time) {
|
||||
elapsed := time.Since(startTime)
|
||||
pct := float64(bytesDone) / float64(totalBytes) * 100
|
||||
byteRate := float64(bytesDone) / elapsed.Seconds()
|
||||
fileRate := float64(filesDone) / elapsed.Seconds()
|
||||
|
||||
remainingBytes := totalBytes - bytesDone
|
||||
var eta time.Duration
|
||||
if byteRate > 0 && remainingBytes > 0 {
|
||||
eta = time.Duration(float64(remainingBytes)/byteRate) * time.Second
|
||||
}
|
||||
|
||||
return result, nil
|
||||
if eta > 0 {
|
||||
v.UI.Progress("Restore: %s/%s files (%s), %s/%s, %s, %.0f files/sec, restore elapsed: %s, restore ETA: %s (est remain %s).",
|
||||
v.UI.Count(filesDone),
|
||||
v.UI.Count(totalFiles),
|
||||
v.UI.Percent(pct),
|
||||
v.UI.Size(bytesDone),
|
||||
v.UI.Size(totalBytes),
|
||||
v.UI.Speed(byteRate),
|
||||
fileRate,
|
||||
v.UI.Duration(elapsed),
|
||||
v.UI.Time(time.Now().Add(eta)),
|
||||
v.UI.Duration(eta))
|
||||
return
|
||||
}
|
||||
v.UI.Progress("Restore: %s/%s files (%s), %s/%s, %s, %.0f files/sec, restore elapsed: %s.",
|
||||
v.UI.Count(filesDone),
|
||||
v.UI.Count(totalFiles),
|
||||
v.UI.Percent(pct),
|
||||
v.UI.Size(bytesDone),
|
||||
v.UI.Size(totalBytes),
|
||||
v.UI.Speed(byteRate),
|
||||
fileRate,
|
||||
v.UI.Duration(elapsed))
|
||||
}
|
||||
|
||||
// handleRestoreVerification runs post-restore verification if requested
|
||||
@@ -259,17 +289,17 @@ func (v *Vaultik) handleRestoreVerification(
|
||||
}
|
||||
|
||||
if result.FilesFailed > 0 {
|
||||
v.printfStdout("\nVerification FAILED: %d files did not match expected checksums\n", result.FilesFailed)
|
||||
v.UI.Error("Verification failed: %s files did not match expected checksums.",
|
||||
v.UI.Count(result.FilesFailed))
|
||||
for _, path := range result.FailedFiles {
|
||||
v.printfStdout(" - %s\n", path)
|
||||
v.UI.Detail("%s", v.UI.Path(path))
|
||||
}
|
||||
return fmt.Errorf("%d files failed verification", result.FilesFailed)
|
||||
}
|
||||
|
||||
v.printfStdout("Verified %d files (%s)\n",
|
||||
result.FilesVerified,
|
||||
humanize.Bytes(uint64(result.BytesVerified)),
|
||||
)
|
||||
v.UI.Complete("Verified %s files (%s).",
|
||||
v.UI.Count(result.FilesVerified),
|
||||
v.UI.Size(result.BytesVerified))
|
||||
return nil
|
||||
}
|
||||
|
||||
@@ -491,21 +521,38 @@ func (v *Vaultik) restoreRegularFile(
|
||||
sweeper *restoreSweeper,
|
||||
result *RestoreResult,
|
||||
) error {
|
||||
fileStart := time.Now()
|
||||
|
||||
// Get file chunks in order
|
||||
t0 := time.Now()
|
||||
fileChunks, err := repos.FileChunks.GetByFileID(ctx, file.ID)
|
||||
fileChunksQueryDur := time.Since(t0)
|
||||
if err != nil {
|
||||
return fmt.Errorf("getting file chunks: %w", err)
|
||||
}
|
||||
|
||||
// Create output file
|
||||
t0 = time.Now()
|
||||
outFile, err := v.Fs.Create(targetPath)
|
||||
createDur := time.Since(t0)
|
||||
if err != nil {
|
||||
return fmt.Errorf("creating output file: %w", err)
|
||||
}
|
||||
defer func() { _ = outFile.Close() }()
|
||||
|
||||
// Write chunks in order
|
||||
var bytesWritten int64
|
||||
// Per-file timing buckets so --debug shows exactly where seconds go.
|
||||
var (
|
||||
blobDBLookupDur time.Duration
|
||||
cacheGetDur time.Duration
|
||||
downloadDur time.Duration
|
||||
cachePutDur time.Duration
|
||||
writeDur time.Duration
|
||||
sweeperDur time.Duration
|
||||
downloadCount int
|
||||
cacheHitCount int
|
||||
bytesWritten int64
|
||||
)
|
||||
|
||||
for _, fc := range fileChunks {
|
||||
// Find which blob contains this chunk
|
||||
chunkHashStr := fc.ChunkHash.String()
|
||||
@@ -514,25 +561,36 @@ func (v *Vaultik) restoreRegularFile(
|
||||
return fmt.Errorf("chunk %s not found in any blob", chunkHashStr[:16])
|
||||
}
|
||||
|
||||
// Get the blob's hash from the database
|
||||
// Get the blob's hash from the database (runs per chunk).
|
||||
t0 = time.Now()
|
||||
blob, err := repos.Blobs.GetByID(ctx, blobChunk.BlobID.String())
|
||||
blobDBLookupDur += time.Since(t0)
|
||||
if err != nil {
|
||||
return fmt.Errorf("getting blob %s: %w", blobChunk.BlobID, err)
|
||||
}
|
||||
|
||||
// Download and decrypt blob if not cached
|
||||
blobHashStr := blob.Hash.String()
|
||||
t0 = time.Now()
|
||||
blobData, ok := blobCache.Get(blobHashStr)
|
||||
cacheGetDur += time.Since(t0)
|
||||
if !ok {
|
||||
t0 = time.Now()
|
||||
blobData, err = v.downloadBlob(ctx, blobHashStr, blob.CompressedSize, identity)
|
||||
downloadDur += time.Since(t0)
|
||||
if err != nil {
|
||||
return fmt.Errorf("downloading blob %s: %w", blobHashStr[:16], err)
|
||||
}
|
||||
t0 = time.Now()
|
||||
if putErr := blobCache.Put(blobHashStr, blobData); putErr != nil {
|
||||
log.Debug("Failed to cache blob on disk", "hash", blobHashStr[:16], "error", putErr)
|
||||
}
|
||||
cachePutDur += time.Since(t0)
|
||||
downloadCount++
|
||||
result.BlobsDownloaded++
|
||||
result.BytesDownloaded += blob.CompressedSize
|
||||
} else {
|
||||
cacheHitCount++
|
||||
}
|
||||
|
||||
// Extract chunk from blob
|
||||
@@ -543,7 +601,9 @@ func (v *Vaultik) restoreRegularFile(
|
||||
chunkData := blobData[blobChunk.Offset : blobChunk.Offset+blobChunk.Length]
|
||||
|
||||
// Write chunk to output file
|
||||
t0 = time.Now()
|
||||
n, err := outFile.Write(chunkData)
|
||||
writeDur += time.Since(t0)
|
||||
if err != nil {
|
||||
return fmt.Errorf("writing chunk: %w", err)
|
||||
}
|
||||
@@ -552,9 +612,28 @@ func (v *Vaultik) restoreRegularFile(
|
||||
// Tell the sweeper about the bytes we just restored so it can
|
||||
// run an eviction sweep once the accumulated total crosses its
|
||||
// threshold (config.BlobSizeLimit/100).
|
||||
t0 = time.Now()
|
||||
sweeper.chunkRestored(int64(n))
|
||||
sweeperDur += time.Since(t0)
|
||||
}
|
||||
|
||||
log.Debug("Restored regular file (timings)",
|
||||
"path", file.Path,
|
||||
"chunks", len(fileChunks),
|
||||
"bytes_written", bytesWritten,
|
||||
"downloads", downloadCount,
|
||||
"cache_hits", cacheHitCount,
|
||||
"ms_total", time.Since(fileStart).Milliseconds(),
|
||||
"ms_file_chunks_query", fileChunksQueryDur.Milliseconds(),
|
||||
"ms_create", createDur.Milliseconds(),
|
||||
"ms_blob_db_lookups", blobDBLookupDur.Milliseconds(),
|
||||
"ms_cache_gets", cacheGetDur.Milliseconds(),
|
||||
"ms_cache_puts", cachePutDur.Milliseconds(),
|
||||
"ms_downloads", downloadDur.Milliseconds(),
|
||||
"ms_writes", writeDur.Milliseconds(),
|
||||
"ms_sweeper", sweeperDur.Milliseconds(),
|
||||
)
|
||||
|
||||
// Close file before setting metadata
|
||||
if err := outFile.Close(); err != nil {
|
||||
return fmt.Errorf("closing output file: %w", err)
|
||||
@@ -585,23 +664,44 @@ func (v *Vaultik) restoreRegularFile(
|
||||
return nil
|
||||
}
|
||||
|
||||
// downloadBlob downloads and decrypts a blob
|
||||
// downloadBlob downloads and decrypts a blob, returning the plaintext.
|
||||
// Emits a debug log line splitting time spent in the network fetch (Get
|
||||
// + Stat round-trips) from the streaming decrypt/decompress/read phase
|
||||
// so --debug shows which side of the wire is the bottleneck.
|
||||
func (v *Vaultik) downloadBlob(ctx context.Context, blobHash string, expectedSize int64, identity age.Identity) ([]byte, error) {
|
||||
start := time.Now()
|
||||
|
||||
t0 := time.Now()
|
||||
rc, err := v.FetchAndDecryptBlob(ctx, blobHash, expectedSize, identity)
|
||||
fetchSetupDur := time.Since(t0)
|
||||
if err != nil {
|
||||
return nil, err
|
||||
}
|
||||
|
||||
t0 = time.Now()
|
||||
data, err := io.ReadAll(rc)
|
||||
readAllDur := time.Since(t0)
|
||||
if err != nil {
|
||||
_ = rc.Close()
|
||||
return nil, fmt.Errorf("reading blob data: %w", err)
|
||||
}
|
||||
|
||||
// Close triggers hash verification
|
||||
t0 = time.Now()
|
||||
if err := rc.Close(); err != nil {
|
||||
return nil, err
|
||||
}
|
||||
closeDur := time.Since(t0)
|
||||
|
||||
log.Debug("Downloaded and decrypted blob (timings)",
|
||||
"hash", blobHash[:16],
|
||||
"compressed_bytes", expectedSize,
|
||||
"plaintext_bytes", len(data),
|
||||
"ms_total", time.Since(start).Milliseconds(),
|
||||
"ms_fetch_setup", fetchSetupDur.Milliseconds(),
|
||||
"ms_read_decrypt_decompress", readAllDur.Milliseconds(),
|
||||
"ms_close_verify", closeDur.Milliseconds(),
|
||||
)
|
||||
|
||||
return data, nil
|
||||
}
|
||||
@@ -635,16 +735,16 @@ func (v *Vaultik) verifyRestoredFiles(
|
||||
"files", len(regularFiles),
|
||||
"bytes", humanize.Bytes(uint64(totalBytes)),
|
||||
)
|
||||
v.printfStdout("\nVerifying %d files (%s)...\n",
|
||||
len(regularFiles),
|
||||
humanize.Bytes(uint64(totalBytes)),
|
||||
)
|
||||
v.UI.Begin("Verifying %s files (%s).",
|
||||
v.UI.Count(len(regularFiles)),
|
||||
v.UI.Size(totalBytes))
|
||||
|
||||
// Create progress bar if output is a terminal
|
||||
bar := v.newProgressBar("Verifying", totalBytes)
|
||||
startTime := time.Now()
|
||||
lastStatusTime := startTime
|
||||
const statusInterval = 15 * time.Second
|
||||
|
||||
// Verify each file
|
||||
for _, file := range regularFiles {
|
||||
var bytesProcessed int64
|
||||
for i, file := range regularFiles {
|
||||
if ctx.Err() != nil {
|
||||
return ctx.Err()
|
||||
}
|
||||
@@ -659,17 +759,14 @@ func (v *Vaultik) verifyRestoredFiles(
|
||||
result.FilesVerified++
|
||||
result.BytesVerified += bytesVerified
|
||||
}
|
||||
bytesProcessed += file.Size
|
||||
|
||||
// Update progress bar
|
||||
if bar != nil {
|
||||
_ = bar.Add64(file.Size)
|
||||
if time.Since(lastStatusTime) >= statusInterval {
|
||||
v.printVerifyProgress(i+1, len(regularFiles), bytesProcessed, totalBytes, startTime)
|
||||
lastStatusTime = time.Now()
|
||||
}
|
||||
}
|
||||
|
||||
if bar != nil {
|
||||
_ = bar.Finish()
|
||||
}
|
||||
|
||||
log.Info("Verification complete",
|
||||
"files_verified", result.FilesVerified,
|
||||
"bytes_verified", humanize.Bytes(uint64(result.BytesVerified)),
|
||||
@@ -679,6 +776,46 @@ func (v *Vaultik) verifyRestoredFiles(
|
||||
return nil
|
||||
}
|
||||
|
||||
// printVerifyProgress emits a periodic verify-phase status line. Same
|
||||
// shape as the restore progress line so user-facing pacing is uniform
|
||||
// across the two phases.
|
||||
func (v *Vaultik) printVerifyProgress(filesDone, totalFiles int, bytesDone, totalBytes int64, startTime time.Time) {
|
||||
elapsed := time.Since(startTime)
|
||||
pct := float64(bytesDone) / float64(totalBytes) * 100
|
||||
byteRate := float64(bytesDone) / elapsed.Seconds()
|
||||
fileRate := float64(filesDone) / elapsed.Seconds()
|
||||
|
||||
remainingBytes := totalBytes - bytesDone
|
||||
var eta time.Duration
|
||||
if byteRate > 0 && remainingBytes > 0 {
|
||||
eta = time.Duration(float64(remainingBytes)/byteRate) * time.Second
|
||||
}
|
||||
|
||||
if eta > 0 {
|
||||
v.UI.Progress("Verify: %s/%s files (%s), %s/%s, %s, %.0f files/sec, verify elapsed: %s, verify ETA: %s (est remain %s).",
|
||||
v.UI.Count(filesDone),
|
||||
v.UI.Count(totalFiles),
|
||||
v.UI.Percent(pct),
|
||||
v.UI.Size(bytesDone),
|
||||
v.UI.Size(totalBytes),
|
||||
v.UI.Speed(byteRate),
|
||||
fileRate,
|
||||
v.UI.Duration(elapsed),
|
||||
v.UI.Time(time.Now().Add(eta)),
|
||||
v.UI.Duration(eta))
|
||||
return
|
||||
}
|
||||
v.UI.Progress("Verify: %s/%s files (%s), %s/%s, %s, %.0f files/sec, verify elapsed: %s.",
|
||||
v.UI.Count(filesDone),
|
||||
v.UI.Count(totalFiles),
|
||||
v.UI.Percent(pct),
|
||||
v.UI.Size(bytesDone),
|
||||
v.UI.Size(totalBytes),
|
||||
v.UI.Speed(byteRate),
|
||||
fileRate,
|
||||
v.UI.Duration(elapsed))
|
||||
}
|
||||
|
||||
// verifyFile verifies a single restored file by checking its chunk hashes
|
||||
func (v *Vaultik) verifyFile(
|
||||
ctx context.Context,
|
||||
@@ -734,38 +871,3 @@ func (v *Vaultik) verifyFile(
|
||||
log.Debug("File verified", "path", file.Path, "bytes", bytesVerified, "chunks", len(fileChunks))
|
||||
return bytesVerified, nil
|
||||
}
|
||||
|
||||
// newProgressBar creates a terminal-aware progress bar with standard options.
|
||||
// It returns nil if stdout is not a terminal.
|
||||
func (v *Vaultik) newProgressBar(description string, total int64) *progressbar.ProgressBar {
|
||||
if !v.isTerminal() {
|
||||
return nil
|
||||
}
|
||||
return progressbar.NewOptions64(
|
||||
total,
|
||||
progressbar.OptionSetDescription(description),
|
||||
progressbar.OptionSetWriter(v.Stderr),
|
||||
progressbar.OptionShowBytes(true),
|
||||
progressbar.OptionShowCount(),
|
||||
progressbar.OptionSetWidth(progressBarWidth),
|
||||
progressbar.OptionThrottle(progressBarThrottle),
|
||||
progressbar.OptionOnCompletion(func() {
|
||||
v.printfStderr("\n")
|
||||
}),
|
||||
progressbar.OptionSetRenderBlankState(true),
|
||||
)
|
||||
}
|
||||
|
||||
// isTerminal returns true if stdout is a terminal.
|
||||
// It checks whether v.Stdout implements Fd() (i.e. is an *os.File),
|
||||
// and falls back to false for non-file writers (e.g. in tests).
|
||||
func (v *Vaultik) isTerminal() bool {
|
||||
type fder interface {
|
||||
Fd() uintptr
|
||||
}
|
||||
f, ok := v.Stdout.(fder)
|
||||
if !ok {
|
||||
return false
|
||||
}
|
||||
return term.IsTerminal(int(f.Fd()))
|
||||
}
|
||||
|
||||
@@ -147,11 +147,6 @@ func (v *Vaultik) printlnStdout(args ...any) {
|
||||
_, _ = fmt.Fprintln(v.Stdout, args...)
|
||||
}
|
||||
|
||||
// printfStderr writes formatted output to stderr.
|
||||
func (v *Vaultik) printfStderr(format string, args ...any) {
|
||||
_, _ = fmt.Fprintf(v.Stderr, format, args...)
|
||||
}
|
||||
|
||||
// scanStdin reads a line of input from stdin.
|
||||
func (v *Vaultik) scanStdin(a ...any) (int, error) {
|
||||
return fmt.Fscanln(v.Stdin, a...)
|
||||
|
||||
Reference in New Issue
Block a user