diff --git a/cli/command_policy_set.go b/cli/command_policy_set.go index 35191f1e0..92e933ca0 100644 --- a/cli/command_policy_set.go +++ b/cli/command_policy_set.go @@ -21,6 +21,7 @@ type commandPolicySet struct { policyCompressionFlags policyErrorFlags policyFilesFlags + policyLoggingFlags policyRetentionFlags policySchedulingFlags } @@ -35,6 +36,7 @@ func (c *commandPolicySet) setup(svc appServices, parent commandParent) { c.policyCompressionFlags.setup(cmd) c.policyErrorFlags.setup(cmd) c.policyFilesFlags.setup(cmd) + c.policyLoggingFlags.setup(cmd) c.policyRetentionFlags.setup(cmd) c.policySchedulingFlags.setup(cmd) @@ -64,7 +66,7 @@ func (c *commandPolicySet) run(ctx context.Context, rep repo.RepositoryWriter) e return errors.Wrap(err, "could not get defined policy") } - log(ctx).Infof("Setting policy for %v\n", target) + log(ctx).Infof("Setting policy for %v", target) changeCount := 0 if err := c.setPolicyFromFlags(ctx, p, &changeCount); err != nil { @@ -108,6 +110,10 @@ func (c *commandPolicySet) setPolicyFromFlags(ctx context.Context, p *policy.Pol return errors.Wrap(err, "actions policy") } + if err := c.setLoggingPolicyFromFlags(ctx, &p.LoggingPolicy, changeCount); err != nil { + return errors.Wrap(err, "actions policy") + } + // It's not really a list, just optional boolean, last one wins. for _, inherit := range c.inherit { *changeCount++ @@ -120,7 +126,7 @@ func (c *commandPolicySet) setPolicyFromFlags(ctx context.Context, p *policy.Pol func applyPolicyStringList(ctx context.Context, desc string, val *[]string, add, remove []string, clear bool, changeCount *int) { if clear { - log(ctx).Infof(" - removing all from %q\n", desc) + log(ctx).Infof(" - removing all from %q", desc) *changeCount++ @@ -137,7 +143,7 @@ func applyPolicyStringList(ctx context.Context, desc string, val *[]string, add, for _, b := range add { *changeCount++ - log(ctx).Infof(" - adding %q to %q\n", b, desc) + log(ctx).Infof(" - adding %q to %q", b, desc) entries[b] = true } @@ -145,7 +151,7 @@ func applyPolicyStringList(ctx context.Context, desc string, val *[]string, add, for _, b := range remove { *changeCount++ - log(ctx).Infof(" - removing %q from %q\n", b, desc) + log(ctx).Infof(" - removing %q from %q", b, desc) delete(entries, b) } @@ -168,7 +174,7 @@ func applyPolicyNumber(ctx context.Context, desc string, val **int, str string, if str == inheritPolicyString || str == defaultPolicyString { *changeCount++ - log(ctx).Infof(" - resetting %q to a default value inherited from parent.\n", desc) + log(ctx).Infof(" - resetting %q to a default value inherited from parent.", desc) *val = nil @@ -184,7 +190,7 @@ func applyPolicyNumber(ctx context.Context, desc string, val **int, str string, i := int(v) *changeCount++ - log(ctx).Infof(" - setting %q to %v.\n", desc, i) + log(ctx).Infof(" - setting %q to %v.", desc, i) *val = &i return nil @@ -199,7 +205,7 @@ func applyPolicyNumber64(ctx context.Context, desc string, val *int64, str strin if str == inheritPolicyString || str == defaultPolicyString { *changeCount++ - log(ctx).Infof(" - resetting %q to a default value inherited from parent.\n", desc) + log(ctx).Infof(" - resetting %q to a default value inherited from parent.", desc) *val = 0 @@ -214,13 +220,13 @@ func applyPolicyNumber64(ctx context.Context, desc string, val *int64, str strin *changeCount++ - log(ctx).Infof(" - setting %q to %v.\n", desc, v) + log(ctx).Infof(" - setting %q to %v.", desc, v) *val = v return nil } -func applyPolicyBoolPtr(ctx context.Context, desc string, val **bool, str string, changeCount *int) error { +func applyPolicyBoolPtr(ctx context.Context, desc string, val **policy.OptionalBool, str string, changeCount *int) error { if str == "" { // not changed return nil @@ -229,7 +235,7 @@ func applyPolicyBoolPtr(ctx context.Context, desc string, val **bool, str string if str == inheritPolicyString || str == defaultPolicyString { *changeCount++ - log(ctx).Infof(" - resetting %q to a default value inherited from parent.\n", desc) + log(ctx).Infof(" - resetting %q to a default value inherited from parent.", desc) *val = nil @@ -243,8 +249,10 @@ func applyPolicyBoolPtr(ctx context.Context, desc string, val **bool, str string *changeCount++ - log(ctx).Infof(" - setting %q to %v.\n", desc, v) - *val = &v + log(ctx).Infof(" - setting %q to %v.", desc, v) + + ov := policy.OptionalBool(v) + *val = &ov return nil } diff --git a/cli/command_policy_set_compression.go b/cli/command_policy_set_compression.go index 212c515ad..b3edf3850 100644 --- a/cli/command_policy_set_compression.go +++ b/cli/command_policy_set_compression.go @@ -54,11 +54,11 @@ func (c *policyCompressionFlags) setCompressionPolicyFromFlags(ctx context.Conte *changeCount++ if v == inheritPolicyString { - log(ctx).Infof(" - resetting compression algorithm to default value inherited from parent\n") + log(ctx).Infof(" - resetting compression algorithm to default value inherited from parent") p.CompressorName = "" } else { - log(ctx).Infof(" - setting compression algorithm to %v\n", v) + log(ctx).Infof(" - setting compression algorithm to %v", v) p.CompressorName = compression.Name(v) } diff --git a/cli/command_policy_set_files.go b/cli/command_policy_set_files.go index df8ecc63c..7a9cd79bf 100644 --- a/cli/command_policy_set_files.go +++ b/cli/command_policy_set_files.go @@ -53,7 +53,7 @@ func (c *policyFilesFlags) setFilesPolicyFromFlags(ctx context.Context, fp *poli applyPolicyStringList(ctx, "dot-ignore filenames", &fp.DotIgnoreFiles, c.policySetAddDotIgnore, c.policySetRemoveDotIgnore, c.policySetClearDotIgnore, changeCount) applyPolicyStringList(ctx, "ignore rules", &fp.IgnoreRules, c.policySetAddIgnore, c.policySetRemoveIgnore, c.policySetClearIgnore, changeCount) - if err := applyPolicyBoolPtr(ctx, "ignore cache dirs", &fp.IgnoreCacheDirs, c.policyIgnoreCacheDirs, changeCount); err != nil { + if err := applyPolicyBoolPtr(ctx, "ignore cache dirs", &fp.IgnoreCacheDirectories, c.policyIgnoreCacheDirs, changeCount); err != nil { return err } diff --git a/cli/command_policy_set_logging.go b/cli/command_policy_set_logging.go new file mode 100644 index 000000000..b4ff5d3a1 --- /dev/null +++ b/cli/command_policy_set_logging.go @@ -0,0 +1,88 @@ +package cli + +import ( + "context" + "strconv" + + "github.com/alecthomas/kingpin" + "github.com/pkg/errors" + + "github.com/kopia/kopia/snapshot/policy" +) + +type policyLoggingFlags struct { + dirSnapshottedDetail string + dirIgnoredDetail string + entrySnapshottedDetail string + entryIgnoredDetail string + entryCacheHitDetail string + entryCacheMissDetail string +} + +func (c *policyLoggingFlags) setup(cmd *kingpin.CmdClause) { + cmd.Flag("log-dir-snapshotted", "Log detail when a directory is snapshotted (or 'inherit')").PlaceHolder("N").StringVar(&c.dirSnapshottedDetail) + cmd.Flag("log-dir-ignored", "Log detail when a directory is ignored (or 'inherit')").PlaceHolder("N").StringVar(&c.dirIgnoredDetail) + cmd.Flag("log-entry-snapshotted", "Log detail when an entry is snapshotted (or 'inherit')").PlaceHolder("N").StringVar(&c.entrySnapshottedDetail) + cmd.Flag("log-entry-ignored", "Log detail when an entry is ignored (or 'inherit')").PlaceHolder("N").StringVar(&c.entryIgnoredDetail) + cmd.Flag("log-entry-cache-hit", "Log detail on entry cache hit (or 'inherit')").PlaceHolder("N").StringVar(&c.entryCacheHitDetail) + cmd.Flag("log-entry-cache-miss", "Log detail on entry cache miss (or 'inherit')").PlaceHolder("N").StringVar(&c.entryCacheMissDetail) +} + +func (c *policyLoggingFlags) setLoggingPolicyFromFlags(ctx context.Context, p *policy.LoggingPolicy, changeCount *int) error { + if err := applyPolicyLogDetailPtr(ctx, "directory snapshotted detail", &p.Directories.Snapshotted, c.dirSnapshottedDetail, changeCount); err != nil { + return errors.Wrap(err, "directory snapshotted detail") + } + + if err := applyPolicyLogDetailPtr(ctx, "directory ignored detail", &p.Directories.Ignored, c.dirIgnoredDetail, changeCount); err != nil { + return errors.Wrap(err, "directory ignored detail") + } + + if err := applyPolicyLogDetailPtr(ctx, "entry snapshotted detail", &p.Entries.Snapshotted, c.entrySnapshottedDetail, changeCount); err != nil { + return errors.Wrap(err, "entry snapshotted detail") + } + + if err := applyPolicyLogDetailPtr(ctx, "entry ignored detail", &p.Entries.Ignored, c.entryIgnoredDetail, changeCount); err != nil { + return errors.Wrap(err, "entry ignored detail") + } + + if err := applyPolicyLogDetailPtr(ctx, "entry cache hit detail", &p.Entries.CacheHit, c.entryCacheHitDetail, changeCount); err != nil { + return errors.Wrap(err, "entry cache hit detail") + } + + if err := applyPolicyLogDetailPtr(ctx, "entry cache miss detail", &p.Entries.CacheMiss, c.entryCacheMissDetail, changeCount); err != nil { + return errors.Wrap(err, "entry cache miss detail") + } + + return nil +} + +func applyPolicyLogDetailPtr(ctx context.Context, desc string, val **policy.LogDetail, str string, changeCount *int) error { + if str == "" { + // not changed + return nil + } + + if str == inheritPolicyString { + *changeCount++ + + log(ctx).Infof(" - resetting %q to a default value inherited from parent.", desc) + + *val = nil + + return nil + } + + v, err := strconv.Atoi(str) + if err != nil || v < int(policy.LogDetailNone) || v > int(policy.LogDetailMax) { + return errors.Errorf("must be >= %v and <= %v or %q", policy.LogDetailNone, policy.LogDetailMax, inheritPolicyString) + } + + *changeCount++ + + log(ctx).Infof(" - setting %q to %v.", desc, v) + + ov := policy.LogDetail(v) + *val = &ov + + return nil +} diff --git a/cli/command_policy_set_logging_test.go b/cli/command_policy_set_logging_test.go new file mode 100644 index 000000000..b313c29ea --- /dev/null +++ b/cli/command_policy_set_logging_test.go @@ -0,0 +1,64 @@ +package cli_test + +import ( + "testing" + + "github.com/stretchr/testify/require" + + "github.com/kopia/kopia/internal/testutil" + "github.com/kopia/kopia/tests/testenv" +) + +func TestSetLoggingPolicy(t *testing.T) { + e := testenv.NewCLITest(t, testenv.RepoFormatNotImportant, testenv.NewInProcRunner(t)) + defer e.RunAndExpectSuccess(t, "repo", "disconnect") + + e.RunAndExpectSuccess(t, "repo", "create", "filesystem", "--path", e.RepoDir) + + lines := e.RunAndExpectSuccess(t, "policy", "show", "--global") + require.Contains(t, lines, " Directory snapshotted: 5 (defined for this target)") + require.Contains(t, lines, " Directory ignored: 5 (defined for this target)") + require.Contains(t, lines, " Entry snapshotted: 0 (defined for this target)") + require.Contains(t, lines, " Entry ignored: 5 (defined for this target)") + require.Contains(t, lines, " Entry cache hit 0 (defined for this target)") + require.Contains(t, lines, " Entry cache miss 0 (defined for this target)") + + // make some directory we'll be setting policy on + td := testutil.TempDirectory(t) + + lines = e.RunAndExpectSuccess(t, "policy", "show", td) + require.Contains(t, lines, " Directory snapshotted: 5 inherited from (global)") + require.Contains(t, lines, " Directory ignored: 5 inherited from (global)") + require.Contains(t, lines, " Entry snapshotted: 0 inherited from (global)") + require.Contains(t, lines, " Entry ignored: 5 inherited from (global)") + require.Contains(t, lines, " Entry cache hit 0 inherited from (global)") + require.Contains(t, lines, " Entry cache miss 0 inherited from (global)") + + e.RunAndExpectSuccess(t, "policy", "set", td, + "--log-dir-snapshotted=1", + "--log-dir-ignored=2", + "--log-entry-snapshotted=3", + "--log-entry-ignored=4", + "--log-entry-cache-hit=5", + "--log-entry-cache-miss=6") + + lines = e.RunAndExpectSuccess(t, "policy", "show", td) + require.Contains(t, lines, " Directory snapshotted: 1 (defined for this target)") + require.Contains(t, lines, " Directory ignored: 2 (defined for this target)") + require.Contains(t, lines, " Entry snapshotted: 3 (defined for this target)") + require.Contains(t, lines, " Entry ignored: 4 (defined for this target)") + require.Contains(t, lines, " Entry cache hit 5 (defined for this target)") + require.Contains(t, lines, " Entry cache miss 6 (defined for this target)") + + e.RunAndExpectSuccess(t, "policy", "set", td, "--log-entry-ignored=inherit") + + lines = e.RunAndExpectSuccess(t, "policy", "show", td) + require.Contains(t, lines, " Entry ignored: 5 inherited from (global)") + + e.RunAndExpectFailure(t, "policy", "set", td, "--log-dir-snapshotted=-1") + e.RunAndExpectFailure(t, "policy", "set", td, "--log-dir-ignored=11") + e.RunAndExpectFailure(t, "policy", "set", td, "--log-entry-snapshotted=xx") + e.RunAndExpectFailure(t, "policy", "set", td, "--log-entry-ignored=-1") + e.RunAndExpectFailure(t, "policy", "set", td, "--log-entry-cache-hit=-1") + e.RunAndExpectFailure(t, "policy", "set", td, "--log-entry-cache-miss=-1") +} diff --git a/cli/command_policy_set_scheduling.go b/cli/command_policy_set_scheduling.go index f03c16c28..a0d96234f 100644 --- a/cli/command_policy_set_scheduling.go +++ b/cli/command_policy_set_scheduling.go @@ -37,7 +37,7 @@ func (c *policySchedulingFlags) setScheduleFromFlags(ctx context.Context, sp *po *changeCount++ sp.SetInterval(interval) - log(ctx).Infof(" - setting snapshot interval to %v\n", sp.Interval()) + log(ctx).Infof(" - setting snapshot interval to %v", sp.Interval()) break } @@ -65,9 +65,9 @@ func (c *policySchedulingFlags) setScheduleFromFlags(ctx context.Context, sp *po sp.TimesOfDay = policy.SortAndDedupeTimesOfDay(timesOfDay) if timesOfDay == nil { - log(ctx).Infof(" - resetting snapshot times of day to default\n") + log(ctx).Infof(" - resetting snapshot times of day to default") } else { - log(ctx).Infof(" - setting snapshot times to %v\n", timesOfDay) + log(ctx).Infof(" - setting snapshot times to %v", timesOfDay) } } diff --git a/cli/command_policy_set_test.go b/cli/command_policy_set_test.go index c1dcb4c91..aed3d5342 100644 --- a/cli/command_policy_set_test.go +++ b/cli/command_policy_set_test.go @@ -26,14 +26,14 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { { name: "No values provided as command line arguments", startingPolicy: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, fileArg: "", dirArg: "", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, expErr: false, expChangeCount: 0, @@ -56,7 +56,7 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { fileArg: "true", dirArg: "some-malformed-arg", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), IgnoreDirectoryErrors: nil, }, expErr: true, @@ -80,8 +80,8 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { fileArg: "true", dirArg: "true", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, expErr: false, expChangeCount: 2, @@ -89,14 +89,14 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { { name: "Set to false", startingPolicy: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, fileArg: "false", dirArg: "false", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), }, expErr: false, expChangeCount: 2, @@ -104,14 +104,14 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { { name: "File false, dir true", startingPolicy: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(false), }, fileArg: "false", dirArg: "true", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(true), }, expErr: false, expChangeCount: 2, @@ -119,14 +119,14 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { { name: "File true, dir false", startingPolicy: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(true), }, fileArg: "true", dirArg: "false", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(false), }, expErr: false, expChangeCount: 2, @@ -134,14 +134,14 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { { name: "File inherit, dir true", startingPolicy: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(false), }, fileArg: "inherit", dirArg: "true", expResult: &policy.ErrorHandlingPolicy{ IgnoreFileErrors: nil, - IgnoreDirectoryErrors: newBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, expErr: false, expChangeCount: 2, @@ -149,13 +149,13 @@ func TestSetErrorHandlingPolicyFromFlags(t *testing.T) { { name: "File true, dir inherit", startingPolicy: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(true), }, fileArg: "true", dirArg: "inherit", expResult: &policy.ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), IgnoreDirectoryErrors: nil, }, expErr: false, @@ -397,6 +397,6 @@ func TestSetSchedulingPolicyFromFlags(t *testing.T) { } } -func newBool(b bool) *bool { +func newOptionalBool(b policy.OptionalBool) *policy.OptionalBool { return &b } diff --git a/cli/command_policy_show.go b/cli/command_policy_show.go index 4c1f4a2e8..cf795a4c3 100644 --- a/cli/command_policy_show.go +++ b/cli/command_policy_show.go @@ -93,6 +93,8 @@ func printPolicy(out *textOutput, p *policy.Policy, parents []*policy.Policy) { printCompressionPolicy(out, p, parents) out.printStdout("\n") printActions(out, p, parents) + out.printStdout("\n") + printLoggingPolicy(out, p, parents) } func printRetentionPolicy(out *textOutput, p *policy.Policy, parents []*policy.Policy) { @@ -133,9 +135,9 @@ func printFilesPolicy(out *textOutput, p *policy.Policy, parents []*policy.Polic out.printStdout("Files policy:\n") out.printStdout(" Ignore cache directories: %5v %v\n", - p.FilesPolicy.IgnoreCacheDirectoriesOrDefault(true), + p.FilesPolicy.IgnoreCacheDirectories.OrDefault(true), getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { - return pol.FilesPolicy.IgnoreCacheDirs != nil + return pol.FilesPolicy.IgnoreCacheDirectories != nil })) if len(p.FilesPolicy.IgnoreRules) > 0 { @@ -171,7 +173,7 @@ func printFilesPolicy(out *textOutput, p *policy.Policy, parents []*policy.Polic } out.printStdout(" Scan one filesystem only: %5v %v\n", - p.FilesPolicy.OneFileSystemOrDefault(false), + p.FilesPolicy.OneFileSystem.OrDefault(false), getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { return pol.FilesPolicy.OneFileSystem != nil })) @@ -181,24 +183,64 @@ func printErrorHandlingPolicy(out *textOutput, p *policy.Policy, parents []*poli out.printStdout("Error handling policy:\n") out.printStdout(" Ignore file read errors: %5v %v\n", - p.ErrorHandlingPolicy.IgnoreFileErrorsOrDefault(false), + p.ErrorHandlingPolicy.IgnoreFileErrors.OrDefault(false), getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { return pol.ErrorHandlingPolicy.IgnoreFileErrors != nil })) out.printStdout(" Ignore directory read errors: %5v %v\n", - p.ErrorHandlingPolicy.IgnoreDirectoryErrorsOrDefault(false), + p.ErrorHandlingPolicy.IgnoreDirectoryErrors.OrDefault(false), getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { return pol.ErrorHandlingPolicy.IgnoreDirectoryErrors != nil })) out.printStdout(" Ignore unknown types: %5v %v\n", - p.ErrorHandlingPolicy.IgnoreUnknownTypesOrDefault(true), + p.ErrorHandlingPolicy.IgnoreUnknownTypes.OrDefault(true), getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { return pol.ErrorHandlingPolicy.IgnoreUnknownTypes != nil })) } +func printLoggingPolicy(out *textOutput, p *policy.Policy, parents []*policy.Policy) { + out.printStdout("Logging details (%v-none, %v-maximum):\n", policy.LogDetailNone, policy.LogDetailMax) + + out.printStdout(" Directory snapshotted: %5v %v\n", + p.LoggingPolicy.Directories.Snapshotted.OrDefault(policy.LogDetailNone), + getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { + return pol.LoggingPolicy.Directories.Snapshotted != nil + })) + + out.printStdout(" Directory ignored: %5v %v\n", + p.LoggingPolicy.Directories.Ignored.OrDefault(policy.LogDetailNone), + getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { + return pol.LoggingPolicy.Directories.Ignored != nil + })) + + out.printStdout(" Entry snapshotted: %5v %v\n", + p.LoggingPolicy.Entries.Snapshotted.OrDefault(policy.LogDetailNone), + getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { + return pol.LoggingPolicy.Entries.Snapshotted != nil + })) + + out.printStdout(" Entry ignored: %5v %v\n", + p.LoggingPolicy.Entries.Ignored.OrDefault(policy.LogDetailNone), + getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { + return pol.LoggingPolicy.Entries.Ignored != nil + })) + + out.printStdout(" Entry cache hit %5v %v\n", + p.LoggingPolicy.Entries.CacheHit.OrDefault(policy.LogDetailNone), + getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { + return pol.LoggingPolicy.Entries.CacheHit != nil + })) + + out.printStdout(" Entry cache miss %5v %v\n", + p.LoggingPolicy.Entries.CacheMiss.OrDefault(policy.LogDetailNone), + getDefinitionPoint(p.Target(), parents, func(pol *policy.Policy) bool { + return pol.LoggingPolicy.Entries.CacheMiss != nil + })) +} + func printSchedulingPolicy(out *textOutput, p *policy.Policy, parents []*policy.Policy) { out.printStdout("Scheduling policy:\n") diff --git a/cli/command_snapshot_create.go b/cli/command_snapshot_create.go index c037bfc1a..49d32aaed 100644 --- a/cli/command_snapshot_create.go +++ b/cli/command_snapshot_create.go @@ -38,6 +38,9 @@ type commandSnapshotCreate struct { snapshotCreateCheckpointUploadLimitMB int64 snapshotCreateTags []string + logDirDetail int + logEntryDetail int + jo jsonOutput svc appServices out textOutput @@ -61,6 +64,12 @@ func (c *commandSnapshotCreate) setup(svc appServices, parent commandParent) { cmd.Flag("stdin-file", "File path to be used for stdin data snapshot.").StringVar(&c.snapshotCreateStdinFileName) cmd.Flag("tags", "Tags applied on the snapshot. Must be provided in the : format.").StringsVar(&c.snapshotCreateTags) + c.logDirDetail = -1 + c.logEntryDetail = -1 + + cmd.Flag("log-dir-detail", "Override log level for directories").IntVar(&c.logDirDetail) + cmd.Flag("log-entry-detail", "Override log level for entries").IntVar(&c.logEntryDetail) + c.jo.setup(svc, cmd) c.out.setup(svc) @@ -192,6 +201,18 @@ func (c *commandSnapshotCreate) setupUploader(rep repo.RepositoryWriter) *snapsh u.EnableActions = false } + if l := c.logDirDetail; l != -1 { + ld := policy.LogDetail(l) + + u.OverrideDirLogDetail = &ld + } + + if l := c.logEntryDetail; l != -1 { + ld := policy.LogDetail(l) + + u.OverrideEntryLogDetail = &ld + } + if interval := c.snapshotCreateCheckpointInterval; interval != 0 { u.CheckpointInterval = interval } diff --git a/cli/command_snapshot_estimate_test.go b/cli/command_snapshot_estimate_test.go index 9b60af263..89e82bc33 100644 --- a/cli/command_snapshot_estimate_test.go +++ b/cli/command_snapshot_estimate_test.go @@ -32,8 +32,8 @@ func TestSnapshotEstimate(t *testing.T) { out = env.RunAndExpectSuccess(t, "snapshot", "estimate", dir) require.Contains(t, out, "Snapshot includes 1 file(s), total size 75 KB") require.Contains(t, out, "Snapshot excludes 2 file(s), total size 75 KB") - require.Contains(t, out, " - ./file2.txt - 50 KB") - require.Contains(t, out, " - ./subdir/file2.txt - 25 KB") + require.Contains(t, out, " - file2.txt - 50 KB") + require.Contains(t, out, " - subdir/file2.txt - 25 KB") require.Contains(t, out, "Snapshot excludes no directories.") // ignore a dir @@ -41,8 +41,8 @@ func TestSnapshotEstimate(t *testing.T) { out = env.RunAndExpectSuccess(t, "snapshot", "estimate", dir) require.Contains(t, out, "Snapshot includes 1 file(s), total size 75 KB") require.Contains(t, out, "Snapshot excludes 1 file(s), total size 50 KB") - require.Contains(t, out, " - ./file2.txt - 50 KB") - require.Contains(t, out, " - ./subdir") + require.Contains(t, out, " - file2.txt - 50 KB") + require.Contains(t, out, " - subdir") require.Contains(t, out, "Snapshot excludes 1 directories. Examples:") } diff --git a/fs/ignorefs/ignorefs.go b/fs/ignorefs/ignorefs.go index bb0de3069..54a187c4b 100644 --- a/fs/ignorefs/ignorefs.go +++ b/fs/ignorefs/ignorefs.go @@ -19,7 +19,7 @@ import ( var log = logging.Module("ignorefs") // IgnoreCallback is a function called by ignorefs to report whenever a file or directory is being ignored while listing its parent. -type IgnoreCallback func(path string, metadata fs.Entry) +type IgnoreCallback func(ctx context.Context, path string, metadata fs.Entry, pol *policy.Tree) type ignoreContext struct { parent *ignoreContext @@ -33,13 +33,13 @@ type ignoreContext struct { oneFileSystem bool // should we enter other mounted filesystems } -func (c *ignoreContext) shouldIncludeByName(path string, e fs.Entry) bool { +func (c *ignoreContext) shouldIncludeByName(ctx context.Context, path string, e fs.Entry, policyTree *policy.Tree) bool { shouldIgnore := false // Start by checking with any ignores defined in a parent directory (if there is one). // Any matches here may be negated by .ignore-files in lower directories. if c.parent != nil { - shouldIgnore = !c.parent.shouldIncludeByName(path, e) + shouldIgnore = !c.parent.shouldIncludeByName(ctx, path, e, policyTree) } for _, m := range c.matchers { @@ -52,7 +52,7 @@ func (c *ignoreContext) shouldIncludeByName(path string, e fs.Entry) bool { if shouldIgnore { for _, oi := range c.onIgnore { - oi(path, e) + oi(ctx, strings.TrimPrefix(path, "./"), e, policyTree) } return false @@ -104,7 +104,7 @@ func isCorrectCacheDirSignature(ctx context.Context, f fs.File) (bool, error) { } func (d *ignoreDirectory) skipCacheDirectory(ctx context.Context, entries fs.Entries, relativePath string, policyTree *policy.Tree) fs.Entries { - if !policyTree.EffectivePolicy().FilesPolicy.IgnoreCacheDirectoriesOrDefault(true) { + if !policyTree.EffectivePolicy().FilesPolicy.IgnoreCacheDirectories.OrDefault(true) { return entries } @@ -119,7 +119,7 @@ func (d *ignoreDirectory) skipCacheDirectory(ctx context.Context, entries fs.Ent if correct { // if the given directory contains a marker file used for kopia cache, pretend the directory was empty. for _, oi := range d.parentContext.onIgnore { - oi(relativePath, d) + oi(ctx, strings.TrimPrefix(relativePath, "./"), d, policyTree) } return nil @@ -158,7 +158,7 @@ func (d *ignoreDirectory) Readdir(ctx context.Context) (fs.Entries, error) { result := make(fs.Entries, 0, len(entries)) for _, e := range entries { - if !thisContext.shouldIncludeByName(d.relativePath+"/"+e.Name(), e) { + if !thisContext.shouldIncludeByName(ctx, d.relativePath+"/"+e.Name(), e, d.policyTree) { continue } @@ -236,7 +236,7 @@ func (c *ignoreContext) overrideFromPolicy(fp *policy.FilesPolicy, dirPath strin c.maxFileSize = fp.MaxFileSize } - c.oneFileSystem = fp.OneFileSystemOrDefault(false) + c.oneFileSystem = fp.OneFileSystem.OrDefault(false) // append policy-level rules for _, rule := range fp.IgnoreRules { diff --git a/fs/ignorefs/ignorefs_test.go b/fs/ignorefs/ignorefs_test.go index 806f5adcc..3669fa93d 100644 --- a/fs/ignorefs/ignorefs_test.go +++ b/fs/ignorefs/ignorefs_test.go @@ -85,7 +85,7 @@ var rootAndSrcPolicy = policy.BuildTree(map[string]*policy.Policy{ }, }, policy.DefaultPolicy) -var trueValue = true +var trueValue = policy.OptionalBool(true) var oneFileSystemPolicy = policy.BuildTree(map[string]*policy.Policy{ ".": { diff --git a/internal/mockfs/mockfs.go b/internal/mockfs/mockfs.go index ed3a5db7e..1ed95479e 100644 --- a/internal/mockfs/mockfs.go +++ b/internal/mockfs/mockfs.go @@ -13,6 +13,9 @@ import ( "github.com/kopia/kopia/fs" ) +// DefaultModTime is the default modification time for mock filesystem entries. +var DefaultModTime = time.Date(2021, 1, 2, 3, 4, 5, 0, time.UTC) + // ReaderSeekerCloser implements io.Reader, io.Seeker and io.Closer. type ReaderSeekerCloser interface { io.Reader @@ -92,9 +95,10 @@ func (imd *Directory) AddFile(name string, content []byte, permissions os.FileMo imd, name = imd.resolveSubdir(name) file := &File{ entry: entry{ - name: name, - mode: permissions, - size: int64(len(content)), + name: name, + mode: permissions, + size: int64(len(content)), + modTime: DefaultModTime, }, source: func() (ReaderSeekerCloser, error) { return readerSeekerCloser{bytes.NewReader(content)}, nil @@ -106,15 +110,34 @@ func (imd *Directory) AddFile(name string, content []byte, permissions os.FileMo return file } +// AddSymlink adds a mock symlink with the specified name, target and permissions. +func (imd *Directory) AddSymlink(name, target string, permissions os.FileMode) *Symlink { + imd, name = imd.resolveSubdir(name) + sl := &Symlink{ + entry: entry{ + name: name, + mode: permissions | os.ModeSymlink, + size: int64(len(target)), + modTime: DefaultModTime, + }, + target: target, + } + + imd.addChild(sl) + + return sl +} + // AddFileDevice adds a mock file with the specified name, content, permissions, and device info. func (imd *Directory) AddFileDevice(name string, content []byte, permissions os.FileMode, deviceInfo fs.DeviceInfo) *File { imd, name = imd.resolveSubdir(name) file := &File{ entry: entry{ - name: name, - mode: permissions, - size: int64(len(content)), - device: deviceInfo, + name: name, + mode: permissions, + size: int64(len(content)), + device: deviceInfo, + modTime: DefaultModTime, }, source: func() (ReaderSeekerCloser, error) { return readerSeekerCloser{bytes.NewReader(content)}, nil @@ -132,8 +155,9 @@ func (imd *Directory) AddDir(name string, permissions os.FileMode) *Directory { subdir := &Directory{ entry: entry{ - name: name, - mode: permissions | os.ModeDir, + name: name, + mode: permissions | os.ModeDir, + modTime: DefaultModTime, }, } @@ -148,8 +172,9 @@ func (imd *Directory) AddErrorEntry(name string, permissions os.FileMode, err er ee := &ErrorEntry{ entry: entry{ - name: name, - mode: permissions | os.ModeDir, + name: name, + mode: permissions | os.ModeDir, + modTime: DefaultModTime, }, err: err, } @@ -165,9 +190,10 @@ func (imd *Directory) AddDirDevice(name string, permissions os.FileMode, deviceI subdir := &Directory{ entry: entry{ - name: name, - mode: permissions | os.ModeDir, - device: deviceInfo, + name: name, + mode: permissions | os.ModeDir, + device: deviceInfo, + modTime: DefaultModTime, }, } @@ -293,20 +319,25 @@ func (imf *File) Open(ctx context.Context) (fs.Reader, error) { }, nil } -type inmemorySymlink struct { +// Symlink is a mock implementation of the fs.Symlink interface. +type Symlink struct { entry + + target string } -func (imsl *inmemorySymlink) Readlink(ctx context.Context) (string, error) { - panic("not implemented yet") +// Readlink implements fs.Symlink interface. +func (imsl *Symlink) Readlink(ctx context.Context) (string, error) { + return imsl.target, nil } // NewDirectory returns new mock directory. func NewDirectory() *Directory { return &Directory{ entry: entry{ - name: "", - mode: 0o777 | os.ModeDir, // nolint:gomnd + name: "", + mode: 0o777 | os.ModeDir, // nolint:gomnd + modTime: DefaultModTime, }, } } @@ -325,6 +356,6 @@ func (e *ErrorEntry) ErrorInfo() error { var ( _ fs.Directory = &Directory{} _ fs.File = &File{} - _ fs.Symlink = &inmemorySymlink{} + _ fs.Symlink = &Symlink{} _ fs.ErrorEntry = &ErrorEntry{} ) diff --git a/repo/logging/logging.go b/repo/logging/logging.go index f4c800d3a..7b255f2a9 100644 --- a/repo/logging/logging.go +++ b/repo/logging/logging.go @@ -24,6 +24,6 @@ func Module(module string) func(ctx context.Context) Logger { return l.(*loggerCache).getLogger(module) } - return nullLoggerInstance + return NullLogger } } diff --git a/repo/logging/null_logger.go b/repo/logging/null_logger.go index 191f5b976..6495b84da 100644 --- a/repo/logging/null_logger.go +++ b/repo/logging/null_logger.go @@ -8,8 +8,9 @@ func (nullLogger) Infof(msg string, args ...interface{}) {} func (nullLogger) Warnf(msg string, args ...interface{}) {} func (nullLogger) Errorf(msg string, args ...interface{}) {} -var nullLoggerInstance = nullLogger{} +// NullLogger is a null logger that discards all log messages. +var NullLogger Logger = nullLogger{} func getNullLogger(module string) Logger { - return nullLoggerInstance + return NullLogger } diff --git a/snapshot/policy/error_handling_policy.go b/snapshot/policy/error_handling_policy.go index b0568e93a..57905340f 100644 --- a/snapshot/policy/error_handling_policy.go +++ b/snapshot/policy/error_handling_policy.go @@ -3,67 +3,25 @@ package policy // ErrorHandlingPolicy controls error hadnling behavior when taking snapshots. type ErrorHandlingPolicy struct { // IgnoreFileErrors controls whether or not snapshot operation should fail when a file throws an error on being read - IgnoreFileErrors *bool `json:"ignoreFileErrors,omitempty"` + IgnoreFileErrors *OptionalBool `json:"ignoreFileErrors,omitempty"` // IgnoreDirectoryErrors controls whether or not snapshot operation should fail when a directory throws an error on being read or opened - IgnoreDirectoryErrors *bool `json:"ignoreDirectoryErrors,omitempty"` + IgnoreDirectoryErrors *OptionalBool `json:"ignoreDirectoryErrors,omitempty"` // IgnoreUnknownTypes controls whether or not snapshot operation should fail when it encounters a directory entry of an unknown type. - IgnoreUnknownTypes *bool `json:"ignoreUnknownTypes,omitempty"` + IgnoreUnknownTypes *OptionalBool `json:"ignoreUnknownTypes,omitempty"` } // Merge applies default values from the provided policy. func (p *ErrorHandlingPolicy) Merge(src ErrorHandlingPolicy) { - if p.IgnoreFileErrors == nil && src.IgnoreFileErrors != nil { - p.IgnoreFileErrors = newBool(*src.IgnoreFileErrors) - } - - if p.IgnoreDirectoryErrors == nil && src.IgnoreDirectoryErrors != nil { - p.IgnoreDirectoryErrors = newBool(*src.IgnoreDirectoryErrors) - } - - if p.IgnoreUnknownTypes == nil && src.IgnoreUnknownTypes != nil { - p.IgnoreUnknownTypes = newBool(*src.IgnoreUnknownTypes) - } -} - -// IgnoreFileErrorsOrDefault returns the ignore-file-error setting if it is set, -// and returns the passed default if not. -func (p *ErrorHandlingPolicy) IgnoreFileErrorsOrDefault(def bool) bool { - if p.IgnoreFileErrors == nil { - return def - } - - return *p.IgnoreFileErrors -} - -// IgnoreDirectoryErrorsOrDefault returns the ignore-directory-error setting if it is set, -// and returns the passed default if not. -func (p *ErrorHandlingPolicy) IgnoreDirectoryErrorsOrDefault(def bool) bool { - if p.IgnoreDirectoryErrors == nil { - return def - } - - return *p.IgnoreDirectoryErrors -} - -// IgnoreUnknownTypesOrDefault returns the IgnoreUnknownTypes if it is set, -// and returns the passed default if not. -func (p *ErrorHandlingPolicy) IgnoreUnknownTypesOrDefault(def bool) bool { - if p.IgnoreUnknownTypes == nil { - return def - } - - return *p.IgnoreUnknownTypes + mergeOptionalBool(&p.IgnoreFileErrors, src.IgnoreFileErrors) + mergeOptionalBool(&p.IgnoreDirectoryErrors, src.IgnoreDirectoryErrors) + mergeOptionalBool(&p.IgnoreUnknownTypes, src.IgnoreUnknownTypes) } // defaultErrorHandlingPolicy is the default error handling policy. var defaultErrorHandlingPolicy = ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), - IgnoreUnknownTypes: newBool(true), -} - -func newBool(b bool) *bool { - return &b + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), + IgnoreUnknownTypes: newOptionalBool(true), } diff --git a/snapshot/policy/error_handling_policy_test.go b/snapshot/policy/error_handling_policy_test.go index 9ef290411..c341879ce 100644 --- a/snapshot/policy/error_handling_policy_test.go +++ b/snapshot/policy/error_handling_policy_test.go @@ -7,8 +7,8 @@ import ( func TestErrorHandlingPolicyMerge(t *testing.T) { type fields struct { - IgnoreFileErrors *bool - IgnoreDirectoryErrors *bool + IgnoreFileErrors *OptionalBool + IgnoreDirectoryErrors *OptionalBool } type args struct { @@ -46,13 +46,13 @@ func TestErrorHandlingPolicyMerge(t *testing.T) { }, args: args{ src: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), }, }, expResult: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), }, }, { @@ -63,47 +63,47 @@ func TestErrorHandlingPolicyMerge(t *testing.T) { }, args: args{ src: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, }, expResult: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, }, { name: "Starting policy already has a value set at false - expect no change from merged policy", fields: fields{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), }, args: args{ src: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, }, expResult: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), }, }, { name: "Policy being merged has a value set at true - expect no change from merged policy", fields: fields{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, args: args{ src: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(false), - IgnoreDirectoryErrors: newBool(false), + IgnoreFileErrors: newOptionalBool(false), + IgnoreDirectoryErrors: newOptionalBool(false), }, }, expResult: ErrorHandlingPolicy{ - IgnoreFileErrors: newBool(true), - IgnoreDirectoryErrors: newBool(true), + IgnoreFileErrors: newOptionalBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, }, { @@ -115,12 +115,12 @@ func TestErrorHandlingPolicyMerge(t *testing.T) { args: args{ src: ErrorHandlingPolicy{ IgnoreFileErrors: nil, - IgnoreDirectoryErrors: newBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, }, expResult: ErrorHandlingPolicy{ IgnoreFileErrors: nil, - IgnoreDirectoryErrors: newBool(true), + IgnoreDirectoryErrors: newOptionalBool(true), }, }, } { @@ -137,115 +137,3 @@ func TestErrorHandlingPolicyMerge(t *testing.T) { } } } - -func TestErrorHandlingPolicy_IgnoreFileErrorsOrDefault(t *testing.T) { - for _, tt := range []struct { - name string - ignoreFileErrors *bool - def bool - want bool - }{ - { - name: "ignoreFileErrors is nil, default is false", - ignoreFileErrors: nil, - def: false, - want: false, - }, - { - name: "ignoreFileErrors is false, default is false", - ignoreFileErrors: newBool(false), - def: false, - want: false, - }, - { - name: "ignoreFileErrors is true, default is false", - ignoreFileErrors: newBool(true), - def: false, - want: true, - }, - { - name: "ignoreFileErrors is nil, default is true", - ignoreFileErrors: nil, - def: true, - want: true, - }, - { - name: "ignoreFileErrors is false, default is true", - ignoreFileErrors: newBool(false), - def: true, - want: false, - }, - { - name: "ignoreFileErrors is true, default is true", - ignoreFileErrors: newBool(true), - def: true, - want: true, - }, - } { - t.Log(tt.name) - - p := &ErrorHandlingPolicy{ - IgnoreFileErrors: tt.ignoreFileErrors, - } - - if got := p.IgnoreFileErrorsOrDefault(tt.def); got != tt.want { - t.Errorf("ErrorHandlingPolicy.IgnoreFileErrorsOrDefault() = %v, want %v", got, tt.want) - } - } -} - -func TestErrorHandlingPolicy_IgnoreDirectoryErrorsOrDefault(t *testing.T) { - for _, tt := range []struct { - name string - ignoreDirErrors *bool - def bool - want bool - }{ - { - name: "ignoreDirErrors is nil, default is false", - ignoreDirErrors: nil, - def: false, - want: false, - }, - { - name: "ignoreDirErrors is false, default is false", - ignoreDirErrors: newBool(false), - def: false, - want: false, - }, - { - name: "ignoreDirErrors is true, default is false", - ignoreDirErrors: newBool(true), - def: false, - want: true, - }, - { - name: "ignoreDirErrors is nil, default is true", - ignoreDirErrors: nil, - def: true, - want: true, - }, - { - name: "ignoreDirErrors is false, default is true", - ignoreDirErrors: newBool(false), - def: true, - want: false, - }, - { - name: "ignoreDirErrors is true, default is true", - ignoreDirErrors: newBool(true), - def: true, - want: true, - }, - } { - t.Log(tt.name) - - p := &ErrorHandlingPolicy{ - IgnoreDirectoryErrors: tt.ignoreDirErrors, - } - - if got := p.IgnoreDirectoryErrorsOrDefault(tt.def); got != tt.want { - t.Errorf("ErrorHandlingPolicy.IgnoreDirectoryErrorsOrDefault() = %v, want %v", got, tt.want) - } - } -} diff --git a/snapshot/policy/files_policy.go b/snapshot/policy/files_policy.go index 6f5102d95..efefd06de 100644 --- a/snapshot/policy/files_policy.go +++ b/snapshot/policy/files_policy.go @@ -8,11 +8,11 @@ type FilesPolicy struct { DotIgnoreFiles []string `json:"ignoreDotFiles,omitempty"` NoParentDotIgnoreFiles bool `json:"noParentDotFiles,omitempty"` - IgnoreCacheDirs *bool `json:"ignoreCacheDirs,omitempty"` + IgnoreCacheDirectories *OptionalBool `json:"ignoreCacheDirs,omitempty"` MaxFileSize int64 `json:"maxFileSize,omitempty"` - OneFileSystem *bool `json:"oneFileSystem,omitempty"` + OneFileSystem *OptionalBool `json:"oneFileSystem,omitempty"` } // Merge applies default values from the provided policy. @@ -29,8 +29,8 @@ func (p *FilesPolicy) Merge(src FilesPolicy) { p.DotIgnoreFiles = src.DotIgnoreFiles } - if p.IgnoreCacheDirs == nil { - p.IgnoreCacheDirs = src.IgnoreCacheDirs + if p.IgnoreCacheDirectories == nil { + p.IgnoreCacheDirectories = src.IgnoreCacheDirectories } if p.OneFileSystem == nil { @@ -38,24 +38,6 @@ func (p *FilesPolicy) Merge(src FilesPolicy) { } } -// IgnoreCacheDirectoriesOrDefault gets the value of IgnoreCacheDirs or the provided default if not set. -func (p *FilesPolicy) IgnoreCacheDirectoriesOrDefault(def bool) bool { - if p.IgnoreCacheDirs == nil { - return def - } - - return *p.IgnoreCacheDirs -} - -// OneFileSystemOrDefault gets the value of OneFileSystem or the provided default if not set. -func (p *FilesPolicy) OneFileSystemOrDefault(def bool) bool { - if p.OneFileSystem == nil { - return def - } - - return *p.OneFileSystem -} - // defaultFilesPolicy is the default file ignore policy. var defaultFilesPolicy = FilesPolicy{ DotIgnoreFiles: []string{".kopiaignore"}, diff --git a/snapshot/policy/log_detail.go b/snapshot/policy/log_detail.go new file mode 100644 index 000000000..a82bbeb1a --- /dev/null +++ b/snapshot/policy/log_detail.go @@ -0,0 +1,33 @@ +package policy + +// LogDetail represents the details of log output. +type LogDetail int + +// Supported log detail levels. +const ( + LogDetailNone LogDetail = 0 + LogDetailNormal LogDetail = 5 + LogDetailMax LogDetail = 10 +) + +// OrDefault returns the log detail or the provided default. +func (l *LogDetail) OrDefault(def LogDetail) LogDetail { + if l == nil { + return def + } + + return *l +} + +// NewLogDetail returns a pointer to the provided LogDetail. +func NewLogDetail(l LogDetail) *LogDetail { + return &l +} + +func mergeLogLevel(target **LogDetail, src *LogDetail) { + if *target == nil && src != nil { + b := *src + + *target = &b + } +} diff --git a/snapshot/policy/log_detail_test.go b/snapshot/policy/log_detail_test.go new file mode 100644 index 000000000..341f1feb8 --- /dev/null +++ b/snapshot/policy/log_detail_test.go @@ -0,0 +1,30 @@ +package policy_test + +import ( + "encoding/json" + "testing" + + "github.com/stretchr/testify/require" + + "github.com/kopia/kopia/snapshot/policy" +) + +func TestLogDetail(t *testing.T) { + var s1, s2 struct { + V0 policy.LogDetail `json:"v0,omitempty"` + V1 *policy.LogDetail `json:"v1,omitempty"` + V2 policy.LogDetail `json:"v2,omitempty"` + V3 policy.LogDetail `json:"v3,omitempty"` + } + + s1.V1 = policy.NewLogDetail(policy.LogDetailNone) + s1.V2 = policy.LogDetailNormal + s1.V3 = policy.LogDetailMax + + v, err := json.Marshal(s1) + require.NoError(t, err) + require.Equal(t, `{"v1":0,"v2":5,"v3":10}`, string(v)) + + require.NoError(t, json.Unmarshal(v, &s2)) + require.Equal(t, s1, s2) +} diff --git a/snapshot/policy/logging_policy.go b/snapshot/policy/logging_policy.go new file mode 100644 index 000000000..93c138b5c --- /dev/null +++ b/snapshot/policy/logging_policy.go @@ -0,0 +1,55 @@ +package policy + +// DirLoggingPolicy represents the policy for logging directory information when snapshotting. +type DirLoggingPolicy struct { + Snapshotted *LogDetail `json:"snapshotted,omitempty"` + Ignored *LogDetail `json:"ignored,omitempty"` +} + +// Merge merges the provided directory logging policy. +func (p *DirLoggingPolicy) Merge(src DirLoggingPolicy) { + mergeLogLevel(&p.Snapshotted, src.Snapshotted) + mergeLogLevel(&p.Ignored, src.Ignored) +} + +// EntryLoggingPolicy represents the policy for logging entry information when snapshotting. +type EntryLoggingPolicy struct { + Snapshotted *LogDetail `json:"snapshotted,omitempty"` + Ignored *LogDetail `json:"ignored,omitempty"` + CacheHit *LogDetail `json:"cacheHit,omitempty"` + CacheMiss *LogDetail `json:"cacheMiss,omitempty"` +} + +// Merge merges the provided entry logging policy. +func (p *EntryLoggingPolicy) Merge(src EntryLoggingPolicy) { + mergeLogLevel(&p.Snapshotted, src.Snapshotted) + mergeLogLevel(&p.Ignored, src.Ignored) + mergeLogLevel(&p.CacheHit, src.CacheHit) + mergeLogLevel(&p.CacheMiss, src.CacheMiss) +} + +// LoggingPolicy describes policy for emitting logs during snapshots. +type LoggingPolicy struct { + Directories DirLoggingPolicy `json:"directories,omitempty"` + Entries EntryLoggingPolicy `json:"entries,omitempty"` +} + +// Merge applies default values from the provided policy. +func (p *LoggingPolicy) Merge(src LoggingPolicy) { + p.Directories.Merge(src.Directories) + p.Entries.Merge(src.Entries) +} + +// defaultLoggingPolicy is the default logs policy. +var defaultLoggingPolicy = LoggingPolicy{ + Directories: DirLoggingPolicy{ + Snapshotted: NewLogDetail(LogDetailNormal), + Ignored: NewLogDetail(LogDetailNormal), + }, + Entries: EntryLoggingPolicy{ + Snapshotted: NewLogDetail(LogDetailNone), + Ignored: NewLogDetail(LogDetailNormal), + CacheHit: NewLogDetail(LogDetailNone), + CacheMiss: NewLogDetail(LogDetailNone), + }, +} diff --git a/snapshot/policy/optional.go b/snapshot/policy/optional.go new file mode 100644 index 000000000..e9e9d4a66 --- /dev/null +++ b/snapshot/policy/optional.go @@ -0,0 +1,25 @@ +package policy + +// OptionalBool provides convenience methods for manipulating optional booleans. +type OptionalBool bool + +// OrDefault returns the value of the boolean or provided default if it's nil. +func (b *OptionalBool) OrDefault(def bool) bool { + if b == nil { + return def + } + + return bool(*b) +} + +func newOptionalBool(b OptionalBool) *OptionalBool { + return &b +} + +func mergeOptionalBool(target **OptionalBool, src *OptionalBool) { + if *target == nil && src != nil { + v := *src + + *target = &v + } +} diff --git a/snapshot/policy/policy.go b/snapshot/policy/policy.go index a1e0ab0f9..903a3bc1c 100644 --- a/snapshot/policy/policy.go +++ b/snapshot/policy/policy.go @@ -28,6 +28,7 @@ type Policy struct { SchedulingPolicy SchedulingPolicy `json:"scheduling,omitempty"` CompressionPolicy CompressionPolicy `json:"compression,omitempty"` Actions ActionsPolicy `json:"actions"` + LoggingPolicy LoggingPolicy `json:"logging"` NoParent bool `json:"noParent,omitempty"` } @@ -73,6 +74,7 @@ func MergePolicies(policies []*Policy) *Policy { merged.SchedulingPolicy.Merge(p.SchedulingPolicy) merged.CompressionPolicy.Merge(p.CompressionPolicy) merged.Actions.Merge(p.Actions) + merged.LoggingPolicy.Merge(p.LoggingPolicy) } // Merge default expiration policy. @@ -82,6 +84,7 @@ func MergePolicies(policies []*Policy) *Policy { merged.SchedulingPolicy.Merge(defaultSchedulingPolicy) merged.CompressionPolicy.Merge(defaultCompressionPolicy) merged.Actions.Merge(defaultActionsPolicy) + merged.LoggingPolicy.Merge(defaultLoggingPolicy) if len(policies) > 0 { merged.Actions.MergeNonInheritable(policies[0].Actions) diff --git a/snapshot/policy/policy_tree.go b/snapshot/policy/policy_tree.go index 4cd69b6f8..88a44eccc 100644 --- a/snapshot/policy/policy_tree.go +++ b/snapshot/policy/policy_tree.go @@ -11,6 +11,7 @@ var DefaultPolicy = &Policy{ CompressionPolicy: defaultCompressionPolicy, ErrorHandlingPolicy: defaultErrorHandlingPolicy, SchedulingPolicy: defaultSchedulingPolicy, + LoggingPolicy: defaultLoggingPolicy, Actions: defaultActionsPolicy, } diff --git a/snapshot/snapshotfs/estimate.go b/snapshot/snapshotfs/estimate.go index fa299a600..2da218d16 100644 --- a/snapshot/snapshotfs/estimate.go +++ b/snapshot/snapshotfs/estimate.go @@ -82,7 +82,7 @@ func Estimate(ctx context.Context, rep repo.Repository, entry fs.Directory, poli progress.Stats(ctx, stats, ib, eb, ed, true) }() - onIgnoredFile := func(relativePath string, e fs.Entry) { + onIgnoredFile := func(ctx context.Context, relativePath string, e fs.Entry, pol *policy.Tree) { if e.IsDir() { if len(ed) < maxExamplesPerBucket { ed = append(ed, relativePath) @@ -90,9 +90,9 @@ func Estimate(ctx context.Context, rep repo.Repository, entry fs.Directory, poli stats.ExcludedDirCount++ - log(ctx).Debugf("excluded dir %v", relativePath) + estimateLog(ctx).Debugf("excluded dir %v", relativePath) } else { - log(ctx).Debugf("excluded file %v (%v)", relativePath, units.BytesStringBase10(e.Size())) + estimateLog(ctx).Debugf("excluded file %v (%v)", relativePath, units.BytesStringBase10(e.Size())) stats.ExcludedFileCount++ stats.ExcludedTotalFileSize += e.Size() eb.add(relativePath, e.Size(), maxExamplesPerBucket) @@ -122,7 +122,7 @@ func estimate(ctx context.Context, relativePath string, entry fs.Entry, policyTr children, err := entry.Readdir(ctx) if err != nil { - isIgnored := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreDirectoryErrorsOrDefault(false) + isIgnored := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreDirectoryErrors.OrDefault(false) if isIgnored { stats.IgnoredErrorCount++ diff --git a/snapshot/snapshotfs/objref.go b/snapshot/snapshotfs/objref.go index b05bfe393..60f69867a 100644 --- a/snapshot/snapshotfs/objref.go +++ b/snapshot/snapshotfs/objref.go @@ -102,7 +102,7 @@ func findSnapshotByRootObjectIDOrManifestID(ctx context.Context, rep repo.Reposi return nil, errors.Errorf("found multiple snapshots matching %v with inconsistent root attributes.", rootID) } - log(ctx).Debugf("Found multiple snapshots matching %v with inconsistent root attributes. Picking latest one.", rootID) + repoFSLog(ctx).Debugf("Found multiple snapshots matching %v with inconsistent root attributes. Picking latest one.", rootID) return latestManifest(mans), nil } @@ -203,7 +203,7 @@ func GetEntryFromPlaceholder(ctx context.Context, r repo.Repository, defp snapsh return nil, errors.Wrap(err, "unable to get direntry from placeholder") } - log(ctx).Debugf("GetDirEntryFromPlaceholder %v %v ", r, de) + repoFSLog(ctx).Debugf("GetDirEntryFromPlaceholder %v %v ", r, de) return EntryFromDirEntry(r, de), nil } diff --git a/snapshot/snapshotfs/repofs.go b/snapshot/snapshotfs/repofs.go index e29ee2640..3d14cf110 100644 --- a/snapshot/snapshotfs/repofs.go +++ b/snapshot/snapshotfs/repofs.go @@ -246,7 +246,7 @@ func AutoDetectEntryFromObjectID(ctx context.Context, rep repo.Repository, oid o if IsDirectoryID(oid) { dirEntry := DirectoryEntry(rep, oid, nil) if _, err := dirEntry.Readdir(ctx); err == nil { - log(ctx).Debugf("%v auto-detected as directory", oid) + repoFSLog(ctx).Debugf("%v auto-detected as directory", oid) return dirEntry } } @@ -263,7 +263,7 @@ func AutoDetectEntryFromObjectID(ctx context.Context, rep repo.Repository, oid o r.Close() //nolint:errcheck } - log(ctx).Debugf("%v auto-detected as a file with name %v and size %v", oid, maybeName, fileSize) + repoFSLog(ctx).Debugf("%v auto-detected as a file with name %v and size %v", oid, maybeName, fileSize) f := EntryFromDirEntry(rep, &snapshot.DirEntry{ Name: maybeName, diff --git a/snapshot/snapshotfs/snapshot_tree_walker.go b/snapshot/snapshotfs/snapshot_tree_walker.go index e0a000894..a72ac7627 100644 --- a/snapshot/snapshotfs/snapshot_tree_walker.go +++ b/snapshot/snapshotfs/snapshot_tree_walker.go @@ -63,7 +63,7 @@ func (w *TreeWalker) Run(ctx context.Context) error { } w.queue.ProgressCallback = func(ctx context.Context, enqueued, active, completed int64) { - log(ctx).Infof(" Processed %v contents, discovered %v...", completed, enqueued) + repoFSLog(ctx).Infof(" Processed %v contents, discovered %v...", completed, enqueued) } // nolint:wrapcheck diff --git a/snapshot/snapshotfs/upload.go b/snapshot/snapshotfs/upload.go index d56a0ce4b..6b5fee1bc 100644 --- a/snapshot/snapshotfs/upload.go +++ b/snapshot/snapshotfs/upload.go @@ -22,6 +22,7 @@ import ( "github.com/kopia/kopia/fs/ignorefs" "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/iocopy" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo" "github.com/kopia/kopia/repo/logging" "github.com/kopia/kopia/repo/object" @@ -32,7 +33,20 @@ import ( // DefaultCheckpointInterval is the default frequency of mid-upload checkpointing. const DefaultCheckpointInterval = 45 * time.Minute -var log = logging.Module("snapshotfs") +var ( + uploadLog = logging.Module("uploader") + estimateLog = logging.Module("estimate") + repoFSLog = logging.Module("repofs") +) + +// minimal detail levels to emit particular pieces of log information. +const ( + minDetailLevelDuration = 1 + minDetailLevelSize = 3 + minDetailLevelDirStats = 5 + minDetailLevelModTime = 6 + minDetailLevelOID = 7 +) var errCanceled = errors.New("canceled") @@ -64,6 +78,10 @@ type Uploader struct { // Enable snapshot actions EnableActions bool + // override the directory log level and entry log verbosity. + OverrideDirLogDetail *policy.LogDetail + OverrideEntryLogDetail *policy.LogDetail + // Fail the entire snapshot on source file/directory error. FailFast bool @@ -395,7 +413,7 @@ func (u *Uploader) checkpointRoot(ctx context.Context, cp *checkpointRegistry, p rootEntry := checkpointManifest.Entries[0] - log(ctx).Debugf("checkpointed root %v", rootEntry.ObjectID) + uploadLog(ctx).Debugf("checkpointed root %v", rootEntry.ObjectID) man := *prototypeManifest man.RootEntry = rootEntry @@ -432,7 +450,7 @@ func (u *Uploader) periodicallyCheckpoint(ctx context.Context, cp *checkpointReg case <-ch: if err := u.checkpointRoot(ctx, cp, prototypeManifest); err != nil { - log(ctx).Errorf("error checkpointing: %v", err) + uploadLog(ctx).Errorf("error checkpointing: %v", err) u.Cancel() return @@ -471,7 +489,7 @@ func (u *Uploader) uploadDirWithCheckpointing(ctx context.Context, rootDir fs.Di } if overrideDir != nil { - rootDir = u.wrapIgnorefs(overrideDir, policyTree) + rootDir = u.wrapIgnorefs(uploadLog(ctx), overrideDir, policyTree) } defer u.executeAfterFolderAction(ctx, "after-snapshot-root", policyTree.EffectivePolicy().Actions.AfterSnapshotRoot, localDirPathOrEmpty, &hc) @@ -742,7 +760,7 @@ func (u *Uploader) processSubdirectories( var dre dirReadError if errors.As(err, &dre) { u.reportErrorAndMaybeCancel(dre.error, - childTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreDirectoryErrorsOrDefault(false), + childTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreDirectoryErrors.OrDefault(false), parentDirBuilder, entryRelativePath) } else { @@ -776,18 +794,29 @@ func metadataEquals(e1, e2 fs.Entry) bool { return true } -func findCachedEntry(ctx context.Context, entry fs.Entry, prevEntries []fs.Entries) fs.Entry { +func findCachedEntry(ctx context.Context, entryRelativePath string, entry fs.Entry, prevEntries []fs.Entries, pol *policy.Tree) fs.Entry { + var missedEntry fs.Entry + for _, e := range prevEntries { if ent := e.FindByName(entry.Name()); ent != nil { if metadataEquals(entry, ent) { return ent } - log(ctx).Debugf("found non-matching entry for %v: %v %v %v", entry.Name(), ent.Mode(), ent.Size(), ent.ModTime()) + missedEntry = ent } } - log(ctx).Debugf("could not find cache entry for %v", entry.Name()) + if missedEntry != nil { + if pol.EffectivePolicy().LoggingPolicy.Entries.CacheMiss.OrDefault(policy.LogDetailNone) >= policy.LogDetailNormal { + uploadLog(ctx).Debugw( + "cache miss", + "path", entryRelativePath, + "mode", missedEntry.Mode().String(), + "size", missedEntry.Size(), + "mtime", missedEntry.ModTime()) + } + } return nil } @@ -795,7 +824,7 @@ func findCachedEntry(ctx context.Context, entry fs.Entry, prevEntries []fs.Entri func (u *Uploader) maybeIgnoreCachedEntry(ctx context.Context, ent fs.Entry) fs.Entry { if h, ok := ent.(object.HasObjectID); ok { if 100*rand.Float64() < u.ForceHashPercentage { // nolint:gosec - log(ctx).Debugf("re-hashing cached object: %v", h.ObjectID()) + uploadLog(ctx).Debugw("re-hashing cached object", "oid", h.ObjectID()) return nil } @@ -814,6 +843,7 @@ func (u *Uploader) effectiveParallelUploads() int { return p } +// nolint:funlen func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRegistry *checkpointRegistry, parentDirBuilder *dirManifestBuilder, dirRelativePath string, entries fs.Entries, policyTree *policy.Tree, prevEntries []fs.Entries) error { workerCount := u.effectiveParallelUploads() @@ -837,8 +867,10 @@ func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRe return nil } + t0 := timetrack.StartTimer() + // See if we had this name during either of previous passes. - if cachedEntry := u.maybeIgnoreCachedEntry(ctx, findCachedEntry(ctx, entry, prevEntries)); cachedEntry != nil { + if cachedEntry := u.maybeIgnoreCachedEntry(ctx, findCachedEntry(ctx, entryRelativePath, entry, prevEntries, policyTree)); cachedEntry != nil { atomic.AddInt32(&u.stats.CachedFiles, 1) atomic.AddInt64(&u.stats.TotalFileSize, entry.Size()) u.Progress.CachedFile(filepath.Join(dirRelativePath, entry.Name()), entry.Size()) @@ -849,7 +881,13 @@ func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRe return errors.Wrap(err, "unable to create dir entry") } + maybeLogEntryProcessed( + uploadLog(ctx), + u.OverrideEntryLogDetail.OrDefault(policyTree.EffectivePolicy().LoggingPolicy.Entries.CacheHit.OrDefault(policy.LogDetailNone)), + "cached", entryRelativePath, cachedDirEntry, nil, t0) + parentDirBuilder.addEntry(cachedDirEntry) + return nil } @@ -857,13 +895,18 @@ func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRe case fs.Symlink: de, err := u.uploadSymlinkInternal(ctx, entryRelativePath, entry) if err != nil { - isIgnoredError := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrorsOrDefault(false) + isIgnoredError := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrors.OrDefault(false) u.reportErrorAndMaybeCancel(err, isIgnoredError, parentDirBuilder, entryRelativePath) } else { parentDirBuilder.addEntry(de) } + maybeLogEntryProcessed( + uploadLog(ctx), + u.OverrideEntryLogDetail.OrDefault(policyTree.EffectivePolicy().LoggingPolicy.Entries.Snapshotted.OrDefault(policy.LogDetailNone)), + "snapshotted symlink", entryRelativePath, de, err, t0) + return nil case fs.File: @@ -871,23 +914,39 @@ func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRe de, err := u.uploadFileInternal(ctx, parentCheckpointRegistry, entryRelativePath, entry, policyTree.Child(entry.Name()).EffectivePolicy(), asyncWritesPerFile) if err != nil { - isIgnoredError := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrorsOrDefault(false) + isIgnoredError := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrors.OrDefault(false) u.reportErrorAndMaybeCancel(err, isIgnoredError, parentDirBuilder, entryRelativePath) } else { parentDirBuilder.addEntry(de) } + maybeLogEntryProcessed( + uploadLog(ctx), + u.OverrideEntryLogDetail.OrDefault(policyTree.EffectivePolicy().LoggingPolicy.Entries.Snapshotted.OrDefault(policy.LogDetailNone)), + "snapshotted file", entryRelativePath, de, nil, t0) + return nil case fs.ErrorEntry: - var isIgnoredError bool + var ( + isIgnoredError bool + prefix string + ) + if errors.Is(entry.ErrorInfo(), fs.ErrUnknown) { - isIgnoredError = policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreUnknownTypesOrDefault(true) + isIgnoredError = policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreUnknownTypes.OrDefault(true) + prefix = "unknown entry" } else { - isIgnoredError = policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrorsOrDefault(false) + isIgnoredError = policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrors.OrDefault(false) + prefix = "error" } + maybeLogEntryProcessed( + uploadLog(ctx), + u.OverrideEntryLogDetail.OrDefault(policyTree.EffectivePolicy().LoggingPolicy.Entries.Snapshotted.OrDefault(policy.LogDetailNone)), + prefix, entryRelativePath, nil, entry.ErrorInfo(), t0) + u.reportErrorAndMaybeCancel(entry.ErrorInfo(), isIgnoredError, parentDirBuilder, entryRelativePath) return nil @@ -897,13 +956,17 @@ func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRe de, err := u.uploadStreamingFileInternal(ctx, entryRelativePath, entry) if err != nil { - isIgnoredError := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrorsOrDefault(false) + isIgnoredError := policyTree.EffectivePolicy().ErrorHandlingPolicy.IgnoreFileErrors.OrDefault(false) u.reportErrorAndMaybeCancel(err, isIgnoredError, parentDirBuilder, entryRelativePath) } else { parentDirBuilder.addEntry(de) } + maybeLogEntryProcessed( + uploadLog(ctx), u.OverrideEntryLogDetail.OrDefault(policyTree.EffectivePolicy().LoggingPolicy.Entries.Snapshotted.OrDefault(policy.LogDetailNone)), + "snapshotted streaming file", entryRelativePath, de, nil, t0) + return nil default: @@ -912,6 +975,64 @@ func (u *Uploader) processNonDirectories(ctx context.Context, parentCheckpointRe }) } +func maybeLogEntryProcessed(logger logging.Logger, level policy.LogDetail, msg, relativePath string, de *snapshot.DirEntry, err error, timer timetrack.Timer) { + if level <= policy.LogDetailNone && err == nil { + return + } + + var ( + bitsBuf [10]interface{} + keyValuePairs = append(bitsBuf[:0], "path", relativePath) + ) + + if err != nil { + keyValuePairs = append(keyValuePairs, "error", err.Error()) + } + + if level >= minDetailLevelDuration { + keyValuePairs = append(keyValuePairs, "dur", timer.Elapsed()) + } + + // nolint:nestif + if de != nil { + if level >= minDetailLevelSize { + if ds := de.DirSummary; ds != nil { + keyValuePairs = append(keyValuePairs, "size", ds.TotalFileSize) + } else { + keyValuePairs = append(keyValuePairs, "size", de.FileSize) + } + } + + if level >= minDetailLevelDirStats { + if ds := de.DirSummary; ds != nil { + keyValuePairs = append(keyValuePairs, + "files", ds.TotalFileCount, + "dirs", ds.TotalDirCount, + "errors", ds.IgnoredErrorCount+ds.FatalErrorCount, + ) + } + } + + if level >= minDetailLevelModTime { + if ds := de.DirSummary; ds != nil { + keyValuePairs = append(keyValuePairs, + "mtime", ds.MaxModTime.Format(time.RFC3339), + ) + } else { + keyValuePairs = append(keyValuePairs, + "mtime", de.ModTime.Format(time.RFC3339), + ) + } + } + + if level >= minDetailLevelOID { + keyValuePairs = append(keyValuePairs, "oid", de.ObjectID) + } + } + + logger.Debugw(msg, keyValuePairs...) +} + func maybeReadDirectoryEntries(ctx context.Context, dir fs.Directory) fs.Entries { if dir == nil { return nil @@ -919,7 +1040,7 @@ func maybeReadDirectoryEntries(ctx context.Context, dir fs.Directory) fs.Entries ent, err := dir.Readdir(ctx) if err != nil { - log(ctx).Errorf("unable to read previous directory entries: %v", err) + uploadLog(ctx).Errorf("unable to read previous directory entries: %v", err) return nil } @@ -979,9 +1100,18 @@ func uploadDirInternal( localDirPathOrEmpty, dirRelativePath string, thisDirBuilder *dirManifestBuilder, thisCheckpointRegistry *checkpointRegistry, -) (*snapshot.DirEntry, error) { +) (resultDE *snapshot.DirEntry, resultErr error) { atomic.AddInt32(&u.stats.TotalDirectoryCount, 1) + t0 := timetrack.StartTimer() + + defer func() { + maybeLogEntryProcessed( + uploadLog(ctx), + u.OverrideDirLogDetail.OrDefault(policyTree.EffectivePolicy().LoggingPolicy.Directories.Snapshotted.OrDefault(policy.LogDetailNone)), + "snapshotted directory", dirRelativePath, resultDE, resultErr, t0) + }() + u.Progress.StartedDirectory(dirRelativePath) defer u.Progress.FinishedDirectory(dirRelativePath) @@ -1002,16 +1132,14 @@ func uploadDirInternal( defer u.executeAfterFolderAction(ctx, "after-folder", definedActions.AfterFolder, localDirPathOrEmpty, &hc) if overrideDir != nil { - directory = u.wrapIgnorefs(overrideDir, policyTree) + directory = u.wrapIgnorefs(uploadLog(ctx), overrideDir, policyTree) } if de, err := uploadShallowDirInternal(ctx, directory, u); de != nil || err != nil { return de, err } - t0 := u.repo.Time() entries, direrr := directory.Readdir(ctx) - log(ctx).Debugf("finished reading directory %v in %v", dirRelativePath, u.repo.Time().Sub(t0)) if direrr != nil { return nil, dirReadError{direrr} @@ -1123,7 +1251,7 @@ func (u *Uploader) maybeOpenDirectoryFromManifest(ctx context.Context, man *snap dir, ok := ent.(fs.Directory) if !ok { - log(ctx).Debugf("previous manifest root is not a directory (was %T %+v)", ent, man.RootEntry) + uploadLog(ctx).Debugf("previous manifest root is not a directory (was %T %+v)", ent, man.RootEntry) return nil } @@ -1139,7 +1267,7 @@ func (u *Uploader) Upload( sourceInfo snapshot.SourceInfo, previousManifests ...*snapshot.Manifest, ) (*snapshot.Manifest, error) { - log(ctx).Debugf("Uploading %v", sourceInfo) + uploadLog(ctx).Debugf("Uploading %v", sourceInfo) s := &snapshot.Manifest{ Source: sourceInfo, @@ -1174,17 +1302,19 @@ func (u *Uploader) Upload( scanWG.Add(1) - entry = u.wrapIgnorefs(entry, policyTree) - go func() { defer scanWG.Done() - ds, _ := u.scanDirectory(scanctx, entry, policyTree) + wrapped := u.wrapIgnorefs(estimateLog(ctx), entry, policyTree) + + ds, _ := u.scanDirectory(scanctx, wrapped, policyTree) u.Progress.EstimatedDataSize(ds.numFiles, ds.totalFileSize) }() - s.RootEntry, err = u.uploadDirWithCheckpointing(ctx, entry, policyTree, previousDirs, sourceInfo) + wrapped := u.wrapIgnorefs(uploadLog(ctx), entry, policyTree) + + s.RootEntry, err = u.uploadDirWithCheckpointing(ctx, wrapped, policyTree, previousDirs, sourceInfo) case fs.File: u.Progress.EstimatedDataSize(1, entry.Size()) @@ -1208,15 +1338,25 @@ func (u *Uploader) Upload( return s, nil } -func (u *Uploader) wrapIgnorefs(entry fs.Directory, policyTree *policy.Tree) fs.Directory { +func (u *Uploader) wrapIgnorefs(logger logging.Logger, entry fs.Directory, policyTree *policy.Tree) fs.Directory { if u.DisableIgnoreRules { return entry } - return ignorefs.New(entry, policyTree, ignorefs.ReportIgnoredFiles(func(fname string, md fs.Entry) { + return ignorefs.New(entry, policyTree, ignorefs.ReportIgnoredFiles(func(ctx context.Context, fname string, md fs.Entry, policyTree *policy.Tree) { if md.IsDir() { + maybeLogEntryProcessed( + logger, + policyTree.EffectivePolicy().LoggingPolicy.Directories.Ignored.OrDefault(policy.LogDetailNone), + "ignored directory", fname, nil, nil, timetrack.StartTimer()) + u.Progress.ExcludedDir(fname) } else { + maybeLogEntryProcessed( + logger, + policyTree.EffectivePolicy().LoggingPolicy.Entries.Ignored.OrDefault(policy.LogDetailNone), + "ignored", fname, nil, nil, timetrack.StartTimer()) + u.Progress.ExcludedFile(fname, md.Size()) } diff --git a/snapshot/snapshotfs/upload_actions.go b/snapshot/snapshotfs/upload_actions.go index 251c15cfc..b5c72533a 100644 --- a/snapshot/snapshotfs/upload_actions.go +++ b/snapshot/snapshotfs/upload_actions.go @@ -56,7 +56,7 @@ func (hc *actionContext) ensureInitialized(ctx context.Context, actionType, dirP } if !uploaderEnabled { - log(ctx).Infof("Not executing %v action on %v because it's been disabled for this client.", actionType, dirPathOrEmpty) + uploadLog(ctx).Infof("Not executing %v action on %v because it's been disabled for this client.", actionType, dirPathOrEmpty) return nil } @@ -166,7 +166,7 @@ func runActionCommand( return errors.Wrap(err, "essential action failed") } - log(ctx).Errorf("error running non-essential action command: %v", err) + uploadLog(ctx).Errorf("error running non-essential action command: %v", err) } return parseCaptures(v, captures) @@ -206,7 +206,7 @@ func (u *Uploader) executeBeforeFolderAction(ctx context.Context, actionType str return nil, nil } - log(ctx).Debugf("running action %v on %v %#v", actionType, hc.SourcePath, *h) + uploadLog(ctx).Debugf("running action %v on %v %#v", actionType, hc.SourcePath, *h) captures := map[string]string{ "KOPIA_SNAPSHOT_PATH": "", @@ -232,7 +232,7 @@ func (u *Uploader) executeAfterFolderAction(ctx context.Context, actionType stri } if err := hc.ensureInitialized(ctx, actionType, dirPathOrEmpty, u.EnableActions); err != nil { - log(ctx).Errorf("error initializing action context: %v", err) + uploadLog(ctx).Errorf("error initializing action context: %v", err) } if !hc.ActionsEnabled { @@ -240,14 +240,14 @@ func (u *Uploader) executeAfterFolderAction(ctx context.Context, actionType stri } if err := runActionCommand(ctx, actionType, h, hc.envars(actionType), nil, hc.WorkDir); err != nil { - log(ctx).Errorf("error running '%v' action: %v", actionType, err) + uploadLog(ctx).Errorf("error running '%v' action: %v", actionType, err) } } func cleanupActionContext(ctx context.Context, hc *actionContext) { if hc.WorkDir != "" { if err := os.RemoveAll(hc.WorkDir); err != nil { - log(ctx).Debugf("unable to remove action working directory: %v", err) + uploadLog(ctx).Debugf("unable to remove action working directory: %v", err) } } } diff --git a/snapshot/snapshotfs/upload_test.go b/snapshot/snapshotfs/upload_test.go index ce721cfe7..6dc89937d 100644 --- a/snapshot/snapshotfs/upload_test.go +++ b/snapshot/snapshotfs/upload_test.go @@ -2,9 +2,11 @@ package snapshotfs import ( "context" + "fmt" "os" "path/filepath" "reflect" + "sort" "testing" "time" @@ -21,6 +23,7 @@ import ( "github.com/kopia/kopia/internal/testutil" "github.com/kopia/kopia/repo" "github.com/kopia/kopia/repo/blob/filesystem" + "github.com/kopia/kopia/repo/logging" "github.com/kopia/kopia/repo/object" "github.com/kopia/kopia/snapshot" "github.com/kopia/kopia/snapshot/policy" @@ -60,7 +63,7 @@ func newUploadTestHarness(ctx context.Context, t *testing.T) *uploadTestHarness panic("unable to create repository: " + initerr.Error()) } - log(ctx).Debugf("repo dir: %v", repoDir) + t.Logf("repo dir: %v", repoDir) configFile := filepath.Join(repoDir, ".kopia.config") if conerr := repo.Connect(ctx, configFile, storage, masterPassword, nil); conerr != nil { @@ -118,7 +121,7 @@ func TestUpload(t *testing.T) { defer th.cleanup() - log(ctx).Infof("Uploading s1") + t.Logf("Uploading s1") u := NewUploader(th.repo) @@ -129,9 +132,9 @@ func TestUpload(t *testing.T) { t.Errorf("Upload error: %v", err) } - log(ctx).Infof("s1: %v", s1.RootEntry) + t.Logf("s1: %v", s1.RootEntry) - log(ctx).Infof("Uploading s2") + t.Logf("Uploading s2") s2, err := u.Upload(ctx, th.sourceDir, policyTree, snapshot.SourceInfo{}, s1) if err != nil { @@ -273,7 +276,7 @@ func TestUpload_SubDirectoryReadFailureIgnoredNoFailFast(t *testing.T) { u := NewUploader(th.repo) - trueValue := true + trueValue := policy.OptionalBool(true) policyTree := policy.BuildTree(nil, &policy.Policy{ ErrorHandlingPolicy: policy.ErrorHandlingPolicy{ @@ -306,8 +309,8 @@ func TestUpload_ErrorEntries(t *testing.T) { th.sourceDir.Subdir("d1").AddErrorEntry("some-failed-entry", 0, errors.Errorf("some-other-error")) th.sourceDir.Subdir("d2").AddErrorEntry("another-failed-entry", os.ModeIrregular, errors.Errorf("another-error")) - trueValue := true - falseValue := false + trueValue := policy.OptionalBool(true) + falseValue := policy.OptionalBool(false) cases := []struct { desc string @@ -453,7 +456,7 @@ func TestUpload_SubDirectoryReadFailureSomeIgnoredNoFailFast(t *testing.T) { u := NewUploader(th.repo) - trueValue := true + trueValue := policy.OptionalBool(true) // set up a policy tree where errors from d3 are ignored. policyTree := policy.BuildTree(map[string]*policy.Policy{ @@ -465,7 +468,7 @@ func TestUpload_SubDirectoryReadFailureSomeIgnoredNoFailFast(t *testing.T) { }, }, policy.DefaultPolicy) - if got, want := policyTree.Child("d3").EffectivePolicy().ErrorHandlingPolicy.IgnoreDirectoryErrorsOrDefault(false), true; got != want { + if got, want := policyTree.Child("d3").EffectivePolicy().ErrorHandlingPolicy.IgnoreDirectoryErrors.OrDefault(false), true; got != want { t.Fatalf("policy not effective") } @@ -619,7 +622,7 @@ func TestUpload_VirtualDirectoryWithStreamingFile(t *testing.T) { defer th.cleanup() - log(ctx).Infof("Uploading static directory with streaming file") + t.Logf("Uploading static directory with streaming file") u := NewUploader(th.repo) @@ -667,3 +670,373 @@ func TestUpload_VirtualDirectoryWithStreamingFile(t *testing.T) { t.Fatalf("unexpected manifest file count: %v, want %v", got, want) } } + +type mockLogger struct { + logging.Logger + + logged []loggedAction +} + +func (l *mockLogger) Debugw(msg string, keysAndValues ...interface{}) { + m := map[string]interface{}{} + + for i := 0; i+1 < len(keysAndValues); i += 2 { + s, ok := keysAndValues[i].(string) + if !ok { + panic("not a string key") + } + + m[s] = keysAndValues[i+1] + } + + l.logged = append(l.logged, loggedAction{msg, m}) +} + +type loggedAction struct { + msg string + keysAndValues map[string]interface{} +} + +func TestUploadLogging(t *testing.T) { + sourceDir := mockfs.NewDirectory() + sourceDir.AddFile("f1", []byte{1, 2, 3}, defaultPermissions) + sourceDir.AddFile("f2", []byte{1, 2, 3, 4}, defaultPermissions) + sourceDir.AddFile("f3", []byte{1, 2, 3, 4, 5}, defaultPermissions) + sourceDir.AddSymlink("f4", "f2", defaultPermissions) + sourceDir.AddErrorEntry("f5", defaultPermissions, errors.New("some error")) + + sourceDir.AddDir("d1", defaultPermissions) + sourceDir.AddDir("d1/d3", defaultPermissions) + sourceDir.AddFile("d1/d3/f1", []byte{1, 2, 3}, defaultPermissions) + sourceDir.AddFile("d1/d3/f2", []byte{1, 2, 3, 4}, defaultPermissions) + sourceDir.AddSymlink("d1/d3/f3", "f1", defaultPermissions) + + cases := []struct { + desc string + globalLoggingPolicy *policy.LoggingPolicy + globalFilesPolicy *policy.FilesPolicy + dirLogDetail *policy.LogDetail + entryLogDetail *policy.LogDetail + wantEntries []string + wantEntriesSecond []string + wantDetailKeys map[string][]string + }{ + { + desc: "override-logging disabled", + dirLogDetail: policy.NewLogDetail(0), + entryLogDetail: policy.NewLogDetail(0), + wantEntries: []string{ + // errors are always logged + "error f5", + }, + wantEntriesSecond: []string{ + // errors are always logged + "error f5", + }, + wantDetailKeys: map[string][]string{ + "cached": {"dur", "path"}, + "error": {"error", "path"}, + }, + }, + { + desc: "override-minimal logging", + dirLogDetail: policy.NewLogDetail(1), + entryLogDetail: policy.NewLogDetail(1), + wantEntries: []string{ + "snapshotted file d1/d3/f1", + "snapshotted file d1/d3/f2", + "snapshotted symlink d1/d3/f3", + "snapshotted directory d1/d3", + "snapshotted directory d1", + "snapshotted file f1", + "snapshotted file f2", + "snapshotted file f3", + "snapshotted symlink f4", + "error f5", + "snapshotted directory .", + }, + wantEntriesSecond: []string{ + "cached d1/d3/f1", + "cached d1/d3/f2", + "cached d1/d3/f3", + "snapshotted directory d1/d3", + "snapshotted directory d1", + "cached f1", + "cached f2", + "cached f3", + "cached f4", + "error f5", + "snapshotted directory .", + }, + // at level 1 only durations and paths are logged + wantDetailKeys: map[string][]string{ + "cached": {"dur", "path"}, + "error": {"path", "error", "dur"}, + "snapshotted file": {"path", "dur"}, + "snapshotted directory": {"path", "dur"}, + "snapshotted symlink": {"path", "dur"}, + }, + }, + // only directories are logged + { + desc: "override-directory-only-logging", + dirLogDetail: policy.NewLogDetail(policy.LogDetailMax), + entryLogDetail: policy.NewLogDetail(0), + wantEntries: []string{ + "snapshotted directory d1/d3", + "snapshotted directory d1", + "error f5", + "snapshotted directory .", + }, + wantEntriesSecond: []string{ + "snapshotted directory d1/d3", + "snapshotted directory d1", + "error f5", + "snapshotted directory .", + }, + // at level 10 a lot of details are logged. + wantDetailKeys: map[string][]string{ + "error": {"path", "error"}, + "snapshotted directory": {"dirs", "dur", "errors", "files", "mtime", "oid", "path", "size"}, + }, + }, + // only entries are scheduled. + { + desc: "override-entry-only-logging", + dirLogDetail: policy.NewLogDetail(0), + entryLogDetail: policy.NewLogDetail(policy.LogDetailMax), + wantEntries: []string{ + "snapshotted file d1/d3/f1", + "snapshotted file d1/d3/f2", + "snapshotted symlink d1/d3/f3", + "snapshotted file f1", + "snapshotted file f2", + "snapshotted file f3", + "snapshotted symlink f4", + "error f5", + }, + wantEntriesSecond: []string{ + "cached d1/d3/f1", + "cached d1/d3/f2", + "cached d1/d3/f3", + "cached f1", + "cached f2", + "cached f3", + "cached f4", + "error f5", + }, + // at level 10 a lot of details are logged. + wantDetailKeys: map[string][]string{ + "cached": {"dur", "mtime", "oid", "path", "size"}, + "error": {"dur", "error", "path"}, + "snapshotted file": {"dur", "mtime", "oid", "path", "size"}, + "snapshotted symlink": {"dur", "mtime", "oid", "path", "size"}, + }, + }, + { + desc: "default-policy", + wantDetailKeys: map[string][]string{ + "cached": {"dur", "mtime", "oid", "path", "size"}, + "error": {"error", "path"}, + "snapshotted file": {"dur", "path", "size"}, + "snapshotted symlink": {"dur", "path", "size"}, + "snapshotted directory": {"dirs", "dur", "errors", "files", "path", "size"}, + }, + wantEntries: []string{ + "snapshotted directory d1/d3", + "snapshotted directory d1", + "error f5", + "snapshotted directory .", + }, + // cache hits are not logged + wantEntriesSecond: []string{ + "snapshotted directory d1/d3", + "snapshotted directory d1", + "error f5", + "snapshotted directory .", + }, + }, + { + desc: "global-logging-policy", + globalLoggingPolicy: &policy.LoggingPolicy{ + Directories: policy.DirLoggingPolicy{ + Snapshotted: policy.NewLogDetail(3), + }, + Entries: policy.EntryLoggingPolicy{ + Snapshotted: policy.NewLogDetail(3), + }, + }, + wantDetailKeys: map[string][]string{ + "cached": {"dur", "mtime", "oid", "path", "size"}, + "error": {"dur", "error", "path"}, + "snapshotted file": {"dur", "path", "size"}, + "snapshotted symlink": {"dur", "path", "size"}, + "snapshotted directory": {"dur", "path", "size"}, + }, + wantEntries: []string{ + "snapshotted file d1/d3/f1", + "snapshotted file d1/d3/f2", + "snapshotted symlink d1/d3/f3", + "snapshotted directory d1/d3", + "snapshotted directory d1", + "snapshotted file f1", + "snapshotted file f2", + "snapshotted file f3", + "snapshotted symlink f4", + "error f5", + "snapshotted directory .", + }, + // cache hits are not logged + wantEntriesSecond: []string{ + "snapshotted directory d1/d3", + "snapshotted directory d1", + "error f5", + "snapshotted directory .", + }, + }, + { + desc: "complex-logging-policy", + globalLoggingPolicy: &policy.LoggingPolicy{ + Directories: policy.DirLoggingPolicy{ + Snapshotted: policy.NewLogDetail(3), + Ignored: policy.NewLogDetail(4), + }, + Entries: policy.EntryLoggingPolicy{ + Ignored: policy.NewLogDetail(3), + Snapshotted: policy.NewLogDetail(3), + CacheMiss: policy.NewLogDetail(4), + CacheHit: policy.NewLogDetail(5), + }, + }, + globalFilesPolicy: &policy.FilesPolicy{ + IgnoreRules: []string{"f1", "d3"}, + }, + wantDetailKeys: map[string][]string{ + "cache miss": {"mode", "mtime", "path", "size"}, + "cached": {"dur", "path", "size"}, + "error": {"dur", "error", "path"}, + "snapshotted file": {"dur", "path", "size"}, + "snapshotted symlink": {"dur", "path", "size"}, + "snapshotted directory": {"dur", "path", "size"}, + "ignored directory": {"dur", "path"}, + "ignored": {"dur", "path"}, + }, + wantEntries: []string{ + "ignored f1", + "ignored directory d1/d3", + "snapshotted directory d1", + "snapshotted file f2", + "snapshotted file f3", + "snapshotted symlink f4", + "error f5", + "snapshotted directory .", + }, + wantEntriesSecond: []string{ + "ignored f1", + "ignored directory d1/d3", + "snapshotted directory d1", + "cached f2", + "cached f3", + "cached f4", + "error f5", + "snapshotted directory .", + }, + }, + } + + sourceInfo := snapshot.SourceInfo{ + Host: "somehost", + UserName: "someuser", + Path: "/somepath", + } + + for _, tc := range cases { + t.Run(fmt.Sprintf("%v", tc.desc), func(t *testing.T) { + ml := &mockLogger{ + Logger: logging.NullLogger, + } + + ctx := testlogging.Context(t) + ctx = logging.WithLogger(ctx, func(module string) logging.Logger { + if module == "uploader" { + // only capture logs from the uploader, not the estimator. + return ml + } + + return logging.NullLogger + }) + th := newUploadTestHarness(ctx, t) + + defer th.cleanup() + + u := NewUploader(th.repo) + + // make sure uploads are strictly sequential to get predictable log output. + u.ParallelUploads = 1 + + pol := *policy.DefaultPolicy + if p := tc.globalLoggingPolicy; p != nil { + pol.LoggingPolicy = *p + } + + if p := tc.globalFilesPolicy; p != nil { + pol.FilesPolicy = *p + } + + policy.SetPolicy(ctx, th.repo, policy.GlobalPolicySourceInfo, &pol) + + u.OverrideDirLogDetail = tc.dirLogDetail + u.OverrideEntryLogDetail = tc.entryLogDetail + + ml.logged = nil + + polTree, err := policy.TreeForSource(ctx, th.repo, sourceInfo) + require.NoError(t, err) + + man1, err := u.Upload(ctx, sourceDir, polTree, sourceInfo) + require.NoError(t, err) + + var gotEntries []string + + for _, l := range ml.logged { + gotEntries = append(gotEntries, fmt.Sprintf("%v %v", l.msg, l.keysAndValues["path"])) + + require.Contains(t, tc.wantDetailKeys, l.msg) + verifyLogDetails(t, l.msg, tc.wantDetailKeys[l.msg], l.keysAndValues) + } + + require.Equal(t, tc.wantEntries, gotEntries) + + ml.logged = nil + + // run second upload with previous manifest to trigger cache. + _, err = u.Upload(ctx, sourceDir, polTree, sourceInfo, man1) + require.NoError(t, err) + + var gotEntriesSecond []string + + for _, l := range ml.logged { + gotEntriesSecond = append(gotEntriesSecond, fmt.Sprintf("%v %v", l.msg, l.keysAndValues["path"])) + + require.Contains(t, tc.wantDetailKeys, l.msg) + verifyLogDetails(t, "second "+l.msg, tc.wantDetailKeys[l.msg], l.keysAndValues) + } + + require.Equal(t, tc.wantEntriesSecond, gotEntriesSecond) + }) + } +} + +func verifyLogDetails(t *testing.T, desc string, wantDetailKeys []string, keysAndValues map[string]interface{}) { + t.Helper() + + var gotDetailKeys []string + + for k := range keysAndValues { + gotDetailKeys = append(gotDetailKeys, k) + } + + sort.Strings(gotDetailKeys) + sort.Strings(wantDetailKeys) + require.Equal(t, wantDetailKeys, gotDetailKeys, "invalid details for "+desc) +}