shorten log messages

README.md

@@ -79,7 +79,7 @@ AWS_S3_BUCKET_NAME="<xxx>"
 # that is expected to be bigger than the maximum difference of backups.
 # Valid values have a suffix of (s)econds, (m)inutes or (h)ours.
 
-# BACKUP_PRUNING_LEEWAY="10m"
+# BACKUP_PRUNING_LEEWAY="1m"
 
 # In case your target bucket or directory contains other files than the ones
 # managed by this container, you can limit the scope of rotation by setting

cmd/backup/main.go

@@ -11,11 +11,9 @@ import (
 	"io"
 	"io/ioutil"
 	"os"
-	"os/exec"
 	"path"
 	"path/filepath"
 	"strconv"
-	"strings"
 	"time"
 
 	"github.com/docker/docker/api/types"
@@ -23,6 +21,7 @@ import (
 	"github.com/docker/docker/api/types/swarm"
 	"github.com/docker/docker/client"
 	"github.com/joho/godotenv"
+	"github.com/leekchan/timeutil"
 	minio "github.com/minio/minio-go/v7"
 	"github.com/minio/minio-go/v7/pkg/credentials"
 	"github.com/sirupsen/logrus"
@@ -45,15 +44,22 @@ func main() {
 }
 
 type script struct {
-	ctx        context.Context
+	ctx    context.Context
-	cli        *client.Client
+	cli    *client.Client
-	mc         *minio.Client
+	mc     *minio.Client
-	logger     *logrus.Logger
+	logger *logrus.Logger
-	file       string
+
-	bucket     string
+	start time.Time
-	archive    string
+
-	sources    string
+	file           string
-	passphrase string
+	bucket         string
+	archive        string
+	sources        string
+	passphrase     []byte
+	retentionDays  *int
+	leeway         *time.Duration
+	containerLabel string
+	pruningPrefix  string
 }
 
 // lock opens a lockfile at the given location, keeping it locked until the
@@ -118,7 +124,27 @@ func (s *script) init() error {
 	s.file = path.Join("/tmp", file)
 	s.archive = os.Getenv("BACKUP_ARCHIVE")
 	s.sources = os.Getenv("BACKUP_SOURCES")
-	s.passphrase = os.Getenv("GPG_PASSPHRASE")
+	if v := os.Getenv("GPG_PASSPHRASE"); v != "" {
+		s.passphrase = []byte(v)
+	}
+	if v := os.Getenv("BACKUP_RETENTION_DAYS"); v != "" {
+		i, err := strconv.Atoi(v)
+		if err != nil {
+			return fmt.Errorf("init: error parsing BACKUP_RETENTION_DAYS as int: %w", err)
+		}
+		s.retentionDays = &i
+	}
+	if v := os.Getenv("BACKUP_PRUNING_LEEWAY"); v != "" {
+		d, err := time.ParseDuration(v)
+		if err != nil {
+			return fmt.Errorf("init: error parsing BACKUP_PRUNING_LEEWAY as duration: %w", err)
+		}
+		s.leeway = &d
+	}
+	s.containerLabel = os.Getenv("BACKUP_STOP_CONTAINER_LABEL")
+	s.pruningPrefix = os.Getenv("BACKUP_PRUNING_PREFIX")
+	s.start = time.Now()
+
 	return nil
 }
 
@@ -127,8 +153,9 @@ func (s *script) init() error {
 // sure containers are being restarted if required.
 func (s *script) stopContainersAndRun(thunk func() error) error {
 	if s.cli == nil {
-		return nil
+		return thunk()
 	}
+
 	allContainers, err := s.cli.ContainerList(s.ctx, types.ContainerListOptions{
 		Quiet: true,
 	})
@@ -138,7 +165,7 @@ func (s *script) stopContainersAndRun(thunk func() error) error {
 
 	containerLabel := fmt.Sprintf(
 		"docker-volume-backup.stop-during-backup=%s",
-		os.Getenv("BACKUP_STOP_CONTAINER_LABEL"),
+		s.containerLabel,
 	)
 	containersToStop, err := s.cli.ContainerList(s.ctx, types.ContainerListOptions{
 		Quiet: true,
@@ -152,7 +179,7 @@ func (s *script) stopContainersAndRun(thunk func() error) error {
 		return fmt.Errorf("stopContainersAndRun: error querying for containers to stop: %w", err)
 	}
 	s.logger.Infof(
-		"Stopping %d containers labeled `%s` out of %d running containers.",
+		"Stopping %d containers labeled `%s` out of %d running container(s).",
 		len(containersToStop),
 		containerLabel,
 		len(allContainers),
@@ -215,7 +242,7 @@ func (s *script) stopContainersAndRun(thunk func() error) error {
 				err,
 			)
 		}
-		s.logger.Infof("Successfully restarted %d containers.", len(stoppedContainers))
+		s.logger.Infof("Restarted %d container(s) and the matching service(s).", len(stoppedContainers))
 		return nil
 	}()
 
@@ -237,15 +264,11 @@ func (s *script) stopContainersAndRun(thunk func() error) error {
 // takeBackup creates a tar archive of the configured backup location and
 // saves it to disk.
 func (s *script) takeBackup() error {
-	outBytes, err := exec.Command("date", fmt.Sprintf("+%s", s.file)).Output()
+	s.file = timeutil.Strftime(&s.start, s.file)
-	if err != nil {
-		return fmt.Errorf("takeBackup: error formatting filename template: %w", err)
-	}
-	s.file = strings.TrimSpace(string(outBytes))
 	if err := targz.Compress(s.sources, s.file); err != nil {
 		return fmt.Errorf("takeBackup: error compressing backup folder: %w", err)
 	}
-	s.logger.Infof("Successfully created backup of `%s` at `%s`.", s.sources, s.file)
+	s.logger.Infof("Created backup of `%s` at `%s`.", s.sources, s.file)
 	return nil
 }
 
@@ -253,7 +276,7 @@ func (s *script) takeBackup() error {
 // In case no passphrase is given it returns early, leaving the backup file
 //  untouched.
 func (s *script) encryptBackup() error {
-	if s.passphrase == "" {
+	if s.passphrase == nil {
 		return nil
 	}
 
@@ -287,8 +310,9 @@ func (s *script) encryptBackup() error {
 	if err := os.Remove(s.file); err != nil {
 		return fmt.Errorf("encryptBackup: error removing unencrpyted backup: %w", err)
 	}
+
 	s.file = gpgFile
-	s.logger.Infof("Successfully encrypted backup using given passphrase, saving as `%s`.", s.file)
+	s.logger.Infof("Encrypted backup using given passphrase, saving as `%s`.", s.file)
 	return nil
 }
 
@@ -303,14 +327,14 @@ 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 a copy of backup `%s` to bucket `%s`", s.file, s.bucket)
+		s.logger.Infof("Uploaded a copy of backup `%s` to bucket `%s`", s.file, s.bucket)
 	}
 
 	if _, err := os.Stat(s.archive); !os.IsNotExist(err) {
 		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)
+		s.logger.Infof("Stored copy of backup `%s` in local archive `%s`", s.file, s.archive)
 	}
 	return nil
 }
@@ -320,7 +344,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 up local artifacts.")
+	s.logger.Info("Cleaned up local artifacts.")
 	return nil
 }
 
@@ -328,29 +352,22 @@ func (s *script) cleanBackup() error {
 // the given configuration. In case the given configuration would delete all
 // backups, it does nothing instead.
 func (s *script) pruneOldBackups() error {
-	retention := os.Getenv("BACKUP_RETENTION_DAYS")
+	if s.retentionDays == nil {
-	if retention == "" {
 		return nil
 	}
-	retentionDays, err := strconv.Atoi(retention)
-	if err != nil {
-		return fmt.Errorf("pruneOldBackups: error parsing BACKUP_RETENTION_DAYS as int: %w", err)
-	}
-	leeway := os.Getenv("BACKUP_PRUNING_LEEWAY")
-	sleepFor, err := time.ParseDuration(leeway)
-	if err != nil {
-		return fmt.Errorf("pruneBackups: error parsing given leeway value: %w", err)
-	}
-	s.logger.Infof("Sleeping for %s before pruning backups.", leeway)
-	time.Sleep(sleepFor)
 
-	s.logger.Infof("Trying to prune backups older than %d days now.", retentionDays)
+	if s.leeway != nil {
-	deadline := time.Now().AddDate(0, 0, -retentionDays)
+		s.logger.Infof("Sleeping for %s before pruning backups.", s.leeway)
+		time.Sleep(*s.leeway)
+	}
+
+	s.logger.Infof("Trying to prune backups older than %d day(s) now.", *s.retentionDays)
+	deadline := s.start.AddDate(0, 0, -*s.retentionDays)
 
 	if s.bucket != "" {
 		candidates := s.mc.ListObjects(s.ctx, s.bucket, minio.ListObjectsOptions{
 			WithMetadata: true,
-			Prefix:       os.Getenv("BACKUP_PRUNING_PREFIX"),
+			Prefix:       s.pruningPrefix,
 		})
 
 		var matches []minio.ObjectInfo
@@ -383,13 +400,13 @@ func (s *script) pruneOldBackups() error {
 
 			if len(errors) != 0 {
 				return fmt.Errorf(
-					"pruneOldBackups: %d errors removing files from remote storage: %w",
+					"pruneOldBackups: %d error(s) removing files from remote storage: %w",
 					len(errors),
 					errors[0],
 				)
 			}
 			s.logger.Infof(
-				"Successfully pruned %d out of %d remote backups as their age exceeded the configured retention period.",
+				"Pruned %d out of %d remote backup(s) as their age exceeded the configured retention period.",
 				len(matches),
 				lenCandidates,
 			)
@@ -399,13 +416,13 @@ func (s *script) pruneOldBackups() error {
 				len(matches),
 			)
 		} else {
-			s.logger.Infof("None of %d remote backups were pruned.", lenCandidates)
+			s.logger.Infof("None of %d remote backup(s) were pruned.", lenCandidates)
 		}
 	}
 
 	if _, err := os.Stat(s.archive); !os.IsNotExist(err) {
 		candidates, err := filepath.Glob(
-			path.Join(s.archive, fmt.Sprintf("%s*", os.Getenv("BACKUP_PRUNING_PREFIX"))),
+			path.Join(s.archive, fmt.Sprintf("%s*", s.pruningPrefix)),
 		)
 		if err != nil {
 			return fmt.Errorf(
@@ -438,13 +455,13 @@ func (s *script) pruneOldBackups() error {
 			}
 			if len(errors) != 0 {
 				return fmt.Errorf(
-					"pruneOldBackups: %d errors deleting local files, starting with: %w",
+					"pruneOldBackups: %d error(s) deleting local files, starting with: %w",
 					len(errors),
 					errors[0],
 				)
 			}
 			s.logger.Infof(
-				"Successfully pruned %d out of %d local backups as their age exceeded the configured retention period.",
+				"Pruned %d out of %d local backup(s) as their age exceeded the configured retention period.",
 				len(matches),
 				len(candidates),
 			)
@@ -454,7 +471,7 @@ func (s *script) pruneOldBackups() error {
 				len(matches),
 			)
 		} else {
-			s.logger.Infof("None of %d local backups were pruned.", len(candidates))
+			s.logger.Infof("None of %d local backup(s) were pruned.", len(candidates))
 		}
 	}
 	return nil

entrypoint.sh

@@ -17,7 +17,7 @@ BACKUP_FILENAME="${BACKUP_FILENAME:-backup-%Y-%m-%dT%H-%M-%S.tar.gz}"
 BACKUP_ARCHIVE="${BACKUP_ARCHIVE:-/archive}"
 
 BACKUP_RETENTION_DAYS="${BACKUP_RETENTION_DAYS:-}"
-BACKUP_PRUNING_LEEWAY="${BACKUP_PRUNING_LEEWAY:-10m}"
+BACKUP_PRUNING_LEEWAY="${BACKUP_PRUNING_LEEWAY:-1m}"
 BACKUP_PRUNING_PREFIX="${BACKUP_PRUNING_PREFIX:-}"
 BACKUP_STOP_CONTAINER_LABEL="${BACKUP_STOP_CONTAINER_LABEL:-true}"
 

go.mod

@@ -5,7 +5,9 @@ go 1.17
 require (
 	github.com/docker/docker v20.10.8+incompatible
 	github.com/joho/godotenv v1.3.0
+	github.com/leekchan/timeutil v0.0.0-20150802142658-28917288c48d
 	github.com/minio/minio-go/v7 v7.0.12
+	github.com/sirupsen/logrus v1.8.1
 	github.com/walle/targz v0.0.0-20140417120357-57fe4206da5a
 	golang.org/x/crypto v0.0.0-20210817164053-32db794688a5
 )
@@ -32,7 +34,6 @@ require (
 	github.com/opencontainers/image-spec v1.0.1 // indirect
 	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/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

go.sum

@@ -401,6 +401,8 @@ github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfn
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/pty v1.1.5/go.mod h1:9r2w37qlBe7rQ6e1fg1S/9xpWHSnaqNdHD3WcMdbPDA=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/leekchan/timeutil v0.0.0-20150802142658-28917288c48d h1:2puqoOQwi3Ai1oznMOsFIbifm6kIfJaLLyYzWD4IzTs=
+github.com/leekchan/timeutil v0.0.0-20150802142658-28917288c48d/go.mod h1:hO90vCP2x3exaSH58BIAowSKvV+0OsY21TtzuFGHON4=
 github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ=
 github.com/mailru/easyjson v0.0.0-20190614124828-94de47d64c63/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc=
 github.com/mailru/easyjson v0.0.0-20190626092158-b2ccc519800e/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc=