code cleanup, logging

cmd/kopia/command_backup.go

@@ -52,16 +52,8 @@ func runBackupCommand(context *kingpin.ParseContext) error {
 		repoOptions = append(repoOptions, repo.WriteBack(*backupWriteBack))
 	}
 
-	vlt, err := openVault()
-	if err != nil {
-		return err
-	}
-
-	mgr, err := vlt.OpenRepository(repoOptions...)
-	if err != nil {
-		return err
-	}
-	defer mgr.Close()
+	vlt, r := mustOpenVaultAndRepository()
+	defer r.Close()
 
 	var options []fs.UploaderOption
 
@@ -69,7 +61,7 @@ func runBackupCommand(context *kingpin.ParseContext) error {
 		options = append(options, fs.EnableBundling())
 	}
 
-	bgen, err := backup.NewGenerator(mgr, options...)
+	bgen, err := backup.NewGenerator(r, options...)
 	if err != nil {
 		return err
 	}

cmd/kopia/command_backups.go

@@ -57,19 +57,12 @@ func findBackups(vlt *vault.Vault, path string) ([]string, string, error) {
 }
 
 func runBackupsCommand(context *kingpin.ParseContext) error {
-	vlt, err := openVault()
-	if err != nil {
-		return err
-	}
-
-	mgr, err := vlt.OpenRepository()
-	if err != nil {
-		return err
-	}
-	defer mgr.Close()
+	vlt, r := mustOpenVaultAndRepository()
+	defer r.Close()
 
 	var previous []string
 	var relPath string
+	var err error
 
 	if *backupsPath != "" {
 		path, err := filepath.Abs(*backupsPath)

cmd/kopia/command_ls.go

@@ -18,11 +18,9 @@
 )
 
 func runLSCommand(context *kingpin.ParseContext) error {
-	vlt := mustOpenVault()
-	mgr, err := vlt.OpenRepository()
-	if err != nil {
-		return err
-	}
+	vlt, r := mustOpenVaultAndRepository()
+	defer vlt.Close()
+	defer r.Close()
 
 	oid, err := parseObjectID(*lsCommandPath, vlt)
 	if err != nil {
@@ -37,7 +35,7 @@ func runLSCommand(context *kingpin.ParseContext) error {
 		}
 	}
 
-	dir := fs.NewDirectory(mgr, oid)
+	dir := fs.NewDirectory(r, oid)
 	entries, err := dir.Readdir()
 	if err != nil {
 		return err

cmd/kopia/command_mount.go

@@ -27,12 +27,7 @@ func (r *root) Root() (fusefs.Node, error) {
 }
 
 func runMountCommand(context *kingpin.ParseContext) error {
-	vlt := mustOpenVault()
-
-	r, err := vlt.OpenRepository()
-	if err != nil {
-		return err
-	}
+	vlt, r := mustOpenVaultAndRepository()
 
 	fuseConnection, err := fuse.Mount(
 		*mountPoint,

cmd/kopia/command_show.go

@@ -20,11 +20,9 @@
 )
 
 func runShowCommand(context *kingpin.ParseContext) error {
-	vlt := mustOpenVault()
-	mgr, err := vlt.OpenRepository()
-	if err != nil {
-		return err
-	}
+	vlt, r := mustOpenVaultAndRepository()
+	defer vlt.Close()
+	defer r.Close()
 
 	for _, oidString := range *showObjectIDs {
 		oid, err := parseObjectID(oidString, vlt)
@@ -32,7 +30,7 @@ func runShowCommand(context *kingpin.ParseContext) error {
 			return err
 		}
 
-		if err := showObject(mgr, oid); err != nil {
+		if err := showObject(r, oid); err != nil {
 			return err
 		}
 	}
@@ -40,14 +38,14 @@ func runShowCommand(context *kingpin.ParseContext) error {
 	return nil
 }
 
-func showObject(mgr repo.Repository, oid repo.ObjectID) error {
-	r, err := mgr.Open(oid)
+func showObject(r repo.Repository, oid repo.ObjectID) error {
+	rd, err := r.Open(oid)
 	if err != nil {
 		return err
 	}
-	defer r.Close()
+	defer rd.Close()
 
-	rawdata, err := ioutil.ReadAll(r)
+	rawdata, err := ioutil.ReadAll(rd)
 	if err != nil {
 		return err
 	}

cmd/kopia/command_status.go

@@ -17,21 +17,18 @@ func init() {
 }
 
 func runRepositoryInfoCommand(context *kingpin.ParseContext) error {
-	v, err := openVault()
-	if err != nil {
-		return err
-	}
+	vlt, r := mustOpenVaultAndRepository()
 
-	vf := v.Format()
+	vf := vlt.Format()
 	fmt.Println("Vault:")
 	fmt.Println("  Version:         ", vf.Version)
 	fmt.Println("  Unique ID:       ", hex.EncodeToString(vf.UniqueID))
 	fmt.Println("  Encryption:      ", vf.Encryption)
 	fmt.Println("  Checksum:        ", vf.Checksum)
-	fmt.Println("  Storage:         ", v.Storage())
+	fmt.Println("  Storage:         ", vlt.Storage())
 	fmt.Println()
 
-	f := v.RepositoryFormat()
+	f := vlt.RepositoryFormat()
 
 	fmt.Println("Repository:")
 	fmt.Println("  Version:         ", f.Version)
@@ -43,12 +40,7 @@ func runRepositoryInfoCommand(context *kingpin.ParseContext) error {
 	fmt.Println("  ID Format:       ", f.ObjectFormat)
 	fmt.Println("  Blob Size:       ", f.MaxBlockSize/1024, "KB")
 	fmt.Println("  Inline Blob Size:", f.MaxInlineContentLength/1024, "KB")
-	r, err := v.OpenRepository()
-	if err == nil {
-		fmt.Println("  Storage:         ", r.Storage())
-	} else {
-		fmt.Println("  WARNING: Cannot open repository.")
-	}
+	fmt.Println("  Storage:         ", r.Storage())
 
 	return nil
 }

cmd/kopia/command_vault_list.go

@@ -16,12 +16,9 @@ func init() {
 }
 
 func listVaultContents(context *kingpin.ParseContext) error {
-	v, err := openVault()
-	if err != nil {
-		return err
-	}
+	vlt := mustOpenVault()
 
-	entries, err := v.List(*vaultListPrefix)
+	entries, err := vlt.List(*vaultListPrefix)
 	if err != nil {
 		return err
 	}

cmd/kopia/command_vault_rm.go

@@ -12,10 +12,7 @@ func init() {
 }
 
 func removeVaultItem(context *kingpin.ParseContext) error {
-	vlt, err := openVault()
-	if err != nil {
-		return err
-	}
+	vlt := mustOpenVault()
 
 	for _, v := range *vaultRemoveItems {
 		if err := vlt.Remove(v); err != nil {

cmd/kopia/config.go

@@ -11,6 +11,7 @@
 	"strings"
 
 	"github.com/bgentry/speakeasy"
+	"github.com/kopia/kopia/repo"
 	"github.com/kopia/kopia/vault"
 )
 
@@ -38,6 +39,31 @@ func mustOpenVault() *vault.Vault {
 	return s
 }
 
+func mustOpenRepository(extraOptions ...repo.RepositoryOption) repo.Repository {
+	_, r := mustOpenVaultAndRepository(extraOptions...)
+	return r
+}
+
+func mustOpenVaultAndRepository(extraOptions ...repo.RepositoryOption) (*vault.Vault, repo.Repository) {
+	v := mustOpenVault()
+	r, err := v.OpenRepository(repositoryOptionsFromFlags(extraOptions)...)
+	failOnError(err)
+	return v, r
+}
+
+func repositoryOptionsFromFlags(extraOptions []repo.RepositoryOption) []repo.RepositoryOption {
+	var opts []repo.RepositoryOption
+
+	for _, o := range extraOptions {
+		opts = append(opts, o)
+	}
+
+	if *traceStorage {
+		opts = append(opts, repo.EnableLogging())
+	}
+	return opts
+}
+
 func getHomeDir() string {
 	if runtime.GOOS == "windows" {
 		home := os.Getenv("HOMEDRIVE") + os.Getenv("HOMEPATH")

repo/repository.go

@@ -84,19 +84,16 @@ type repository struct {
 }
 
 func (r *repository) Close() error {
-	if err := r.Flush(); err != nil {
+	if err := r.storage.Close(); err != nil {
 		return err
 	}
 	r.bufferManager.close()
+
 	return nil
 }
 
 func (r *repository) Flush() error {
-	if f, ok := r.storage.(storage.Flusher); ok {
-		return f.Flush()
-	}
-
-	return nil
+	return r.storage.Flush()
 }
 
 func (r *repository) Stats() RepositoryStats {

storage/logging/logging_storage.go

@@ -3,71 +3,95 @@
 
 import (
 	"log"
+	"time"
 
 	"github.com/kopia/kopia/storage"
 )
 
-// Printfer supports emitting formatted strings to arbitrary outputs.
-// The formatting language must be compatible with fmt.Sprintf().
-type Printfer interface {
-	Printf(fmt string, args ...interface{})
-}
-
 type loggingStorage struct {
 	base   storage.Storage
 	printf func(string, ...interface{})
 }
 
 func (s *loggingStorage) BlockExists(id string) (bool, error) {
+	t0 := time.Now()
 	result, err := s.base.BlockExists(id)
-	s.printf("BlockExists(%#v)=%#v,%#v", id, result, err)
+	dt := time.Since(t0)
+	s.printf(s.prefix()+"BlockExists(%#v)=%#v,%#v took %v", id, result, err, dt)
 	return result, err
 }
 
 func (s *loggingStorage) GetBlock(id string) ([]byte, error) {
+	t0 := time.Now()
 	result, err := s.base.GetBlock(id)
+	dt := time.Since(t0)
 	if len(result) < 20 {
-		s.printf("GetBlock(%#v)=(%#v, %#v)", id, result, err)
+		s.printf(s.prefix()+"GetBlock(%#v)=(%#v, %#v) took %v", id, result, err, dt)
 	} else {
-		s.printf("GetBlock(%#v)=({%#v bytes}, %#v)", id, len(result), err)
+		s.printf(s.prefix()+"GetBlock(%#v)=({%#v bytes}, %#v) took %v", id, len(result), err, dt)
 	}
 	return result, err
 }
 
 func (s *loggingStorage) PutBlock(id string, data storage.ReaderWithLength, options storage.PutOptions) error {
+	t0 := time.Now()
 	l := data.Len()
 	err := s.base.PutBlock(id, data, options)
-	s.printf("PutBlock(%#v, options=%v, len=%v)=%#v", id, options, l, err)
+	dt := time.Since(t0)
+	s.printf(s.prefix()+"PutBlock(%#v, options=%v, len=%v)=%#v took %v", id, options, l, err, dt)
 	return err
 }
 
 func (s *loggingStorage) DeleteBlock(id string) error {
+	t0 := time.Now()
 	err := s.base.DeleteBlock(id)
-	s.printf("DeleteBlock(%#v)=%#v", id, err)
+	dt := time.Since(t0)
+	s.printf(s.prefix()+"DeleteBlock(%#v)=%#v took %v", id, err, dt)
 	return err
 }
 
 func (s *loggingStorage) ListBlocks(prefix string) chan (storage.BlockMetadata) {
-	s.printf("ListBlocks(%#v)", prefix)
-	return s.base.ListBlocks(prefix)
+	t0 := time.Now()
+	ch := s.base.ListBlocks(prefix)
+	dt := time.Since(t0)
+	s.printf(s.prefix()+"ListBlocks(%#v) took %v", prefix, dt)
+	return ch
 }
 
 func (s *loggingStorage) Flush() error {
-	s.printf("Flush()")
-	return s.base.Flush()
+	t0 := time.Now()
+	err := s.base.Flush()
+	dt := time.Since(t0)
+	s.printf(s.prefix()+"Flush()=%#v took %v", err, dt)
+	return err
 }
 
 func (s *loggingStorage) Close() error {
-	s.printf("Close()")
-	return s.base.Close()
+	t0 := time.Now()
+	err := s.base.Close()
+	dt := time.Since(t0)
+	s.printf(s.prefix()+"Close()=%#v took %v", err, dt)
+	return err
 }
 
+func (s *loggingStorage) prefix() string {
+	return "[STORAGE] "
+}
+
+type Option func(s *loggingStorage)
+
 // NewWrapper returns a Storage wrapper that logs all storage commands.
-func NewWrapper(wrapped storage.Storage) storage.Storage {
-	return &loggingStorage{base: wrapped, printf: log.Printf}
+func NewWrapper(wrapped storage.Storage, options ...Option) storage.Storage {
+	s := &loggingStorage{base: wrapped, printf: log.Printf}
+	for _, o := range options {
+		o(s)
+	}
+	return s
 }
 
-// NewWrapperWithLogger returns a Storage wrapper that logs all storage commands to the specified logger.
-func NewWrapperWithLogger(wrapped storage.Storage, printfer Printfer) storage.Storage {
-	return &loggingStorage{base: wrapped, printf: printfer.Printf}
+// Output is a logging storage option that causes all output to be sent to a given function instead of log.Printf()
+func Output(outputFunc func(fmt string, args ...interface{})) Option {
+	return func(s *loggingStorage) {
+		s.printf = outputFunc
+	}
 }