restore: print JSON versions of errors in --json mode

Previously, they were printed as freeform text.

This also adds a ui.Terminal interface to make writing
tests easier and also adds a few tests.
This commit is contained in:
Michael Terry 2024-07-27 19:06:26 -04:00
parent ad2585af67
commit a376323331
17 changed files with 234 additions and 70 deletions

View file

@ -0,0 +1,8 @@
Enhancement: Print JSON-formatted errors during `restore --json`
Restic printed any restore errors directly to the console as freeform
text messages, even with `--json`. Restic now prints them as JSON formatted
messages when `--json` is passed.
https://github.com/restic/restic/issues/4944
https://github.com/restic/restic/pull/4946

View file

@ -0,0 +1,8 @@
Bugfix: Include missing backup error text with `--json`
Restic was not actually providing the text of an error message during
backup if `--json` was passed, instead only printing `"error": {}`.
Restic now includes the error text in JSON output.
https://github.com/restic/restic/issues/4945
https://github.com/restic/restic/pull/4946

View file

@ -164,9 +164,8 @@ func runRestore(ctx context.Context, opts RestoreOptions, gopts GlobalOptions,
totalErrors := 0
res.Error = func(location string, err error) error {
msg.E("ignoring error for %s: %s\n", location, err)
totalErrors++
return nil
return progress.Error(location, err)
}
res.Warn = func(message string) {
msg.E("Warning: %s\n", message)

View file

@ -989,6 +989,9 @@ type printerMock struct {
func (p *printerMock) Update(_ restoreui.State, _ time.Duration) {
}
func (p *printerMock) Error(item string, err error) error {
return nil
}
func (p *printerMock) CompleteItem(action restoreui.ItemAction, item string, size uint64) {
}
func (p *printerMock) Finish(s restoreui.State, _ time.Duration) {

View file

@ -7,14 +7,13 @@ import (
"github.com/restic/restic/internal/archiver"
"github.com/restic/restic/internal/restic"
"github.com/restic/restic/internal/ui"
"github.com/restic/restic/internal/ui/termstatus"
)
// JSONProgress reports progress for the `backup` command in JSON.
type JSONProgress struct {
*ui.Message
term *termstatus.Terminal
term ui.Terminal
v uint
}
@ -22,7 +21,7 @@ type JSONProgress struct {
var _ ProgressPrinter = &JSONProgress{}
// NewJSONProgress returns a new backup progress reporter.
func NewJSONProgress(term *termstatus.Terminal, verbosity uint) *JSONProgress {
func NewJSONProgress(term ui.Terminal, verbosity uint) *JSONProgress {
return &JSONProgress{
Message: ui.NewMessage(term, verbosity),
term: term,

View file

@ -0,0 +1,27 @@
package backup
import (
"testing"
"github.com/restic/restic/internal/errors"
"github.com/restic/restic/internal/test"
"github.com/restic/restic/internal/ui"
)
func createJSONProgress() (*ui.MockTerminal, ProgressPrinter) {
term := &ui.MockTerminal{}
printer := NewJSONProgress(term, 3)
return term, printer
}
func TestJSONError(t *testing.T) {
term, printer := createJSONProgress()
test.Equals(t, printer.Error("/path", errors.New("error \"message\"")), nil)
test.Equals(t, []string{"{\"message_type\":\"error\",\"error\":\"error \\\"message\\\"\",\"during\":\"archival\",\"item\":\"/path\"}\n"}, term.Errors)
}
func TestJSONScannerError(t *testing.T) {
term, printer := createJSONProgress()
test.Equals(t, printer.ScannerError("/path", errors.New("error \"message\"")), nil)
test.Equals(t, []string{"{\"message_type\":\"error\",\"error\":\"error \\\"message\\\"\",\"during\":\"scan\",\"item\":\"/path\"}\n"}, term.Errors)
}

View file

@ -15,7 +15,7 @@ import (
type TextProgress struct {
*ui.Message
term *termstatus.Terminal
term ui.Terminal
verbosity uint
}
@ -23,7 +23,7 @@ type TextProgress struct {
var _ ProgressPrinter = &TextProgress{}
// NewTextProgress returns a new backup progress reporter.
func NewTextProgress(term *termstatus.Terminal, verbosity uint) *TextProgress {
func NewTextProgress(term ui.Terminal, verbosity uint) *TextProgress {
return &TextProgress{
Message: ui.NewMessage(term, verbosity),
term: term,

View file

@ -0,0 +1,27 @@
package backup
import (
"testing"
"github.com/restic/restic/internal/errors"
"github.com/restic/restic/internal/test"
"github.com/restic/restic/internal/ui"
)
func createTextProgress() (*ui.MockTerminal, ProgressPrinter) {
term := &ui.MockTerminal{}
printer := NewTextProgress(term, 3)
return term, printer
}
func TestError(t *testing.T) {
term, printer := createTextProgress()
test.Equals(t, printer.Error("/path", errors.New("error \"message\"")), nil)
test.Equals(t, []string{"error: error \"message\"\n"}, term.Errors)
}
func TestScannerError(t *testing.T) {
term, printer := createTextProgress()
test.Equals(t, printer.ScannerError("/path", errors.New("error \"message\"")), nil)
test.Equals(t, []string{"scan: error \"message\"\n"}, term.Errors)
}

View file

@ -2,19 +2,17 @@ package ui
import (
"fmt"
"github.com/restic/restic/internal/ui/termstatus"
)
// Message reports progress with messages of different verbosity.
type Message struct {
term *termstatus.Terminal
term Terminal
v uint
}
// NewMessage returns a message progress reporter with underlying terminal
// term.
func NewMessage(term *termstatus.Terminal, verbosity uint) *Message {
func NewMessage(term Terminal, verbosity uint) *Message {
return &Message{
term: term,
v: verbosity,

22
internal/ui/mock.go Normal file
View file

@ -0,0 +1,22 @@
package ui
type MockTerminal struct {
Output []string
Errors []string
}
func (m *MockTerminal) Print(line string) {
m.Output = append(m.Output, line)
}
func (m *MockTerminal) Error(line string) {
m.Errors = append(m.Errors, line)
}
func (m *MockTerminal) SetStatus(lines []string) {
m.Output = append([]string{}, lines...)
}
func (m *MockTerminal) CanUpdateStatus() bool {
return true
}

View file

@ -7,11 +7,11 @@ import (
)
type jsonPrinter struct {
terminal term
terminal ui.Terminal
verbosity uint
}
func NewJSONProgress(terminal term, verbosity uint) ProgressPrinter {
func NewJSONProgress(terminal ui.Terminal, verbosity uint) ProgressPrinter {
return &jsonPrinter{
terminal: terminal,
verbosity: verbosity,
@ -22,6 +22,10 @@ func (t *jsonPrinter) print(status interface{}) {
t.terminal.Print(ui.ToJSONString(status))
}
func (t *jsonPrinter) error(status interface{}) {
t.terminal.Error(ui.ToJSONString(status))
}
func (t *jsonPrinter) Update(p State, duration time.Duration) {
status := statusUpdate{
MessageType: "status",
@ -41,6 +45,16 @@ func (t *jsonPrinter) Update(p State, duration time.Duration) {
t.print(status)
}
func (t *jsonPrinter) Error(item string, err error) error {
t.error(errorUpdate{
MessageType: "error",
Error: err.Error(),
During: "restore",
Item: item,
})
return nil
}
func (t *jsonPrinter) CompleteItem(messageType ItemAction, item string, size uint64) {
if t.verbosity < 3 {
return
@ -99,6 +113,13 @@ type statusUpdate struct {
BytesSkipped uint64 `json:"bytes_skipped,omitempty"`
}
type errorUpdate struct {
MessageType string `json:"message_type"` // "error"
Error string `json:"error"`
During string `json:"during"`
Item string `json:"item"`
}
type verboseUpdate struct {
MessageType string `json:"message_type"` // "verbose_status"
Action string `json:"action"`

View file

@ -4,11 +4,13 @@ import (
"testing"
"time"
"github.com/restic/restic/internal/errors"
"github.com/restic/restic/internal/test"
"github.com/restic/restic/internal/ui"
)
func createJSONProgress() (*mockTerm, ProgressPrinter) {
term := &mockTerm{}
func createJSONProgress() (*ui.MockTerminal, ProgressPrinter) {
term := &ui.MockTerminal{}
printer := NewJSONProgress(term, 3)
return term, printer
}
@ -16,31 +18,31 @@ func createJSONProgress() (*mockTerm, ProgressPrinter) {
func TestJSONPrintUpdate(t *testing.T) {
term, printer := createJSONProgress()
printer.Update(State{3, 11, 0, 29, 47, 0}, 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)
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 TestJSONPrintUpdateWithSkipped(t *testing.T) {
term, printer := createJSONProgress()
printer.Update(State{3, 11, 2, 29, 47, 59}, 5*time.Second)
test.Equals(t, []string{"{\"message_type\":\"status\",\"seconds_elapsed\":5,\"percent_done\":0.6170212765957447,\"total_files\":11,\"files_restored\":3,\"files_skipped\":2,\"total_bytes\":47,\"bytes_restored\":29,\"bytes_skipped\":59}\n"}, term.output)
test.Equals(t, []string{"{\"message_type\":\"status\",\"seconds_elapsed\":5,\"percent_done\":0.6170212765957447,\"total_files\":11,\"files_restored\":3,\"files_skipped\":2,\"total_bytes\":47,\"bytes_restored\":29,\"bytes_skipped\":59}\n"}, term.Output)
}
func TestJSONPrintSummaryOnSuccess(t *testing.T) {
term, printer := createJSONProgress()
printer.Finish(State{11, 11, 0, 47, 47, 0}, 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)
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, printer := createJSONProgress()
printer.Finish(State{3, 11, 0, 29, 47, 0}, 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)
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)
}
func TestJSONPrintSummaryOnSuccessWithSkipped(t *testing.T) {
term, printer := createJSONProgress()
printer.Finish(State{11, 11, 2, 47, 47, 59}, 5*time.Second)
test.Equals(t, []string{"{\"message_type\":\"summary\",\"seconds_elapsed\":5,\"total_files\":11,\"files_restored\":11,\"files_skipped\":2,\"total_bytes\":47,\"bytes_restored\":47,\"bytes_skipped\":59}\n"}, term.output)
test.Equals(t, []string{"{\"message_type\":\"summary\",\"seconds_elapsed\":5,\"total_files\":11,\"files_restored\":11,\"files_skipped\":2,\"total_bytes\":47,\"bytes_restored\":47,\"bytes_skipped\":59}\n"}, term.Output)
}
func TestJSONPrintCompleteItem(t *testing.T) {
@ -57,6 +59,12 @@ func TestJSONPrintCompleteItem(t *testing.T) {
} {
term, printer := createJSONProgress()
printer.CompleteItem(data.action, "test", data.size)
test.Equals(t, []string{data.expected}, term.output)
test.Equals(t, []string{data.expected}, term.Output)
}
}
func TestJSONError(t *testing.T) {
term, printer := createJSONProgress()
test.Equals(t, printer.Error("/path", errors.New("error \"message\"")), nil)
test.Equals(t, []string{"{\"message_type\":\"error\",\"error\":\"error \\\"message\\\"\",\"during\":\"restore\",\"item\":\"/path\"}\n"}, term.Errors)
}

View file

@ -32,13 +32,9 @@ type progressInfoEntry struct {
bytesTotal uint64
}
type term interface {
Print(line string)
SetStatus(lines []string)
}
type ProgressPrinter interface {
Update(progress State, duration time.Duration)
Error(item string, err error) error
CompleteItem(action ItemAction, item string, size uint64)
Finish(progress State, duration time.Duration)
}
@ -139,6 +135,17 @@ func (p *Progress) ReportDeletedFile(name string) {
p.printer.CompleteItem(ActionDeleted, name, 0)
}
func (p *Progress) Error(item string, err error) error {
if p == nil {
return nil
}
p.m.Lock()
defer p.m.Unlock()
return p.printer.Error(item, err)
}
func (p *Progress) Finish() {
p.updater.Done()
}

View file

@ -4,6 +4,7 @@ import (
"testing"
"time"
"github.com/restic/restic/internal/errors"
"github.com/restic/restic/internal/test"
)
@ -23,9 +24,18 @@ type itemTraceEntry struct {
}
type itemTrace []itemTraceEntry
type errorTraceEntry struct {
item string
err error
}
type errorTrace []errorTraceEntry
type mockPrinter struct {
trace printerTrace
items itemTrace
errors errorTrace
}
const mockFinishDuration = 42 * time.Second
@ -33,6 +43,10 @@ const mockFinishDuration = 42 * time.Second
func (p *mockPrinter) Update(progress State, duration time.Duration) {
p.trace = append(p.trace, printerTraceEntry{progress, duration, false})
}
func (p *mockPrinter) Error(item string, err error) error {
p.errors = append(p.errors, errorTraceEntry{item, err})
return nil
}
func (p *mockPrinter) CompleteItem(action ItemAction, item string, size uint64) {
p.items = append(p.items, itemTraceEntry{action, item, size})
}
@ -40,20 +54,21 @@ func (p *mockPrinter) Finish(progress State, _ time.Duration) {
p.trace = append(p.trace, printerTraceEntry{progress, mockFinishDuration, true})
}
func testProgress(fn func(progress *Progress) bool) (printerTrace, itemTrace) {
func testProgress(fn func(progress *Progress) bool) (printerTrace, itemTrace, errorTrace) {
printer := &mockPrinter{}
progress := NewProgress(printer, 0)
final := fn(progress)
progress.update(0, final)
trace := append(printerTrace{}, printer.trace...)
items := append(itemTrace{}, printer.items...)
errors := append(errorTrace{}, printer.errors...)
// cleanup to avoid goroutine leak, but copy trace first
progress.Finish()
return trace, items
return trace, items, errors
}
func TestNew(t *testing.T) {
result, items := testProgress(func(progress *Progress) bool {
result, items, _ := testProgress(func(progress *Progress) bool {
return false
})
test.Equals(t, printerTrace{
@ -65,7 +80,7 @@ func TestNew(t *testing.T) {
func TestAddFile(t *testing.T) {
fileSize := uint64(100)
result, items := testProgress(func(progress *Progress) bool {
result, items, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(fileSize)
return false
})
@ -79,7 +94,7 @@ func TestFirstProgressOnAFile(t *testing.T) {
expectedBytesWritten := uint64(5)
expectedBytesTotal := uint64(100)
result, items := testProgress(func(progress *Progress) bool {
result, items, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(expectedBytesTotal)
progress.AddProgress("test", ActionFileUpdated, expectedBytesWritten, expectedBytesTotal)
return false
@ -93,7 +108,7 @@ func TestFirstProgressOnAFile(t *testing.T) {
func TestLastProgressOnAFile(t *testing.T) {
fileSize := uint64(100)
result, items := testProgress(func(progress *Progress) bool {
result, items, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(fileSize)
progress.AddProgress("test", ActionFileUpdated, 30, fileSize)
progress.AddProgress("test", ActionFileUpdated, 35, fileSize)
@ -111,7 +126,7 @@ func TestLastProgressOnAFile(t *testing.T) {
func TestLastProgressOnLastFile(t *testing.T) {
fileSize := uint64(100)
result, items := testProgress(func(progress *Progress) bool {
result, items, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(fileSize)
progress.AddFile(50)
progress.AddProgress("test1", ActionFileUpdated, 50, 50)
@ -131,7 +146,7 @@ func TestLastProgressOnLastFile(t *testing.T) {
func TestSummaryOnSuccess(t *testing.T) {
fileSize := uint64(100)
result, _ := testProgress(func(progress *Progress) bool {
result, _, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(fileSize)
progress.AddFile(50)
progress.AddProgress("test1", ActionFileUpdated, 50, 50)
@ -146,7 +161,7 @@ func TestSummaryOnSuccess(t *testing.T) {
func TestSummaryOnErrors(t *testing.T) {
fileSize := uint64(100)
result, _ := testProgress(func(progress *Progress) bool {
result, _, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(fileSize)
progress.AddFile(50)
progress.AddProgress("test1", ActionFileUpdated, 50, 50)
@ -161,7 +176,7 @@ func TestSummaryOnErrors(t *testing.T) {
func TestSkipFile(t *testing.T) {
fileSize := uint64(100)
result, items := testProgress(func(progress *Progress) bool {
result, items, _ := testProgress(func(progress *Progress) bool {
progress.AddSkippedFile("test", fileSize)
return true
})
@ -176,7 +191,7 @@ func TestSkipFile(t *testing.T) {
func TestProgressTypes(t *testing.T) {
fileSize := uint64(100)
_, items := testProgress(func(progress *Progress) bool {
_, items, _ := testProgress(func(progress *Progress) bool {
progress.AddFile(fileSize)
progress.AddFile(0)
progress.AddProgress("dir", ActionDirRestored, fileSize, fileSize)
@ -190,3 +205,17 @@ func TestProgressTypes(t *testing.T) {
itemTraceEntry{ActionDeleted, "del", 0},
}, items)
}
func TestProgressError(t *testing.T) {
err1 := errors.New("err1")
err2 := errors.New("err2")
_, _, errors := testProgress(func(progress *Progress) bool {
test.Equals(t, progress.Error("first", err1), nil)
test.Equals(t, progress.Error("second", err2), nil)
return true
})
test.Equals(t, errorTrace{
errorTraceEntry{"first", err1},
errorTraceEntry{"second", err2},
}, errors)
}

View file

@ -8,14 +8,15 @@ import (
)
type textPrinter struct {
terminal term
verbosity uint
*ui.Message
terminal ui.Terminal
}
func NewTextProgress(terminal term, verbosity uint) ProgressPrinter {
func NewTextProgress(terminal ui.Terminal, verbosity uint) ProgressPrinter {
return &textPrinter{
Message: ui.NewMessage(terminal, verbosity),
terminal: terminal,
verbosity: verbosity,
}
}
@ -33,11 +34,12 @@ func (t *textPrinter) Update(p State, duration time.Duration) {
t.terminal.SetStatus([]string{progress})
}
func (t *textPrinter) CompleteItem(messageType ItemAction, item string, size uint64) {
if t.verbosity < 3 {
return
func (t *textPrinter) Error(item string, err error) error {
t.E("ignoring error for %s: %s\n", item, err)
return nil
}
func (t *textPrinter) CompleteItem(messageType ItemAction, item string, size uint64) {
var action string
switch messageType {
case ActionDirRestored:
@ -57,9 +59,9 @@ func (t *textPrinter) CompleteItem(messageType ItemAction, item string, size uin
}
if messageType == ActionDirRestored || messageType == ActionOtherRestored || messageType == ActionDeleted {
t.terminal.Print(fmt.Sprintf("%-9v %v", action, item))
t.VV("%-9v %v", action, item)
} else {
t.terminal.Print(fmt.Sprintf("%-9v %v with size %v", action, item, ui.FormatBytes(size)))
t.VV("%-9v %v with size %v", action, item, ui.FormatBytes(size))
}
}

View file

@ -4,23 +4,13 @@ import (
"testing"
"time"
"github.com/restic/restic/internal/errors"
"github.com/restic/restic/internal/test"
"github.com/restic/restic/internal/ui"
)
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 createTextProgress() (*mockTerm, ProgressPrinter) {
term := &mockTerm{}
func createTextProgress() (*ui.MockTerminal, ProgressPrinter) {
term := &ui.MockTerminal{}
printer := NewTextProgress(term, 3)
return term, printer
}
@ -28,31 +18,31 @@ func createTextProgress() (*mockTerm, ProgressPrinter) {
func TestPrintUpdate(t *testing.T) {
term, printer := createTextProgress()
printer.Update(State{3, 11, 0, 29, 47, 0}, 5*time.Second)
test.Equals(t, []string{"[0:05] 61.70% 3 files/dirs 29 B, total 11 files/dirs 47 B"}, term.output)
test.Equals(t, []string{"[0:05] 61.70% 3 files/dirs 29 B, total 11 files/dirs 47 B"}, term.Output)
}
func TestPrintUpdateWithSkipped(t *testing.T) {
term, printer := createTextProgress()
printer.Update(State{3, 11, 2, 29, 47, 59}, 5*time.Second)
test.Equals(t, []string{"[0:05] 61.70% 3 files/dirs 29 B, total 11 files/dirs 47 B, skipped 2 files/dirs 59 B"}, term.output)
test.Equals(t, []string{"[0:05] 61.70% 3 files/dirs 29 B, total 11 files/dirs 47 B, skipped 2 files/dirs 59 B"}, term.Output)
}
func TestPrintSummaryOnSuccess(t *testing.T) {
term, printer := createTextProgress()
printer.Finish(State{11, 11, 0, 47, 47, 0}, 5*time.Second)
test.Equals(t, []string{"Summary: Restored 11 files/dirs (47 B) in 0:05"}, term.output)
test.Equals(t, []string{"Summary: Restored 11 files/dirs (47 B) in 0:05"}, term.Output)
}
func TestPrintSummaryOnErrors(t *testing.T) {
term, printer := createTextProgress()
printer.Finish(State{3, 11, 0, 29, 47, 0}, 5*time.Second)
test.Equals(t, []string{"Summary: Restored 3 / 11 files/dirs (29 B / 47 B) in 0:05"}, term.output)
test.Equals(t, []string{"Summary: Restored 3 / 11 files/dirs (29 B / 47 B) in 0:05"}, term.Output)
}
func TestPrintSummaryOnSuccessWithSkipped(t *testing.T) {
term, printer := createTextProgress()
printer.Finish(State{11, 11, 2, 47, 47, 59}, 5*time.Second)
test.Equals(t, []string{"Summary: Restored 11 files/dirs (47 B) in 0:05, skipped 2 files/dirs 59 B"}, term.output)
test.Equals(t, []string{"Summary: Restored 11 files/dirs (47 B) in 0:05, skipped 2 files/dirs 59 B"}, term.Output)
}
func TestPrintCompleteItem(t *testing.T) {
@ -70,6 +60,12 @@ func TestPrintCompleteItem(t *testing.T) {
} {
term, printer := createTextProgress()
printer.CompleteItem(data.action, "test", data.size)
test.Equals(t, []string{data.expected}, term.output)
test.Equals(t, []string{data.expected}, term.Output)
}
}
func TestError(t *testing.T) {
term, printer := createTextProgress()
test.Equals(t, printer.Error("/path", errors.New("error \"message\"")), nil)
test.Equals(t, []string{"ignoring error for /path: error \"message\"\n"}, term.Errors)
}

10
internal/ui/terminal.go Normal file
View file

@ -0,0 +1,10 @@
package ui
// Terminal is used to write messages and display status lines which can be
// updated. See termstatus.Terminal for a concrete implementation.
type Terminal interface {
Print(line string)
Error(line string)
SetStatus(lines []string)
CanUpdateStatus() bool
}