Added support for logging policies (#1472)

* policy: introduced OptionalBool - refactoring

* policy: added logging policy

* testing: added support for symlinks and modtime to mockfs

* logging: exposed NullLogger instance

* upload: emit debug logs according to logging policies

* cli: logging policy support

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
 }

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)
 		}

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
 	}
 

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
+}

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")
+}

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)
 		}
 	}
 

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
 }

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")
 

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 <key>:<value> 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
 	}

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:")
 }
 

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 {

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{
 	".": {

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: "<root>",
-			mode: 0o777 | os.ModeDir, // nolint:gomnd
+			name:    "<root>",
+			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{}
 )

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
 	}
 }

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
 }

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),
 }

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)
-		}
-	}
-}

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"},

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
+	}
+}

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)
+}

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),
+	},
+}

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
+	}
+}

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)

snapshot/policy/policy_tree.go

@@ -11,6 +11,7 @@ var DefaultPolicy = &Policy{
 	CompressionPolicy:   defaultCompressionPolicy,
 	ErrorHandlingPolicy: defaultErrorHandlingPolicy,
 	SchedulingPolicy:    defaultSchedulingPolicy,
+	LoggingPolicy:       defaultLoggingPolicy,
 	Actions:             defaultActionsPolicy,
 }
 

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++

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
 }

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,

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

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())
 		}
 

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)
 		}
 	}
 }

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)
+}