Merge refactor/restore-progress-output
All checks were successful
check / check (push) Successful in 2m46s

This commit is contained in:
2026-06-17 07:54:18 +02:00
5 changed files with 202 additions and 99 deletions

3
go.mod
View File

@@ -18,7 +18,6 @@ require (
github.com/johannesboyne/gofakes3 v0.0.0-20250603205740-ed9094be7668 github.com/johannesboyne/gofakes3 v0.0.0-20250603205740-ed9094be7668
github.com/klauspost/compress v1.18.1 github.com/klauspost/compress v1.18.1
github.com/rclone/rclone v1.72.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/afero v1.15.0
github.com/spf13/cobra v1.10.1 github.com/spf13/cobra v1.10.1
github.com/stretchr/testify v1.11.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-colorable v0.1.14 // indirect
github.com/mattn/go-isatty v0.0.20 // indirect github.com/mattn/go-isatty v0.0.20 // indirect
github.com/mattn/go-runewidth v0.0.19 // 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/go-homedir v1.1.0 // indirect
github.com/mitchellh/mapstructure v1.5.0 // indirect github.com/mitchellh/mapstructure v1.5.0 // indirect
github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // 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/relvacode/iso8601 v1.7.0 // indirect
github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect
github.com/rfjakob/eme v1.1.2 // 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/ryanuber/go-glob v1.0.0 // indirect
github.com/ryszard/goskiplist v0.0.0-20150312221310-2dfbae5fcf46 // indirect github.com/ryszard/goskiplist v0.0.0-20150312221310-2dfbae5fcf46 // indirect
github.com/sabhiram/go-gitignore v0.0.0-20210923224102-525f6e181f06 // indirect github.com/sabhiram/go-gitignore v0.0.0-20210923224102-525f6e181f06 // indirect

8
go.sum
View File

@@ -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/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 h1:SGH10hXpBJhhTlObuZzTuFn1rrdmjQImITXnZVPSodc=
github.com/cevatbarisyilmaz/ara v0.0.4/go.mod h1:BfFOxnUd6Mj6xmcvRxHN3Sr21Z1T3U2MYkYOmoQe4Ts= 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 h1:z0uK8UQqjMVYzvk4tiiu3obv2B44+XBsvgEJREQfnO8=
github.com/chilts/sid v0.0.0-20190607042430-660e94789ec9/go.mod h1:Jl2neWsQaDanWORdqZ4emBl50J4/aRBBS4FyyG9/PFo= 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= 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/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.0.0/go.mod h1:hNIlj7HEI86fIcpObd7a0FcrxTWetlwJDGcceTlRvqc=
github.com/mitchellh/cli v1.1.0/go.mod h1:xcISNoH86gajksDmfB23e/pu+B+GeFRMYmoHXxx3xhI= 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 h1:lukF9ziXFxDFPkA1vsr5zpc1XuPDn/wFntq5mG+4E0Y=
github.com/mitchellh/go-homedir v1.1.0/go.mod h1:SfyaCUpYCn1Vlf4IUYiD9fPX4A5wJrkLzIz1N1q0pr0= github.com/mitchellh/go-homedir v1.1.0/go.mod h1:SfyaCUpYCn1Vlf4IUYiD9fPX4A5wJrkLzIz1N1q0pr0=
github.com/mitchellh/go-wordwrap v1.0.0/go.mod h1:ZXFpozHsX6DPmq2I0TCekCxypsnAUbP2oI0UX1GXzOo= 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/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 h1:SxziR8msSOElPayZNFfQw4Tjx/Sbaeeh3eRvrHVMUs4=
github.com/rfjakob/eme v1.1.2/go.mod h1:cVvpasglm/G3ngEfcfT/Wt0GwhkuO32pf/poW6Nyk1k= 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.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 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ=
github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc= 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/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 h1:Rvi+3BFHES3A8meP33VPAxiBZX/Aws5RxrschYGjomw=
github.com/samber/lo v1.52.0/go.mod h1:4+MXEGsJzbKGaUEQFKBq2xtfuznW9oz/WrgyzMzRoM0= 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 h1:nn5Wsu0esKSJiIVhscUtVbo7ada43DJhG55ua/hjS5I=
github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg65j358z/aeFdxmN0P9QXhEzd20vsDc= 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= github.com/sergi/go-diff v1.0.0/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=

View File

@@ -6,9 +6,11 @@ import (
"encoding/hex" "encoding/hex"
"fmt" "fmt"
"io" "io"
"time"
"filippo.io/age" "filippo.io/age"
"sneak.berlin/go/vaultik/internal/blobgen" "sneak.berlin/go/vaultik/internal/blobgen"
"sneak.berlin/go/vaultik/internal/log"
) )
// hashVerifyReader wraps a blobgen.Reader and verifies the double-SHA-256 hash // 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. // 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) { 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) blobPath := fmt.Sprintf("blobs/%s/%s/%s", blobHash[:2], blobHash[2:4], blobHash)
t0 := time.Now()
rc, err := v.Storage.Get(ctx, blobPath) rc, err := v.Storage.Get(ctx, blobPath)
getDur := time.Since(t0)
if err != nil { if err != nil {
return nil, 0, fmt.Errorf("downloading blob %s: %w", blobHash[:16], err) return nil, 0, fmt.Errorf("downloading blob %s: %w", blobHash[:16], err)
} }
t0 = time.Now()
info, err := v.Storage.Stat(ctx, blobPath) info, err := v.Storage.Stat(ctx, blobPath)
statDur := time.Since(t0)
if err != nil { if err != nil {
_ = rc.Close() _ = rc.Close()
return nil, 0, fmt.Errorf("stat blob %s: %w", blobHash[:16], err) 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 return rc, info.Size, nil
} }

