From 05db153372b0085aee4bc3bf58d391b6e3b7beb0 Mon Sep 17 00:00:00 2001 From: Eugene Sumin <95425330+e-sumin@users.noreply.github.com> Date: Tue, 21 May 2024 11:57:04 +0200 Subject: [PATCH] feat: Parse `kopia snapshot restore` progress output. (#2776) * Parse `kopia snapshot restore` progress output. * Apply suggestions from code review Reformat comments Co-authored-by: Pavan Navarathna <6504783+pavannd1@users.noreply.github.com> * Address review notes * Address review notes * Address review notes * Apply suggestions from code review Co-authored-by: Vivek Singh * Address review notes * Rename SnapshotRestore to Restore --------- Co-authored-by: Pavan Navarathna <6504783+pavannd1@users.noreply.github.com> Co-authored-by: Vivek Singh Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> --- pkg/kopia/command/parse_command_output.go | 111 +++++++++++++++++- .../command/parse_command_output_test.go | 62 ++++++++++ 2 files changed, 169 insertions(+), 4 deletions(-) diff --git a/pkg/kopia/command/parse_command_output.go b/pkg/kopia/command/parse_command_output.go index 0f510abd0d..1789d64138 100644 --- a/pkg/kopia/command/parse_command_output.go +++ b/pkg/kopia/command/parse_command_output.go @@ -39,6 +39,7 @@ const ( //nolint:lll snapshotCreateOutputRegEx = `(?P[|/\-\\\*]).+[^\d](?P\d+) hashed \((?P[^\)]+)\), (?P\d+) cached \((?P[^\)]+)\), uploaded (?P[^\)]+), (?:estimating...|estimated (?P[^\)]+) \((?P[^\)]+)\%\).+)` + restoreOutputRegEx = `Processed (?P\d+) \((?P.*)\) of (?P\d+) \((?P.*)\) (?P.*) \((?P.*)%\) remaining (?P.*)\.` extractSnapshotIDRegEx = `Created snapshot with root ([^\s]+) and ID ([^\s]+).*$` repoTotalSizeFromBlobStatsRegEx = `Total: (\d+)$` repoCountFromBlobStatsRegEx = `Count: (\d+)$` @@ -205,11 +206,19 @@ type SnapshotCreateStats struct { ProgressPercent int64 } -var kopiaProgressPattern = regexp.MustCompile(snapshotCreateOutputRegEx) //nolint:lll +var ( + kopiaProgressPattern = regexp.MustCompile(snapshotCreateOutputRegEx) + kopiaRestorePattern = regexp.MustCompile(restoreOutputRegEx) +) -// SnapshotStatsFromSnapshotCreate parses the output of a kopia snapshot -// create execution for a log of the stats for that execution. -func SnapshotStatsFromSnapshotCreate(snapCreateStderrOutput string, matchOnlyFinished bool) (stats *SnapshotCreateStats) { +// SnapshotStatsFromSnapshotCreate parses the output of a `kopia snapshot +// create` line-by-line in search of progress statistics. +// It returns nil if no statistics are found, or the most recent statistic +// if multiple are encountered. +func SnapshotStatsFromSnapshotCreate( + snapCreateStderrOutput string, + matchOnlyFinished bool, +) (stats *SnapshotCreateStats) { if snapCreateStderrOutput == "" { return nil } @@ -327,6 +336,100 @@ func parseKopiaProgressLine(line string, matchOnlyFinished bool) (stats *Snapsho } } +// RestoreStats is a container for stats parsed from the output of a +// `kopia restore` command. +type RestoreStats struct { + FilesProcessed int64 + SizeProcessedB int64 + FilesTotal int64 + SizeTotalB int64 + ProgressPercent int64 +} + +// RestoreStatsFromRestoreOutput parses the output of a `kopia restore` +// line-by-line in search of progress statistics. +// It returns nil if no statistics are found, or the most recent statistic +// if multiple are encountered. +func RestoreStatsFromRestoreOutput( + restoreStderrOutput string, +) (stats *RestoreStats) { + if restoreStderrOutput == "" { + return nil + } + logs := regexp.MustCompile("[\r\n]").Split(restoreStderrOutput, -1) + + for _, l := range logs { + lineStats := parseKopiaRestoreProgressLine(l) + if lineStats != nil { + stats = lineStats + } + } + + return stats +} + +// parseKopiaRestoreProgressLine parses restore stats from the output log line, +// which is expected to be in the following format: +// Processed 5 (1.4 GB) of 5 (1.8 GB) 291.1 MB/s (75.2%) remaining 1s. +func parseKopiaRestoreProgressLine(line string) (stats *RestoreStats) { + match := kopiaRestorePattern.FindStringSubmatch(line) + if len(match) < 8 { + return nil + } + + groups := make(map[string]string) + for i, name := range kopiaRestorePattern.SubexpNames() { + if i != 0 && name != "" { + groups[name] = match[i] + } + } + + processedCount, err := strconv.Atoi(groups["processedCount"]) + if err != nil { + log.WithError(err).Print("Skipping entry due to inability to parse number of processed files", field.M{"processedCount": groups["processedCount"]}) + return nil + } + + processedSize, err := humanize.ParseBytes(groups["processedSize"]) + if err != nil { + log.WithError(err).Print("Skipping entry due to inability to parse amount of processed bytes", field.M{"processedSize": groups["processedSize"]}) + return nil + } + + totalCount, err := strconv.Atoi(groups["totalCount"]) + if err != nil { + log.WithError(err).Print("Skipping entry due to inability to parse expected number of files", field.M{"totalCount": groups["totalCount"]}) + return nil + } + + totalSize, err := humanize.ParseBytes(groups["totalSize"]) + if err != nil { + log.WithError(err).Print("Skipping entry due to inability to parse expected amount of bytes", field.M{"totalSize": groups["totalSize"]}) + return nil + } + + progressPercent, err := strconv.ParseFloat(groups["percentage"], 64) + if err != nil { + log.WithError(err).Print("Skipping entry due to inability to parse progress percent string", field.M{"progressPercent": groups["progressPercent"]}) + return nil + } + + if progressPercent >= 100 { + // It may happen that kopia reports progress of 100 or higher without actually + // completing the task. This can occur due to inaccurate estimation. + // In such cases, we will return the progress as 99% to avoid confusion. + progressPercent = 99 + } + + return &RestoreStats{ + FilesProcessed: int64(processedCount), + SizeProcessedB: int64(processedSize), + FilesTotal: int64(totalCount), + SizeTotalB: int64(totalSize), + ProgressPercent: int64(progressPercent), + } +} + // RepoSizeStatsFromBlobStatsRaw takes a string as input, interprets it as a kopia blob stats // output in an expected format (Contains the line "Total: "), and returns the integer // size in bytes or an error if parsing is unsuccessful. diff --git a/pkg/kopia/command/parse_command_output_test.go b/pkg/kopia/command/parse_command_output_test.go index 963955e9db..67671e78c4 100644 --- a/pkg/kopia/command/parse_command_output_test.go +++ b/pkg/kopia/command/parse_command_output_test.go @@ -440,6 +440,68 @@ func (kParse *KopiaParseUtilsTestSuite) TestSnapshotStatsFromSnapshotCreate(c *C } } +func (kParse *KopiaParseUtilsTestSuite) TestRestoreStatsFromRestoreOutput(c *C) { + type args struct { + restoreOutput string + } + tests := []struct { + name string + args args + wantStats *RestoreStats + }{ + { + name: "Basic test case", + args: args{ + restoreOutput: "Processed 2 (397.5 MB) of 3 (3.1 GB) 14.9 MB/s (12.6%) remaining 3m3s.", + }, + wantStats: &RestoreStats{ + FilesProcessed: 2, + SizeProcessedB: 397500000, + FilesTotal: 3, + SizeTotalB: 3100000000, + ProgressPercent: 12, + }, + }, + { + name: "Real test case", + args: args{ + restoreOutput: "Processed 2 (13.7 MB) of 2 (3.1 GB) 8.5 MB/s (0.4%) remaining 6m10s.", + }, + wantStats: &RestoreStats{ + FilesProcessed: 2, + SizeProcessedB: 13700000, + FilesTotal: 2, + SizeTotalB: 3100000000, + ProgressPercent: 0, + }, + }, + { + name: "Ignore incomplete stats without during estimation", + args: args{ + restoreOutput: "Processed 2 (32.8 KB) of 2 (3.1 GB).", + }, + wantStats: nil, + }, + { + name: "Progress is over 100% and still not ready - set 99%", + args: args{ + restoreOutput: "Processed 2 (13.7 MB) of 2 (3.1 GB) 8.5 MB/s (120.4%) remaining 6m10s.", + }, + wantStats: &RestoreStats{ + FilesProcessed: 2, + SizeProcessedB: 13700000, + FilesTotal: 2, + SizeTotalB: 3100000000, + ProgressPercent: 99, + }, + }, + } + for _, tt := range tests { + stats := RestoreStatsFromRestoreOutput(tt.args.restoreOutput) + c.Check(stats, DeepEquals, tt.wantStats, Commentf("Failed for %s", tt.name)) + } +} + func (kParse *KopiaParseUtilsTestSuite) TestPhysicalSizeFromBlobStatsRaw(c *C) { for _, tc := range []struct { blobStatsOutput string