Rework logging

Signed-off-by: Knut Ahlers <knut@ahlers.me>

Gopkg.lock

@@ -42,6 +42,14 @@
   pruneopts = "NUT"
   revision = "a1dbeea552b7c8df4b542c66073e393de198a800"
 
+[[projects]]
+  digest = "1:4059c14e87a2de3a434430340521b5feece186c1469eff0834c29a63870de3ed"
+  name = "github.com/konsorten/go-windows-terminal-sequences"
+  packages = ["."]
+  pruneopts = "NUT"
+  revision = "5c8c8bd35d3832f5d134ae1e1e375b69a4d25242"
+  version = "v1.0.1"
+
 [[projects]]
   digest = "1:a4df73029d2c42fabcb6b41e327d2f87e685284ec03edf76921c267d9cfc9c23"
   name = "github.com/mitchellh/go-homedir"
@@ -106,6 +114,22 @@
   revision = "7615b9433f86a8bdf29709bf288bc4fd0636a369"
   version = "v1.4.2"
 
+[[projects]]
+  digest = "1:ffe8353de82ab7608fc1fd9a246e71b231af2479727dd165e3720cc2e8918177"
+  name = "github.com/rifflock/lfshook"
+  packages = ["."]
+  pruneopts = "NUT"
+  revision = "b9218ef580f59a2e72dad1aa33d660150445d05a"
+  version = "v2.4"
+
+[[projects]]
+  digest = "1:01252cd79aac70f16cac02a72a1067dd136e0ad6d5b597d0129cf74c739fd8d1"
+  name = "github.com/sirupsen/logrus"
+  packages = ["."]
+  pruneopts = "NUT"
+  revision = "a67f783a3814b8729bd2dac5780b5f78f8dbd64d"
+  version = "v1.1.0"
+
 [[projects]]
   digest = "1:9d8420bbf131d1618bde6530af37c3799340d3762cc47210c1d9532a4c3a2779"
   name = "github.com/spf13/pflag"
@@ -114,6 +138,14 @@
   revision = "298182f68c66c05229eb03ac171abe6e309ee79a"
   version = "v1.0.3"
 
+[[projects]]
+  branch = "master"
+  digest = "1:3f3a05ae0b95893d90b9b3b5afdb79a9b3d96e4e36e099d841ae602e4aca0da8"
+  name = "golang.org/x/crypto"
+  packages = ["ssh/terminal"]
+  pruneopts = "NUT"
+  revision = "e3636079e1a4c1f337f212cc5cd2aca108f6c900"
+
 [[projects]]
   branch = "master"
   digest = "1:5193d913046443e59093d66a97a40c51f4a5ea4ceba60f3b3ecf89694de5d16f"
@@ -128,9 +160,12 @@
 
 [[projects]]
   branch = "master"
-  digest = "1:a9bc64e1206f3d5ce2ac71e397ddfe81065ac706929d34fcb3f0a48e74cd6e3b"
+  digest = "1:68ca1f18d986adc1d25a28aa732806ee8f1c874cc5b606e4ba67ddd3eeb89e20"
   name = "golang.org/x/sys"
-  packages = ["unix"]
+  packages = [
+    "unix",
+    "windows",
+  ]
   pruneopts = "NUT"
   revision = "4497e2df6f9e69048a54498c7affbbec3294ad47"
 
@@ -203,6 +238,7 @@
     "github.com/nightlyone/lockfile",
     "github.com/onsi/ginkgo",
     "github.com/onsi/gomega",
+    "github.com/rifflock/lfshook",
     "gopkg.in/yaml.v2",
   ]
   solver-name = "gps-cdcl"

Gopkg.toml

@@ -61,3 +61,7 @@
   non-go = true
   go-tests = true
   unused-packages = true
+
+[[constraint]]
+  name = "github.com/rifflock/lfshook"
+  version = "2.4.0"

main.go