View File

@@ -14,22 +14,13 @@ import (
"filippo.io/age" "filippo.io/age"
"github.com/dustin/go-humanize" "github.com/dustin/go-humanize"
"github.com/schollz/progressbar/v3"
"github.com/spf13/afero" "github.com/spf13/afero"
"golang.org/x/term"
"sneak.berlin/go/vaultik/internal/blobgen" "sneak.berlin/go/vaultik/internal/blobgen"
"sneak.berlin/go/vaultik/internal/database" "sneak.berlin/go/vaultik/internal/database"
"sneak.berlin/go/vaultik/internal/log" "sneak.berlin/go/vaultik/internal/log"
"sneak.berlin/go/vaultik/internal/types" "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 // RestoreOptions contains options for the restore operation
type RestoreOptions struct { type RestoreOptions struct {
SnapshotID string SnapshotID string
@@ -193,14 +184,21 @@ func (v *Vaultik) restoreAllFiles(
// are all already restored. // are all already restored.
sweeper := newRestoreSweeper(v.ctx, repos, blobCache, v.Config.BlobSizeLimit.Int64()/100) 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 var totalBytesExpected int64
for _, file := range files { for _, file := range files {
totalBytesExpected += file.Size totalBytesExpected += file.Size
} }
// Create progress bar if output is a terminal v.UI.Begin("Restoring %s files (%s) to %s.",
bar := v.newProgressBar("Restoring", totalBytesExpected) 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 { for i, file := range files {
if v.ctx.Err() != nil { 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) v.UI.Error("Failed to restore %s: %v. Skipping (--skip-errors).", v.UI.Path(file.Path.String()), err)
result.FilesFailed++ result.FilesFailed++
result.FailedFiles = append(result.FailedFiles, file.Path.String()) result.FailedFiles = append(result.FailedFiles, file.Path.String())
// Update progress bar even on failure
if bar != nil {
_ = bar.Add64(file.Size)
}
continue continue
} }
@@ -226,12 +220,12 @@ func (v *Vaultik) restoreAllFiles(
// all referencing files are done. // all referencing files are done.
sweeper.fileRestored(file.ID.String()) sweeper.fileRestored(file.ID.String())
// Update progress bar if time.Since(lastStatusTime) >= statusInterval {
if bar != nil { v.printRestoreProgress(i+1, len(files), result.BytesRestored, totalBytesExpected, startTime)
_ = bar.Add64(file.Size) 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) { if (i+1)%100 == 0 || i+1 == len(files) {
log.Info("Restore progress", log.Info("Restore progress",
"files", fmt.Sprintf("%d/%d", i+1, len(files)), "files", fmt.Sprintf("%d/%d", i+1, len(files)),
@@ -240,11 +234,47 @@ func (v *Vaultik) restoreAllFiles(
} }
} }
if bar != nil { return result, nil
_ = bar.Finish() }
// 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 // handleRestoreVerification runs post-restore verification if requested
@@ -259,17 +289,17 @@ func (v *Vaultik) handleRestoreVerification(
} }
if result.FilesFailed > 0 { 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 { 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) return fmt.Errorf("%d files failed verification", result.FilesFailed)
} }
v.printfStdout("Verified %d files (%s)\n", v.UI.Complete("Verified %s files (%s).",
result.FilesVerified, v.UI.Count(result.FilesVerified),
humanize.Bytes(uint64(result.BytesVerified)), v.UI.Size(result.BytesVerified))
)
return nil return nil
} }
@@ -491,21 +521,38 @@ func (v *Vaultik) restoreRegularFile(
sweeper *restoreSweeper, sweeper *restoreSweeper,
result *RestoreResult, result *RestoreResult,
) error { ) error {
fileStart := time.Now()
// Get file chunks in order // Get file chunks in order
t0 := time.Now()
fileChunks, err := repos.FileChunks.GetByFileID(ctx, file.ID) fileChunks, err := repos.FileChunks.GetByFileID(ctx, file.ID)
fileChunksQueryDur := time.Since(t0)
if err != nil { if err != nil {
return fmt.Errorf("getting file chunks: %w", err) return fmt.Errorf("getting file chunks: %w", err)
} }
// Create output file // Create output file
t0 = time.Now()
outFile, err := v.Fs.Create(targetPath) outFile, err := v.Fs.Create(targetPath)
createDur := time.Since(t0)
if err != nil { if err != nil {
return fmt.Errorf("creating output file: %w", err) return fmt.Errorf("creating output file: %w", err)
} }
defer func() { _ = outFile.Close() }() defer func() { _ = outFile.Close() }()
// Write chunks in order // Per-file timing buckets so --debug shows exactly where seconds go.
var bytesWritten int64 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 { for _, fc := range fileChunks {
// Find which blob contains this chunk // Find which blob contains this chunk
chunkHashStr := fc.ChunkHash.String() chunkHashStr := fc.ChunkHash.String()
@@ -514,25 +561,36 @@ func (v *Vaultik) restoreRegularFile(
return fmt.Errorf("chunk %s not found in any blob", chunkHashStr[:16]) 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()) blob, err := repos.Blobs.GetByID(ctx, blobChunk.BlobID.String())
blobDBLookupDur += time.Since(t0)
if err != nil { if err != nil {
return fmt.Errorf("getting blob %s: %w", blobChunk.BlobID, err) return fmt.Errorf("getting blob %s: %w", blobChunk.BlobID, err)
} }
// Download and decrypt blob if not cached // Download and decrypt blob if not cached
blobHashStr := blob.Hash.String() blobHashStr := blob.Hash.String()
t0 = time.Now()
blobData, ok := blobCache.Get(blobHashStr) blobData, ok := blobCache.Get(blobHashStr)
cacheGetDur += time.Since(t0)
if !ok { if !ok {
t0 = time.Now()
blobData, err = v.downloadBlob(ctx, blobHashStr, blob.CompressedSize, identity) blobData, err = v.downloadBlob(ctx, blobHashStr, blob.CompressedSize, identity)
downloadDur += time.Since(t0)
if err != nil { if err != nil {
return fmt.Errorf("downloading blob %s: %w", blobHashStr[:16], err) return fmt.Errorf("downloading blob %s: %w", blobHashStr[:16], err)
} }
t0 = time.Now()
if putErr := blobCache.Put(blobHashStr, blobData); putErr != nil { if putErr := blobCache.Put(blobHashStr, blobData); putErr != nil {
log.Debug("Failed to cache blob on disk", "hash", blobHashStr[:16], "error", putErr) log.Debug("Failed to cache blob on disk", "hash", blobHashStr[:16], "error", putErr)
} }
cachePutDur += time.Since(t0)
downloadCount++
result.BlobsDownloaded++ result.BlobsDownloaded++
result.BytesDownloaded += blob.CompressedSize result.BytesDownloaded += blob.CompressedSize
} else {
cacheHitCount++
} }
// Extract chunk from blob // Extract chunk from blob
@@ -543,7 +601,9 @@ func (v *Vaultik) restoreRegularFile(
chunkData := blobData[blobChunk.Offset : blobChunk.Offset+blobChunk.Length] chunkData := blobData[blobChunk.Offset : blobChunk.Offset+blobChunk.Length]
// Write chunk to output file // Write chunk to output file
t0 = time.Now()
n, err := outFile.Write(chunkData) n, err := outFile.Write(chunkData)
writeDur += time.Since(t0)
if err != nil { if err != nil {
return fmt.Errorf("writing chunk: %w", err) 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 // Tell the sweeper about the bytes we just restored so it can
// run an eviction sweep once the accumulated total crosses its // run an eviction sweep once the accumulated total crosses its
// threshold (config.BlobSizeLimit/100). // threshold (config.BlobSizeLimit/100).
t0 = time.Now()
sweeper.chunkRestored(int64(n)) 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 // Close file before setting metadata
if err := outFile.Close(); err != nil { if err := outFile.Close(); err != nil {
return fmt.Errorf("closing output file: %w", err) return fmt.Errorf("closing output file: %w", err)
@@ -585,23 +664,44 @@ func (v *Vaultik) restoreRegularFile(
return nil 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) { 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) rc, err := v.FetchAndDecryptBlob(ctx, blobHash, expectedSize, identity)
fetchSetupDur := time.Since(t0)
if err != nil { if err != nil {
return nil, err return nil, err
} }
t0 = time.Now()
data, err := io.ReadAll(rc) data, err := io.ReadAll(rc)
readAllDur := time.Since(t0)
if err != nil { if err != nil {
_ = rc.Close() _ = rc.Close()
return nil, fmt.Errorf("reading blob data: %w", err) return nil, fmt.Errorf("reading blob data: %w", err)
} }
// Close triggers hash verification // Close triggers hash verification
t0 = time.Now()
if err := rc.Close(); err != nil { if err := rc.Close(); err != nil {
return nil, err 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 return data, nil
} }
@@ -635,16 +735,16 @@ func (v *Vaultik) verifyRestoredFiles(
"files", len(regularFiles), "files", len(regularFiles),
"bytes", humanize.Bytes(uint64(totalBytes)), "bytes", humanize.Bytes(uint64(totalBytes)),
) )
v.printfStdout("\nVerifying %d files (%s)...\n", v.UI.Begin("Verifying %s files (%s).",
len(regularFiles), v.UI.Count(len(regularFiles)),
humanize.Bytes(uint64(totalBytes)), v.UI.Size(totalBytes))
)
// Create progress bar if output is a terminal startTime := time.Now()
bar := v.newProgressBar("Verifying", totalBytes) lastStatusTime := startTime
const statusInterval = 15 * time.Second
// Verify each file var bytesProcessed int64
for _, file := range regularFiles { for i, file := range regularFiles {
if ctx.Err() != nil { if ctx.Err() != nil {
return ctx.Err() return ctx.Err()
} }
@@ -659,17 +759,14 @@ func (v *Vaultik) verifyRestoredFiles(
result.FilesVerified++ result.FilesVerified++
result.BytesVerified += bytesVerified result.BytesVerified += bytesVerified
} }
bytesProcessed += file.Size
// Update progress bar if time.Since(lastStatusTime) >= statusInterval {
if bar != nil { v.printVerifyProgress(i+1, len(regularFiles), bytesProcessed, totalBytes, startTime)
_ = bar.Add64(file.Size) lastStatusTime = time.Now()
} }
} }
if bar != nil {
_ = bar.Finish()
}
log.Info("Verification complete", log.Info("Verification complete",
"files_verified", result.FilesVerified, "files_verified", result.FilesVerified,
"bytes_verified", humanize.Bytes(uint64(result.BytesVerified)), "bytes_verified", humanize.Bytes(uint64(result.BytesVerified)),
@@ -679,6 +776,46 @@ func (v *Vaultik) verifyRestoredFiles(
return nil 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 // verifyFile verifies a single restored file by checking its chunk hashes
func (v *Vaultik) verifyFile( func (v *Vaultik) verifyFile(
ctx context.Context, ctx context.Context,
@@ -734,38 +871,3 @@ func (v *Vaultik) verifyFile(
log.Debug("File verified", "path", file.Path, "bytes", bytesVerified, "chunks", len(fileChunks)) log.Debug("File verified", "path", file.Path, "bytes", bytesVerified, "chunks", len(fileChunks))
return bytesVerified, nil 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()))
}

View File

@@ -147,11 +147,6 @@ func (v *Vaultik) printlnStdout(args ...any) {
_, _ = fmt.Fprintln(v.Stdout, args...) _, _ = 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. // scanStdin reads a line of input from stdin.
func (v *Vaultik) scanStdin(a ...any) (int, error) { func (v *Vaultik) scanStdin(a ...any) (int, error) {
return fmt.Fscanln(v.Stdin, a...) return fmt.Fscanln(v.Stdin, a...)