add logging

go.mod

@@ -2,7 +2,13 @@ module github.com/offen/docker-volume-backup
 
 go 1.17
 
-require github.com/docker/docker v20.10.8+incompatible
+require (
+	github.com/docker/docker v20.10.8+incompatible
+	github.com/joho/godotenv v1.3.0
+	github.com/minio/minio-go/v7 v7.0.12
+	github.com/walle/targz v0.0.0-20140417120357-57fe4206da5a
+	golang.org/x/crypto v0.0.0-20210817164053-32db794688a5
+)
 
 require (
 	github.com/Microsoft/go-winio v0.4.17 // indirect
@@ -14,12 +20,9 @@ require (
 	github.com/gogo/protobuf v1.3.2 // indirect
 	github.com/golang/protobuf v1.5.0 // indirect
 	github.com/google/uuid v1.2.0 // indirect
-	github.com/joho/godotenv v1.3.0 // indirect
 	github.com/json-iterator/go v1.1.10 // indirect
 	github.com/klauspost/cpuid v1.3.1 // indirect
 	github.com/minio/md5-simd v1.1.0 // indirect
-	github.com/minio/minio-go v6.0.14+incompatible
-	github.com/minio/minio-go/v7 v7.0.12 // indirect
 	github.com/minio/sha256-simd v0.1.1 // indirect
 	github.com/mitchellh/go-homedir v1.1.0 // indirect
 	github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect
@@ -30,7 +33,6 @@ require (
 	github.com/pkg/errors v0.9.1 // indirect
 	github.com/rs/xid v1.2.1 // indirect
 	github.com/sirupsen/logrus v1.8.1 // indirect
-	golang.org/x/crypto v0.0.0-20210817164053-32db794688a5 // indirect
 	golang.org/x/net v0.0.0-20210226172049-e18ecbb05110 // indirect
 	golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1 // indirect
 	golang.org/x/text v0.3.4 // indirect
@@ -39,8 +41,3 @@ require (
 	google.golang.org/protobuf v1.26.0 // indirect
 	gopkg.in/ini.v1 v1.57.0 // indirect
 )
-
-require (
-	github.com/go-ini/ini v1.25.4 // indirect
-	github.com/walle/targz v0.0.0-20140417120357-57fe4206da5a // indirect
-)

go.sum

@@ -254,7 +254,6 @@ github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeME
 github.com/go-gl/glfw v0.0.0-20190409004039-e6da0acd62b1/go.mod h1:vR7hzQXu2zJy9AVAgeJqvqgH9Q5CA+iKCZ2gyEVpxRU=
 github.com/go-gl/glfw/v3.3/glfw v0.0.0-20191125211704-12ad95a8df72/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8=
 github.com/go-gl/glfw/v3.3/glfw v0.0.0-20200222043503-6f7a984d4dc4/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8=
-github.com/go-ini/ini v1.25.4 h1:Mujh4R/dH6YL8bxuISne3xX2+qcQ9p0IxKAP6ExWoUo=
 github.com/go-ini/ini v1.25.4/go.mod h1:ByCAeIL28uOIIG0E3PJtZPDL8WnHpFKFOtgjp+3Ies8=
 github.com/go-kit/kit v0.8.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as=
 github.com/go-kit/kit v0.9.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as=
@@ -340,6 +339,7 @@ github.com/google/uuid v1.2.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+
 github.com/googleapis/gax-go/v2 v2.0.4/go.mod h1:0Wqv26UfaUD9n4G6kQubkQ+KchISgw+vpHVxEJEs9eg=
 github.com/googleapis/gax-go/v2 v2.0.5/go.mod h1:DWXyrwAJ9X0FpwwEdw+IPEYBICEFu5mhpdKc/us6bOk=
 github.com/googleapis/gnostic v0.4.1/go.mod h1:LRhVm6pbyptWbWbuZ38d1eyptfvIytN3ir6b65WBswg=
+github.com/gopherjs/gopherjs v0.0.0-20181017120253-0766667cb4d1 h1:EGx4pi6eqNxGaHF6qqu48+N2wcFQ5qg5FXgOdqsJ5d8=
 github.com/gopherjs/gopherjs v0.0.0-20181017120253-0766667cb4d1/go.mod h1:wJfORRmW1u3UXTncJ5qlYoELFm8eSnnEO6hX4iZ3EWY=
 github.com/gorilla/handlers v0.0.0-20150720190736-60c7bfde3e33/go.mod h1:Qkdc/uu4tH4g6mTK6auzZ766c4CA0Ng8+o/OAirnOIQ=
 github.com/gorilla/mux v1.7.2 h1:zoNxOV7WjqXptQOVngLmcSQgXmgk4NMz1HibBchjl/I=
@@ -379,6 +379,7 @@ github.com/json-iterator/go v1.1.10 h1:Kz6Cvnvv2wGdaG/V8yMvfkmNiXq9Ya2KUv4rouJJr
 github.com/json-iterator/go v1.1.10/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU=
 github.com/jstemmer/go-junit-report v0.9.1/go.mod h1:Brl9GWCQeLvo8nXZwPNNblvFj/XSXhF0NWZEnDohbsk=
+github.com/jtolds/gls v4.20.0+incompatible h1:xdiiI2gbIgH/gLH7ADydsJ1uDOEzR8yvV7C0MuV77Wo=
 github.com/jtolds/gls v4.20.0+incompatible/go.mod h1:QJZ7F/aHp+rZTRtaJ1ow/lLfFfVYBRgL+9YlvaHOwJU=
 github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7VTCxuUUipMqKk8s4w=
 github.com/kisielk/errcheck v1.1.0/go.mod h1:EZBBE59ingxPouuu3KfxchcWSUPOHkagtvWXihfKN4Q=
@@ -414,8 +415,6 @@ github.com/matttproud/golang_protobuf_extensions v1.0.2-0.20181231171920-c182aff
 github.com/miekg/pkcs11 v1.0.3/go.mod h1:XsNlhZGX73bx86s2hdc/FuaLm2CPZJemRLMA+WTFxgs=
 github.com/minio/md5-simd v1.1.0 h1:QPfiOqlZH+Cj9teu0t9b1nTBfPbyTl16Of5MeuShdK4=
 github.com/minio/md5-simd v1.1.0/go.mod h1:XpBqgZULrMYD3R+M28PcmP0CkI7PEMzB3U77ZrKZ0Gw=
-github.com/minio/minio-go v6.0.14+incompatible h1:fnV+GD28LeqdN6vT2XdGKW8Qe/IfjJDswNVuni6km9o=
-github.com/minio/minio-go v6.0.14+incompatible/go.mod h1:7guKYtitv8dktvNUGrhzmNlA5wrAABTQXCoesZdFQO8=
 github.com/minio/minio-go/v7 v7.0.12 h1:/4pxUdwn9w0QEryNkrrWaodIESPRX+NxpO0Q6hVdaAA=
 github.com/minio/minio-go/v7 v7.0.12/go.mod h1:S23iSP5/gbMwtxeY5FM71R+TkAYyzEdoNEDDwpt8yWs=
 github.com/minio/sha256-simd v0.1.1 h1:5QHSlgo3nt5yKOJrC7W8w7X+NFl8cMPZm96iu8kKUJU=
@@ -543,8 +542,10 @@ github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrf
 github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE=
 github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
+github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d h1:zE9ykElWQ6/NYmHa3jpm/yHnI4xSofP+UP6SpjHcSeM=
 github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc=
 github.com/smartystreets/goconvey v0.0.0-20190330032615-68dc04aab96a/go.mod h1:syvi0/a8iFYH4r/RixwvyeAJjdLS9QV7WQ/tjFTllLA=
+github.com/smartystreets/goconvey v1.6.4 h1:fv0U8FUIMPNf1L9lnHLvLhgicrIVChEkdzIKYqbNC9s=
 github.com/smartystreets/goconvey v1.6.4/go.mod h1:syvi0/a8iFYH4r/RixwvyeAJjdLS9QV7WQ/tjFTllLA=
 github.com/soheilhy/cmux v0.1.4/go.mod h1:IM3LyeVVIOuxMH7sFAkER9+bJ4dT7Ms6E4xg4kGIyLM=
 github.com/spaolacci/murmur3 v0.0.0-20180118202830-f09979ecbc72/go.mod h1:JwIasOWyU6f++ZhiEuf87xNszmSA2myDM2Kzu9HwQUA=
@@ -629,7 +630,6 @@ golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPh
 golang.org/x/crypto v0.0.0-20200728195943-123391ffb6de/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
 golang.org/x/crypto v0.0.0-20201002170205-7f63de1d35b0/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
 golang.org/x/crypto v0.0.0-20201216223049-8b5274cf687f/go.mod h1:jdWPYTVW3xRLrWPugEBEK3UY2ZEsg3UU495nc5E+M+I=
-golang.org/x/crypto v0.0.0-20210322153248-0c34fe9e7dc2 h1:It14KIkyBFYkHkwZ7k45minvA9aorojkyjGk9KJ5B/w=
 golang.org/x/crypto v0.0.0-20210322153248-0c34fe9e7dc2/go.mod h1:T9bdIzuCu7OtxOm1hfPfRQxPLYneinmdGuTeoZ9dtd4=
 golang.org/x/crypto v0.0.0-20210817164053-32db794688a5 h1:HWj/xjIHfjYU5nVXpTM0s39J9CbLn7Cc5a7IC5rwsMQ=
 golang.org/x/crypto v0.0.0-20210817164053-32db794688a5/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc=
@@ -772,7 +772,6 @@ golang.org/x/sys v0.0.0-20201201145000-ef89a241ccb3/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20201202213521-69691e467435/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210324051608-47abb6519492/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210426230700-d19ff857e887 h1:dXfMednGJh/SUUFjTLsWJz3P+TQt9qnR11GgeI3vWKs=
 golang.org/x/sys v0.0.0-20210426230700-d19ff857e887/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1 h1:SrN+KX8Art/Sf4HNj6Zcz06G7VEz+7w9tdXTPOZ7+l4=
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=

src/main.go

@@ -22,6 +22,7 @@ import (
 	"github.com/joho/godotenv"
 	minio "github.com/minio/minio-go/v7"
 	"github.com/minio/minio-go/v7/pkg/credentials"
+	"github.com/sirupsen/logrus"
 	"github.com/walle/targz"
 	"golang.org/x/crypto/openpgp"
 )
@@ -36,28 +37,24 @@ func main() {
 	s := &script{}
 
 	must(s.init)()
-	fmt.Println("Successfully initialized resources.")
 	err = s.stopContainersAndRun(s.takeBackup)
 	if err != nil {
 		panic(err)
 	}
-	fmt.Println("Successfully took backup.")
 	must(s.encryptBackup)()
-	fmt.Println("Successfully encrypted backup.")
 	must(s.copyBackup)()
-	fmt.Println("Successfully copied backup.")
 	must(s.cleanBackup)()
-	fmt.Println("Successfully cleaned local backup.")
 	must(s.pruneOldBackups)()
-	fmt.Println("Successfully pruned old backups.")
 }
 
 type script struct {
 	ctx     context.Context
 	cli     *client.Client
 	mc      *minio.Client
+	logger  *logrus.Logger
 	file    string
 	bucket  string
+	archive string
 }
 
 // lock opens a lock file without releasing it and returns a function that
@@ -83,6 +80,8 @@ func lock() (func() error, error) {
 // remote resources like the Docker engine or remote storage locations.
 func (s *script) init() error {
 	s.ctx = context.Background()
+	s.logger = logrus.New()
+	s.logger.SetOutput(os.Stdout)
 
 	if err := godotenv.Load("/etc/backup.env"); err != nil {
 		return fmt.Errorf("init: failed to load env file: %w", err)
@@ -92,7 +91,7 @@ func (s *script) init() error {
 	if !os.IsNotExist(err) {
 		cli, err := client.NewClientWithOpts(client.FromEnv, client.WithAPIVersionNegotiation())
 		if err != nil {
-			return fmt.Errorf("init: failied to create docker client")
+			return fmt.Errorf("init: failed to create docker client")
 		}
 		s.cli = cli
 	}
@@ -112,11 +111,13 @@ func (s *script) init() error {
 		}
 		s.mc = mc
 	}
+
 	file := os.Getenv("BACKUP_FILENAME")
 	if file == "" {
 		return errors.New("init: BACKUP_FILENAME not given")
 	}
 	s.file = path.Join("/tmp", file)
+	s.archive = os.Getenv("BACKUP_ARCHIVE")
 	return nil
 }
 
@@ -148,7 +149,7 @@ func (s *script) stopContainersAndRun(thunk func() error) error {
 	if err != nil {
 		return fmt.Errorf("stopContainersAndRun: error querying for containers to stop: %w", err)
 	}
-	fmt.Printf("Stopping %d out of %d running containers\n", len(containersToStop), len(allContainers))
+	s.logger.Infof("Stopping %d out of %d running containers\n", len(containersToStop), len(allContainers))
 
 	var stoppedContainers []types.Container
 	var errors []error
@@ -207,6 +208,7 @@ func (s *script) stopContainersAndRun(thunk func() error) error {
 				err,
 			)
 		}
+		s.logger.Infof("Successfully restarted %d containers.", len(stoppedContainers))
 		return nil
 	}()
 
@@ -236,6 +238,7 @@ func (s *script) takeBackup() error {
 	if err := targz.Compress(os.Getenv("BACKUP_SOURCES"), s.file); err != nil {
 		return fmt.Errorf("takeBackup: error compressing backup folder: %w", err)
 	}
+	s.logger.Infof("Successfully created backup from %s at %s", os.Getenv("BACKUP_SOURCES"), s.file)
 	return nil
 }
 
@@ -279,6 +282,7 @@ func (s *script) encryptBackup() error {
 		return fmt.Errorf("encryptBackup: error removing unencrpyted backup: %w", err)
 	}
 	s.file = gpgFile
+	s.logger.Info("Successfully encrypted backup using given passphrase.")
 	return nil
 }
 
@@ -293,14 +297,16 @@ func (s *script) copyBackup() error {
 		if err != nil {
 			return fmt.Errorf("copyBackup: error uploading backup to remote storage: %w", err)
 		}
+		s.logger.Infof("Successfully uploaded backup %s to bucket %s", s.file, s.bucket)
 	}
 
-	if archive := os.Getenv("BACKUP_ARCHIVE"); archive != "" {
+	if s.archive != "" {
-		if _, err := os.Stat(archive); !os.IsNotExist(err) {
+		if _, err := os.Stat(s.archive); !os.IsNotExist(err) {
-			if err := copy(s.file, path.Join(archive, name)); err != nil {
+			if err := copy(s.file, path.Join(s.archive, name)); err != nil {
 				return fmt.Errorf("copyBackup: error copying file to local archive: %w", err)
 			}
 		}
+		s.logger.Infof("Successfully stored copy of backup %s in local archive %s", s.file, s.archive)
 	}
 	return nil
 }
@@ -310,6 +316,7 @@ func (s *script) cleanBackup() error {
 	if err := os.Remove(s.file); err != nil {
 		return fmt.Errorf("cleanBackup: error removing file: %w", err)
 	}
+	s.logger.Info("Successfully cleaned local backup.")
 	return nil
 }
 
@@ -329,8 +336,10 @@ func (s *script) pruneOldBackups() error {
 	if err != nil {
 		return fmt.Errorf("pruneBackups: error parsing given leeway value: %w", err)
 	}
+	s.logger.Infof("Sleeping for %s before pruning backups.", os.Getenv("BACKUP_PRUNING_LEEWAY"))
 	time.Sleep(sleepFor)
 
+	s.logger.Infof("Trying to prune backups older than %d days now.", retentionDays)
 	deadline := time.Now().AddDate(0, 0, -retentionDays)
 
 	if s.bucket != "" {
@@ -340,17 +349,22 @@ func (s *script) pruneOldBackups() error {
 		})
 
 		var matches []minio.ObjectInfo
+		var lenCandidates int
 		for candidate := range candidates {
+			lenCandidates++
+			if candidate.Err != nil {
+				return fmt.Errorf("pruneOldBackups: error looking up candidates from remote storage: %w", candidate.Err)
+			}
 			if candidate.LastModified.Before(deadline) {
 				matches = append(matches, candidate)
 			}
 		}
 
-		if len(matches) != len(candidates) {
+		if len(matches) != 0 && len(matches) != lenCandidates {
 			objectsCh := make(chan minio.ObjectInfo)
 			go func() {
-				for _, candidate := range matches {
+				for _, match := range matches {
-					objectsCh <- candidate
+					objectsCh <- match
 				}
 				close(objectsCh)
 			}()
@@ -369,14 +383,21 @@ func (s *script) pruneOldBackups() error {
 					errors[0],
 				)
 			}
-		} else if len(candidates) != 0 {
+			s.logger.Infof(
-			fmt.Println("Refusing to delete all backups. Check your configuration.")
+				"Successfully pruned %d out of %d remote backups as their age exceeded the configured retention period.",
+				len(matches),
+				lenCandidates,
+			)
+		} else if len(matches) != 0 && len(matches) == lenCandidates {
+			s.logger.Warnf("The current configuration would delete all %d remote backups. Refusing to do so.", len(matches))
+		} else {
+			s.logger.Info("No remote backups were pruned.")
 		}
 	}
 
-	if archive := os.Getenv("BACKUP_ARCHIVE"); archive != "" {
+	if s.archive != "" {
 		candidates, err := filepath.Glob(
-			path.Join(archive, fmt.Sprintf("%s%s", os.Getenv("BACKUP_PRUNING_PREFIX"), "*")),
+			path.Join(s.archive, fmt.Sprintf("%s*", os.Getenv("BACKUP_PRUNING_PREFIX"))),
 		)
 		if err != nil {
 			return fmt.Errorf(
@@ -400,7 +421,7 @@ func (s *script) pruneOldBackups() error {
 			}
 		}
 
-		if len(matches) != len(candidates) {
+		if len(matches) != 0 && len(matches) != len(candidates) {
 			var errors []error
 			for _, candidate := range matches {
 				if err := os.Remove(candidate.Name()); err != nil {
@@ -414,8 +435,15 @@ func (s *script) pruneOldBackups() error {
 					errors[0],
 				)
 			}
-		} else if len(candidates) != 0 {
+			s.logger.Infof(
-			fmt.Println("Refusing to delete all backups. Check your configuration.")
+				"Successfully pruned %d out of %d local backups as their age exceeded the configured retention period.",
+				len(matches),
+				len(candidates),
+			)
+		} else if len(matches) != 0 && len(matches) == len(candidates) {
+			s.logger.Warnf("The current configuration would delete all %d local backups. Refusing to do so.", len(matches))
+		} else {
+			s.logger.Info("No local backups were pruned.")
 		}
 	}
 	return nil