Merge pull request #4314 from MichaelEischer/restore-json

Add JSON support for the restore progress bar

changelog/unreleased/issue-426

@@ -4,6 +4,11 @@ The `restore` command now shows a progress report while restoring files.
 
 Example: [0:42]  5.76%  23 files 12.98 MiB, total 3456 files 23.54 GiB
 
+JSON output is now also supported.
+
+https://github.com/restic/restic/issues/426
+https://github.com/restic/restic/issues/3413
 https://github.com/restic/restic/issues/3627
 https://github.com/restic/restic/pull/3991
+https://github.com/restic/restic/pull/4314
 https://forum.restic.net/t/progress-bar-for-restore/5210

cmd/restic/cmd_backup_integration_test.go

@@ -13,34 +13,19 @@ import (
 	"github.com/restic/restic/internal/restic"
 	rtest "github.com/restic/restic/internal/test"
 	"github.com/restic/restic/internal/ui/termstatus"
-	"golang.org/x/sync/errgroup"
 )
 
 func testRunBackupAssumeFailure(t testing.TB, dir string, target []string, opts BackupOptions, gopts GlobalOptions) error {
-	ctx, cancel := context.WithCancel(context.TODO())
-	defer cancel()
+	return withTermStatus(gopts, func(ctx context.Context, term *termstatus.Terminal) error {
+		t.Logf("backing up %v in %v", target, dir)
+		if dir != "" {
+			cleanup := rtest.Chdir(t, dir)
+			defer cleanup()
+		}
 
-	var wg errgroup.Group
-	term := termstatus.New(gopts.stdout, gopts.stderr, gopts.Quiet)
-	wg.Go(func() error { term.Run(ctx); return nil })
-
-	t.Logf("backing up %v in %v", target, dir)
-	if dir != "" {
-		cleanup := rtest.Chdir(t, dir)
-		defer cleanup()
-	}
-
-	opts.GroupBy = restic.SnapshotGroupByOptions{Host: true, Path: true}
-	backupErr := runBackup(ctx, opts, gopts, term, target)
-
-	cancel()
-
-	err := wg.Wait()
-	if err != nil {
-		t.Fatal(err)
-	}
-
-	return backupErr
+		opts.GroupBy = restic.SnapshotGroupByOptions{Host: true, Path: true}
+		return runBackup(ctx, opts, gopts, term, target)
+	})
 }
 
 func testRunBackup(t testing.TB, dir string, target []string, opts BackupOptions, gopts GlobalOptions) {

cmd/restic/cmd_restore.go

@@ -175,16 +175,20 @@ func runRestore(ctx context.Context, opts RestoreOptions, gopts GlobalOptions,
 		return err
 	}
 
-	var progress *restoreui.Progress
-	if !gopts.Quiet && !gopts.JSON {
-		progress = restoreui.NewProgress(restoreui.NewProgressPrinter(term), calculateProgressInterval(!gopts.Quiet, gopts.JSON))
+	msg := ui.NewMessage(term, gopts.verbosity)
+	var printer restoreui.ProgressPrinter
+	if gopts.JSON {
+		printer = restoreui.NewJSONProgress(term)
+	} else {
+		printer = restoreui.NewTextProgress(term)
 	}
 
+	progress := restoreui.NewProgress(printer, calculateProgressInterval(!gopts.Quiet, gopts.JSON))
 	res := restorer.NewRestorer(repo, sn, opts.Sparse, progress)
 
 	totalErrors := 0
 	res.Error = func(location string, err error) error {
-		Warnf("ignoring error for %s: %s\n", location, err)
+		msg.E("ignoring error for %s: %s\n", location, err)
 		totalErrors++
 		return nil
 	}
@@ -194,12 +198,12 @@ func runRestore(ctx context.Context, opts RestoreOptions, gopts GlobalOptions,
 	selectExcludeFilter := func(item string, dstpath string, node *restic.Node) (selectedForRestore bool, childMayBeSelected bool) {
 		matched, err := filter.List(excludePatterns, item)
 		if err != nil {
-			Warnf("error for exclude pattern: %v", err)
+			msg.E("error for exclude pattern: %v", err)
 		}
 
 		matchedInsensitive, err := filter.List(insensitiveExcludePatterns, strings.ToLower(item))
 		if err != nil {
-			Warnf("error for iexclude pattern: %v", err)
+			msg.E("error for iexclude pattern: %v", err)
 		}
 
 		// An exclude filter is basically a 'wildcard but foo',
@@ -217,12 +221,12 @@ func runRestore(ctx context.Context, opts RestoreOptions, gopts GlobalOptions,
 	selectIncludeFilter := func(item string, dstpath string, node *restic.Node) (selectedForRestore bool, childMayBeSelected bool) {
 		matched, childMayMatch, err := filter.ListWithChild(includePatterns, item)
 		if err != nil {
-			Warnf("error for include pattern: %v", err)
+			msg.E("error for include pattern: %v", err)
 		}
 
 		matchedInsensitive, childMayMatchInsensitive, err := filter.ListWithChild(insensitiveIncludePatterns, strings.ToLower(item))
 		if err != nil {
-			Warnf("error for iexclude pattern: %v", err)
+			msg.E("error for iexclude pattern: %v", err)
 		}
 
 		selectedForRestore = matched || matchedInsensitive
@@ -237,23 +241,25 @@ func runRestore(ctx context.Context, opts RestoreOptions, gopts GlobalOptions,
 		res.SelectFilter = selectIncludeFilter
 	}
 
-	Verbosef("restoring %s to %s\n", res.Snapshot(), opts.Target)
+	if !gopts.JSON {
+		msg.P("restoring %s to %s\n", res.Snapshot(), opts.Target)
+	}
 
 	err = res.RestoreTo(ctx, opts.Target)
 	if err != nil {
 		return err
 	}
 
-	if progress != nil {
-		progress.Finish()
-	}
+	progress.Finish()
 
 	if totalErrors > 0 {
 		return errors.Fatalf("There were %d errors\n", totalErrors)
 	}
 
 	if opts.Verify {
-		Verbosef("verifying files in %s\n", opts.Target)
+		if !gopts.JSON {
+			msg.P("verifying files in %s\n", opts.Target)
+		}
 		var count int
 		t0 := time.Now()
 		count, err = res.VerifyFiles(ctx, opts.Target)
@@ -263,8 +269,11 @@ func runRestore(ctx context.Context, opts RestoreOptions, gopts GlobalOptions,
 		if totalErrors > 0 {
 			return errors.Fatalf("There were %d errors\n", totalErrors)
 		}
-		Verbosef("finished verifying %d files in %s (took %s)\n", count, opts.Target,
-			time.Since(t0).Round(time.Millisecond))
+
+		if !gopts.JSON {
+			msg.P("finished verifying %d files in %s (took %s)\n", count, opts.Target,
+				time.Since(t0).Round(time.Millisecond))
+		}
 	}
 
 	return nil

cmd/restic/cmd_restore_integration_test.go

@@ -14,6 +14,7 @@ import (
 	"github.com/restic/restic/internal/filter"
 	"github.com/restic/restic/internal/restic"
 	rtest "github.com/restic/restic/internal/test"
+	"github.com/restic/restic/internal/ui/termstatus"
 )
 
 func testRunRestore(t testing.TB, opts GlobalOptions, dir string, snapshotID restic.ID) {
@@ -26,11 +27,13 @@ func testRunRestoreExcludes(t testing.TB, gopts GlobalOptions, dir string, snaps
 		Exclude: excludes,
 	}
 
-	rtest.OK(t, runRestore(context.TODO(), opts, gopts, nil, []string{snapshotID.String()}))
+	rtest.OK(t, testRunRestoreAssumeFailure(snapshotID.String(), opts, gopts))
 }
 
 func testRunRestoreAssumeFailure(snapshotID string, opts RestoreOptions, gopts GlobalOptions) error {
-	return runRestore(context.TODO(), opts, gopts, nil, []string{snapshotID})
+	return withTermStatus(gopts, func(ctx context.Context, term *termstatus.Terminal) error {
+		return runRestore(ctx, opts, gopts, term, []string{snapshotID})
+	})
 }
 
 func testRunRestoreLatest(t testing.TB, gopts GlobalOptions, dir string, paths []string, hosts []string) {
@@ -42,7 +45,7 @@ func testRunRestoreLatest(t testing.TB, gopts GlobalOptions, dir string, paths [
 		},
 	}
 
-	rtest.OK(t, runRestore(context.TODO(), opts, gopts, nil, []string{"latest"}))
+	rtest.OK(t, testRunRestoreAssumeFailure("latest", opts, gopts))
 }
 
 func testRunRestoreIncludes(t testing.TB, gopts GlobalOptions, dir string, snapshotID restic.ID, includes []string) {
@@ -51,7 +54,7 @@ func testRunRestoreIncludes(t testing.TB, gopts GlobalOptions, dir string, snaps
 		Include: includes,
 	}
 
-	rtest.OK(t, runRestore(context.TODO(), opts, gopts, nil, []string{snapshotID.String()}))
+	rtest.OK(t, testRunRestoreAssumeFailure(snapshotID.String(), opts, gopts))
 }
 
 func TestRestoreFilter(t *testing.T) {

cmd/restic/integration_helpers_test.go

@@ -9,6 +9,7 @@ import (
 	"os"
 	"path/filepath"
 	"runtime"
+	"sync"
 	"testing"
 
 	"github.com/restic/restic/internal/backend/retry"
@@ -17,6 +18,7 @@ import (
 	"github.com/restic/restic/internal/repository"
 	"github.com/restic/restic/internal/restic"
 	rtest "github.com/restic/restic/internal/test"
+	"github.com/restic/restic/internal/ui/termstatus"
 )
 
 type dirEntry struct {
@@ -356,3 +358,20 @@ func withCaptureStdout(inner func() error) (*bytes.Buffer, error) {
 
 	return buf, err
 }
+
+func withTermStatus(gopts GlobalOptions, callback func(ctx context.Context, term *termstatus.Terminal) error) error {
+	ctx, cancel := context.WithCancel(context.TODO())
+	var wg sync.WaitGroup
+
+	term := termstatus.New(gopts.stdout, gopts.stderr, gopts.Quiet)
+	wg.Add(1)
+	go func() {
+		defer wg.Done()
+		term.Run(ctx)
+	}()
+
+	defer wg.Wait()
+	defer cancel()
+
+	return callback(ctx, term)
+}

internal/ui/backup/json.go

@@ -1,8 +1,6 @@
 package backup
 
 import (
-	"bytes"
-	"encoding/json"
 	"sort"
 	"time"
 
@@ -32,21 +30,12 @@ func NewJSONProgress(term *termstatus.Terminal, verbosity uint) *JSONProgress {
 	}
 }
 
-func toJSONString(status interface{}) string {
-	buf := new(bytes.Buffer)
-	err := json.NewEncoder(buf).Encode(status)
-	if err != nil {
-		panic(err)
-	}
-	return buf.String()
-}
-
 func (b *JSONProgress) print(status interface{}) {
-	b.term.Print(toJSONString(status))
+	b.term.Print(ui.ToJSONString(status))
 }
 
 func (b *JSONProgress) error(status interface{}) {
-	b.term.Error(toJSONString(status))
+	b.term.Error(ui.ToJSONString(status))
 }
 
 // Update updates the status lines.

internal/ui/format.go

@@ -1,6 +1,8 @@
 package ui
 
 import (
+	"bytes"
+	"encoding/json"
 	"fmt"
 	"time"
 )
@@ -53,3 +55,12 @@ func FormatSeconds(sec uint64) string {
 	}
 	return fmt.Sprintf("%d:%02d", min, sec)
 }
+
+func ToJSONString(status interface{}) string {
+	buf := new(bytes.Buffer)
+	err := json.NewEncoder(buf).Encode(status)
+	if err != nil {
+		panic(err)
+	}
+	return buf.String()
+}

internal/ui/restore/json.go

@@ -0,0 +1,69 @@
+package restore
+
+import (
+	"time"
+
+	"github.com/restic/restic/internal/ui"
+)
+
+type jsonPrinter struct {
+	terminal term
+}
+
+func NewJSONProgress(terminal term) ProgressPrinter {
+	return &jsonPrinter{
+		terminal: terminal,
+	}
+}
+
+func (t *jsonPrinter) print(status interface{}) {
+	t.terminal.Print(ui.ToJSONString(status))
+}
+
+func (t *jsonPrinter) Update(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration) {
+	status := statusUpdate{
+		MessageType:    "status",
+		SecondsElapsed: uint64(duration / time.Second),
+		TotalFiles:     filesTotal,
+		FilesRestored:  filesFinished,
+		TotalBytes:     allBytesTotal,
+		BytesRestored:  allBytesWritten,
+	}
+
+	if allBytesTotal > 0 {
+		status.PercentDone = float64(allBytesWritten) / float64(allBytesTotal)
+	}
+
+	t.print(status)
+}
+
+func (t *jsonPrinter) Finish(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration) {
+	status := summaryOutput{
+		MessageType:    "summary",
+		SecondsElapsed: uint64(duration / time.Second),
+		TotalFiles:     filesTotal,
+		FilesRestored:  filesFinished,
+		TotalBytes:     allBytesTotal,
+		BytesRestored:  allBytesWritten,
+	}
+	t.print(status)
+}
+
+type statusUpdate struct {
+	MessageType    string  `json:"message_type"` // "status"
+	SecondsElapsed uint64  `json:"seconds_elapsed,omitempty"`
+	PercentDone    float64 `json:"percent_done"`
+	TotalFiles     uint64  `json:"total_files,omitempty"`
+	FilesRestored  uint64  `json:"files_restored,omitempty"`
+	TotalBytes     uint64  `json:"total_bytes,omitempty"`
+	BytesRestored  uint64  `json:"bytes_restored,omitempty"`
+}
+
+type summaryOutput struct {
+	MessageType    string `json:"message_type"` // "summary"
+	SecondsElapsed uint64 `json:"seconds_elapsed,omitempty"`
+	TotalFiles     uint64 `json:"total_files,omitempty"`
+	FilesRestored  uint64 `json:"files_restored,omitempty"`
+	TotalBytes     uint64 `json:"total_bytes,omitempty"`
+	BytesRestored  uint64 `json:"bytes_restored,omitempty"`
+}

internal/ui/restore/json_test.go

@@ -0,0 +1,29 @@
+package restore
+
+import (
+	"testing"
+	"time"
+
+	"github.com/restic/restic/internal/test"
+)
+
+func TestJSONPrintUpdate(t *testing.T) {
+	term := &mockTerm{}
+	printer := NewJSONProgress(term)
+	printer.Update(3, 11, 29, 47, 5*time.Second)
+	test.Equals(t, []string{"{\"message_type\":\"status\",\"seconds_elapsed\":5,\"percent_done\":0.6170212765957447,\"total_files\":11,\"files_restored\":3,\"total_bytes\":47,\"bytes_restored\":29}\n"}, term.output)
+}
+
+func TestJSONPrintSummaryOnSuccess(t *testing.T) {
+	term := &mockTerm{}
+	printer := NewJSONProgress(term)
+	printer.Finish(11, 11, 47, 47, 5*time.Second)
+	test.Equals(t, []string{"{\"message_type\":\"summary\",\"seconds_elapsed\":5,\"total_files\":11,\"files_restored\":11,\"total_bytes\":47,\"bytes_restored\":47}\n"}, term.output)
+}
+
+func TestJSONPrintSummaryOnErrors(t *testing.T) {
+	term := &mockTerm{}
+	printer := NewJSONProgress(term)
+	printer.Finish(3, 11, 29, 47, 5*time.Second)
+	test.Equals(t, []string{"{\"message_type\":\"summary\",\"seconds_elapsed\":5,\"total_files\":11,\"files_restored\":3,\"total_bytes\":47,\"bytes_restored\":29}\n"}, term.output)
+}

internal/ui/restore/progress.go

@@ -1,11 +1,9 @@
 package restore
 
 import (
-	"fmt"
 	"sync"
 	"time"
 
-	"github.com/restic/restic/internal/ui"
 	"github.com/restic/restic/internal/ui/progress"
 )
 
@@ -28,6 +26,11 @@ type progressInfoEntry struct {
 	bytesTotal   uint64
 }
 
+type term interface {
+	Print(line string)
+	SetStatus(lines []string)
+}
+
 type ProgressPrinter interface {
 	Update(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration)
 	Finish(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration)
@@ -85,47 +88,3 @@ func (p *Progress) AddProgress(name string, bytesWrittenPortion uint64, bytesTot
 func (p *Progress) Finish() {
 	p.updater.Done()
 }
-
-type term interface {
-	Print(line string)
-	SetStatus(lines []string)
-}
-
-type textPrinter struct {
-	terminal term
-}
-
-func NewProgressPrinter(terminal term) ProgressPrinter {
-	return &textPrinter{
-		terminal: terminal,
-	}
-}
-
-func (t *textPrinter) Update(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration) {
-	timeLeft := ui.FormatDuration(duration)
-	formattedAllBytesWritten := ui.FormatBytes(allBytesWritten)
-	formattedAllBytesTotal := ui.FormatBytes(allBytesTotal)
-	allPercent := ui.FormatPercent(allBytesWritten, allBytesTotal)
-	progress := fmt.Sprintf("[%s] %s  %v files %s, total %v files %v",
-		timeLeft, allPercent, filesFinished, formattedAllBytesWritten, filesTotal, formattedAllBytesTotal)
-
-	t.terminal.SetStatus([]string{progress})
-}
-
-func (t *textPrinter) Finish(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration) {
-	t.terminal.SetStatus([]string{})
-
-	timeLeft := ui.FormatDuration(duration)
-	formattedAllBytesTotal := ui.FormatBytes(allBytesTotal)
-
-	var summary string
-	if filesFinished == filesTotal && allBytesWritten == allBytesTotal {
-		summary = fmt.Sprintf("Summary: Restored %d Files (%s) in %s", filesTotal, formattedAllBytesTotal, timeLeft)
-	} else {
-		formattedAllBytesWritten := ui.FormatBytes(allBytesWritten)
-		summary = fmt.Sprintf("Summary: Restored %d / %d Files (%s / %s) in %s",
-			filesFinished, filesTotal, formattedAllBytesWritten, formattedAllBytesTotal, timeLeft)
-	}
-
-	t.terminal.Print(summary)
-}

internal/ui/restore/progress_test.go

@@ -135,36 +135,3 @@ func TestSummaryOnErrors(t *testing.T) {
 		printerTraceEntry{1, 2, 50 + fileSize/2, 50 + fileSize, mockFinishDuration, true},
 	}, result)
 }
-
-type mockTerm struct {
-	output []string
-}
-
-func (m *mockTerm) Print(line string) {
-	m.output = append(m.output, line)
-}
-
-func (m *mockTerm) SetStatus(lines []string) {
-	m.output = append([]string{}, lines...)
-}
-
-func TestPrintUpdate(t *testing.T) {
-	term := &mockTerm{}
-	printer := NewProgressPrinter(term)
-	printer.Update(3, 11, 29, 47, 5*time.Second)
-	test.Equals(t, []string{"[0:05] 61.70%  3 files 29 B, total 11 files 47 B"}, term.output)
-}
-
-func TestPrintSummaryOnSuccess(t *testing.T) {
-	term := &mockTerm{}
-	printer := NewProgressPrinter(term)
-	printer.Finish(11, 11, 47, 47, 5*time.Second)
-	test.Equals(t, []string{"Summary: Restored 11 Files (47 B) in 0:05"}, term.output)
-}
-
-func TestPrintSummaryOnErrors(t *testing.T) {
-	term := &mockTerm{}
-	printer := NewProgressPrinter(term)
-	printer.Finish(3, 11, 29, 47, 5*time.Second)
-	test.Equals(t, []string{"Summary: Restored 3 / 11 Files (29 B / 47 B) in 0:05"}, term.output)
-}

internal/ui/restore/text.go

@@ -0,0 +1,47 @@
+package restore
+
+import (
+	"fmt"
+	"time"
+
+	"github.com/restic/restic/internal/ui"
+)
+
+type textPrinter struct {
+	terminal term
+}
+
+func NewTextProgress(terminal term) ProgressPrinter {
+	return &textPrinter{
+		terminal: terminal,
+	}
+}
+
+func (t *textPrinter) Update(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration) {
+	timeLeft := ui.FormatDuration(duration)
+	formattedAllBytesWritten := ui.FormatBytes(allBytesWritten)
+	formattedAllBytesTotal := ui.FormatBytes(allBytesTotal)
+	allPercent := ui.FormatPercent(allBytesWritten, allBytesTotal)
+	progress := fmt.Sprintf("[%s] %s  %v files %s, total %v files %v",
+		timeLeft, allPercent, filesFinished, formattedAllBytesWritten, filesTotal, formattedAllBytesTotal)
+
+	t.terminal.SetStatus([]string{progress})
+}
+
+func (t *textPrinter) Finish(filesFinished, filesTotal, allBytesWritten, allBytesTotal uint64, duration time.Duration) {
+	t.terminal.SetStatus([]string{})
+
+	timeLeft := ui.FormatDuration(duration)
+	formattedAllBytesTotal := ui.FormatBytes(allBytesTotal)
+
+	var summary string
+	if filesFinished == filesTotal && allBytesWritten == allBytesTotal {
+		summary = fmt.Sprintf("Summary: Restored %d Files (%s) in %s", filesTotal, formattedAllBytesTotal, timeLeft)
+	} else {
+		formattedAllBytesWritten := ui.FormatBytes(allBytesWritten)
+		summary = fmt.Sprintf("Summary: Restored %d / %d Files (%s / %s) in %s",
+			filesFinished, filesTotal, formattedAllBytesWritten, formattedAllBytesTotal, timeLeft)
+	}
+
+	t.terminal.Print(summary)
+}

internal/ui/restore/text_test.go

@@ -0,0 +1,41 @@
+package restore
+
+import (
+	"testing"
+	"time"
+
+	"github.com/restic/restic/internal/test"
+)
+
+type mockTerm struct {
+	output []string
+}
+
+func (m *mockTerm) Print(line string) {
+	m.output = append(m.output, line)
+}
+
+func (m *mockTerm) SetStatus(lines []string) {
+	m.output = append([]string{}, lines...)
+}
+
+func TestPrintUpdate(t *testing.T) {
+	term := &mockTerm{}
+	printer := NewTextProgress(term)
+	printer.Update(3, 11, 29, 47, 5*time.Second)
+	test.Equals(t, []string{"[0:05] 61.70%  3 files 29 B, total 11 files 47 B"}, term.output)
+}
+
+func TestPrintSummaryOnSuccess(t *testing.T) {
+	term := &mockTerm{}
+	printer := NewTextProgress(term)
+	printer.Finish(11, 11, 47, 47, 5*time.Second)
+	test.Equals(t, []string{"Summary: Restored 11 Files (47 B) in 0:05"}, term.output)
+}
+
+func TestPrintSummaryOnErrors(t *testing.T) {
+	term := &mockTerm{}
+	printer := NewTextProgress(term)
+	printer.Finish(3, 11, 29, 47, 5*time.Second)
+	test.Equals(t, []string{"Summary: Restored 3 / 11 Files (29 B / 47 B) in 0:05"}, term.output)
+}