@@ -2,7 +2,6 @@ package main
 
 import (
 	"fmt"
-	"log"
 	"os"
 	"os/exec"
 	"path"
@@ -13,8 +12,11 @@ import (
 	"github.com/Luzifer/go_helpers/str"
 	"github.com/Luzifer/go_helpers/which"
 	"github.com/Luzifer/rconfig"
+	"github.com/rifflock/lfshook"
+
 	"github.com/mitchellh/go-homedir"
 	"github.com/nightlyone/lockfile"
+	log "github.com/sirupsen/logrus"
 )
 
 var (
@@ -25,14 +27,13 @@ var (
 		RestoreTime string `flag:"time,t" description:"The time from which to restore or list files"`
 
 		DryRun   bool   `flag:"dry-run,n" default:"false" description:"Do a test-run without changes"`
-		Debug  bool `flag:"debug,d" default:"false" description:"Print duplicity commands to output"`
 		Silent   bool   `flag:"silent,s" default:"false" description:"Do not print to stdout, only write to logfile (for example useful for crons)"`
+		LogLevel string `flag:"log-level" default:"info" description:"Verbosity of logs to use (debug, info, warning, error, ...)"`
 
 		VersionAndExit bool `flag:"version" default:"false" description:"Print version and exit"`
 	}{}
 
 	duplicityBinary string
-	logFile         *os.File
 
 	version = "dev"
 )
@@ -40,7 +41,7 @@ var (
 func initCFG() {
 	var err error
 	if err = rconfig.Parse(&cfg); err != nil {
-		log.Fatalf("Error while parsing arguments: %s", err)
+		log.WithError(err).Fatal("Error while parsing arguments")
 	}
 
 	if cfg.VersionAndExit {
@@ -48,25 +49,22 @@ func initCFG() {
 		os.Exit(0)
 	}
 
+	if logLevel, err := log.ParseLevel(cfg.LogLevel); err == nil {
+		log.SetLevel(logLevel)
+	} else {
+		log.Fatalf("Unable to parse log level: %s", err)
+	}
+
 	if cfg.ConfigFile, err = homedir.Expand(cfg.ConfigFile); err != nil {
-		log.Fatalf("Unable to expand config-file: %s", err)
+		log.WithError(err).Fatal("Unable to expand config-file")
 	}
 
 	if cfg.LockFile, err = homedir.Expand(cfg.LockFile); err != nil {
-		log.Fatalf("Unable to expand lock: %s", err)
+		log.WithError(err).Fatal("Unable to expand lock")
 	}
 
 	if duplicityBinary, err = which.FindInPath("duplicity"); err != nil {
-		log.Fatalf("Did not find duplicity binary in $PATH, please install it")
+		log.WithError(err).Fatal("Did not find duplicity binary in $PATH, please install it")
-	}
-}
-
-func logf(pattern string, fields ...interface{}) {
-	t := time.Now().Format("2006-01-02 15:04:05")
-	pattern = fmt.Sprintf("(%s) ", t) + pattern + "\n"
-	fmt.Fprintf(logFile, pattern, fields...)
-	if !cfg.Silent {
-		fmt.Printf(pattern, fields...)
 	}
 }
 
@@ -80,7 +78,7 @@ func main() {
 
 	lock, err := lockfile.New(cfg.LockFile)
 	if err != nil {
-		log.Fatalf("Could not initialize lockfile: %s", err)
+		log.WithError(err).Fatal("Could not initialize lockfile")
 	}
 
 	// If no command is passed assume we're requesting "help"
@@ -94,29 +92,33 @@ func main() {
 	// Get configuration
 	configSource, err := os.Open(cfg.ConfigFile)
 	if err != nil {
-		log.Fatalf("Unable to open configuration file %s: %s", cfg.ConfigFile, err)
+		log.WithError(err).Fatalf("Unable to open configuration file %s", cfg.ConfigFile)
 	}
 	defer configSource.Close()
 	config, err = loadConfigFile(configSource)
 	if err != nil {
-		log.Fatalf("Unable to read configuration file: %s", err)
+		log.WithError(err).Fatal("Unable to read configuration file")
 	}
 
 	// Initialize logfile
 	if err := os.MkdirAll(config.LogDirectory, 0750); err != nil {
-		log.Fatalf("Unable to create log dir: %s", err)
+		log.WithError(err).Fatal("Unable to create log dir")
 	}
 
 	logFilePath := path.Join(config.LogDirectory, time.Now().Format("duplicity-backup_2006-01-02_15-04-05.txt"))
-	if logFile, err = os.Create(logFilePath); err != nil {
+	logFile, err := os.Create(logFilePath)
-		log.Fatalf("Unable to open logfile %s: %s", logFilePath, err)
+	if err != nil {
+		log.WithError(err).Fatalf("Unable to open logfile %s", logFilePath)
 	}
 	defer logFile.Close()
 
-	logf("++++ duplicity-backup %s started with command '%s'", version, argv[1])
+	// Hook into logging and write to file
+	log.AddHook(lfshook.NewHook(logFile, nil))
+
+	log.Infof("++++ duplicity-backup %s started with command '%s'", version, argv[1])
 
 	if err := lock.TryLock(); err != nil {
-		logf("Could not acquire lock: %s", err)
+		log.WithError(err).Error("Could not acquire lock")
 		return
 	}
 	defer lock.Unlock()
@@ -126,7 +128,7 @@ func main() {
 	}
 
 	if config.Cleanup.Type != "none" && str.StringInSlice(argv[1], removeCommands) {
-		logf("++++ Starting removal of old backups")
+		log.Info("++++ Starting removal of old backups")
 
 		if err := execute(config, []string{commandRemove}); err != nil {
 			return
@@ -134,12 +136,12 @@ func main() {
 	}
 
 	if err := config.Notify(argv[1], true, nil); err != nil {
-		logf("[ERR] Error sending notifications: %s", err)
+		log.WithError(err).Error("Error sending notifications")
 	} else {
-		logf("[INF] Notifications sent")
+		log.Info("Notifications sent")
 	}
 
-	logf("++++ Backup finished successfully")
+	log.Info("++++ Backup finished successfully")
 }
 
 func execute(config *configFile, argv []string) error {
@@ -150,7 +152,7 @@ func execute(config *configFile, argv []string) error {
 	)
 	commandLine, tmpEnv, logFilter, err = config.GenerateCommand(argv, cfg.RestoreTime)
 	if err != nil {
-		logf("[ERR] %s", err)
+		log.WithError(err).Error("Unable to generate command")
 		return err
 	}
 
@@ -166,15 +168,13 @@ func execute(config *configFile, argv []string) error {
 		commandLine = append([]string{"--dry-run"}, commandLine...)
 	}
 
-	if cfg.Debug {
+	log.Debugf("Command: %s %s", duplicityBinary, strings.Join(commandLine, " "))
-		logf("[DBG] Command: %s %s", duplicityBinary, strings.Join(commandLine, " "))
-	}
 
 	msgChan := make(chan string, 10)
 	go func(c chan string, logFilter *regexp.Regexp) {
 		for l := range c {
 			if logFilter == nil || logFilter.MatchString(l) {
-				logf(l)
+				log.Info(l)
 			}
 		}
 	}(msgChan, logFilter)
@@ -189,16 +189,16 @@ func execute(config *configFile, argv []string) error {
 	close(msgChan)
 
 	if err != nil {
-		logf("[ERR] Execution of duplicity command was unsuccessful! (exit-code was non-zero)")
+		log.Error("Execution of duplicity command was unsuccessful! (exit-code was non-zero)")
 	} else {
-		logf("[INF] Execution of duplicity command was successful.")
+		log.Info("Execution of duplicity command was successful.")
 	}
 
 	if err != nil {
 		if nErr := config.Notify(argv[0], false, fmt.Errorf("Could not create backup: %s", err)); nErr != nil {
-			logf("[ERR] Error sending notifications: %s", nErr)
+			log.WithError(err).Error("Error sending notifications")
 		} else {
-			logf("[INF] Notifications sent")
+			log.Info("Notifications sent")
 		}
 	}