Also log number of objects in heap

* Hoist control for exiting script a level up

* Do not accidentally nil out errors

* Log when running schedule

* Remove duplicate log line

* Warn on cron schedule that will never run

cmd/backup/config_provider.go

@@ -38,7 +38,7 @@ func loadConfig(lookup envProxy) (*Config, error) {
 
 	var c = &Config{}
 	if err := envconfig.Process("", c); err != nil {
-		return nil, fmt.Errorf("failed to process configuration values, error: %w", err)
+		return nil, fmt.Errorf("loadConfig: failed to process configuration values: %w", err)
 	}
 
 	return c, nil
@@ -48,22 +48,29 @@ func loadEnvVars() (*Config, error) {
 	return loadConfig(os.LookupEnv)
 }
 
-func loadEnvFiles(directory string) ([]*Config, error) {
+type configFile struct {
+	name   string
+	config *Config
+}
+
+func loadEnvFiles(directory string) ([]configFile, error) {
 	items, err := os.ReadDir(directory)
 	if err != nil {
 		if os.IsNotExist(err) {
 			return nil, err
 		}
-		return nil, fmt.Errorf("failed to read files from env directory, error: %w", err)
+		return nil, fmt.Errorf("loadEnvFiles: failed to read files from env directory: %w", err)
 	}
 
-	var cs = make([]*Config, 0)
+	cs := []configFile{}
 	for _, item := range items {
-		if !item.IsDir() {
+		if item.IsDir() {
+			continue
+		}
 		p := filepath.Join(directory, item.Name())
 		envFile, err := godotenv.Read(p)
 		if err != nil {
-				return nil, fmt.Errorf("error reading config file %s, error: %w", p, err)
+			return nil, fmt.Errorf("loadEnvFiles: error reading config file %s: %w", p, err)
 		}
 		lookup := func(key string) (string, bool) {
 			val, ok := envFile[key]
@@ -71,10 +78,9 @@ func loadEnvFiles(directory string) ([]*Config, error) {
 		}
 		c, err := loadConfig(lookup)
 		if err != nil {
-				return nil, fmt.Errorf("error loading config from file %s, error: %w", p, err)
+			return nil, fmt.Errorf("loadEnvFiles: error loading config from file %s: %w", p, err)
-			}
-			cs = append(cs, c)
 		}
+		cs = append(cs, configFile{config: c, name: item.Name()})
 	}
 
 	return cs, nil

cmd/backup/cron.go

@@ -0,0 +1,29 @@
+// Copyright 2024 - Offen Authors <hioffen@posteo.de>
+// SPDX-License-Identifier: MPL-2.0
+
+package main
+
+import (
+	"time"
+
+	"github.com/robfig/cron/v3"
+)
+
+// checkCronSchedule detects whether the given cron expression will actually
+// ever be executed or not.
+func checkCronSchedule(expression string) (ok bool) {
+	defer func() {
+		if err := recover(); err != nil {
+			ok = false
+		}
+	}()
+	sched, err := cron.ParseStandard(expression)
+	if err != nil {
+		ok = false
+		return
+	}
+	now := time.Now()
+	sched.Next(now) // panics when the cron would never run
+	ok = true
+	return
+}

cmd/backup/exec.go

@@ -188,13 +188,18 @@ func (s *script) withLabeledCommands(step lifecyclePhase, cb func() error) func(
 	if s.cli == nil {
 		return cb
 	}
-	return func() error {
+	return func() (err error) {
-		if err := s.runLabeledCommands(fmt.Sprintf("docker-volume-backup.%s-pre", step)); err != nil {
+		if err = s.runLabeledCommands(fmt.Sprintf("docker-volume-backup.%s-pre", step)); err != nil {
-			return fmt.Errorf("withLabeledCommands: %s: error running pre commands: %w", step, err)
+			err = fmt.Errorf("withLabeledCommands: %s: error running pre commands: %w", step, err)
+			return
 		}
 		defer func() {
-			s.must(s.runLabeledCommands(fmt.Sprintf("docker-volume-backup.%s-post", step)))
+			derr := s.runLabeledCommands(fmt.Sprintf("docker-volume-backup.%s-post", step))
+			if err == nil && derr != nil {
+				err = derr
+			}
 		}()
-		return cb()
+		err = cb()
+		return
 	}
 }

cmd/backup/main.go

@@ -9,84 +9,121 @@ import (
 	"log/slog"
 	"os"
 	"os/signal"
+	"runtime"
 	"syscall"
 
 	"github.com/robfig/cron/v3"
 )
 
-func runScript(c *Config) (ret error) {
+type command struct {
+	logger *slog.Logger
+}
+
+func newCommand() *command {
+	return &command{
+		logger: slog.New(slog.NewTextHandler(os.Stdout, nil)),
+	}
+}
+
+func (c *command) must(err error) {
+	if err != nil {
+		c.logger.Error(
+			fmt.Sprintf("Fatal error running command: %v", err),
+			"error",
+			err,
+		)
+		os.Exit(1)
+	}
+}
+
+func runScript(c *Config) (err error) {
+	defer func() {
+		if derr := recover(); derr != nil {
+			err = fmt.Errorf("runScript: unexpected panic running script: %v", err)
+		}
+	}()
+
 	s, err := newScript(c)
 	if err != nil {
-		return err
+		err = fmt.Errorf("runScript: error instantiating script: %w", err)
+		return
 	}
 
+	runErr := func() (err error) {
 		unlock, err := s.lock("/var/lock/dockervolumebackup.lock")
 		if err != nil {
-		return err
+			err = fmt.Errorf("runScript: error acquiring file lock: %w", err)
+			return
 		}
 
 		defer func() {
-		err = unlock()
+			derr := unlock()
-		if err != nil {
+			if err == nil && derr != nil {
-			ret = err
+				err = fmt.Errorf("runScript: error releasing file lock: %w", derr)
 			}
 		}()
 
-	defer func() {
+		scriptErr := func() error {
-		if pArg := recover(); pArg != nil {
+			if err := s.withLabeledCommands(lifecyclePhaseArchive, func() (err error) {
-			if err, ok := pArg.(error); ok {
-				s.logger.Error(
-					fmt.Sprintf("Executing the script encountered a panic: %v", err),
-				)
-				if hookErr := s.runHooks(err); hookErr != nil {
-					s.logger.Error(
-						fmt.Sprintf("An error occurred calling the registered hooks: %s", hookErr),
-					)
-				}
-				ret = err
-			} else {
-				s.logger.Error(
-					fmt.Sprintf("Executing the script encountered an unrecoverable panic: %v", err),
-				)
-
-				panic(pArg)
-			}
-		}
-
-		if err := s.runHooks(nil); err != nil {
-			s.logger.Error(
-				fmt.Sprintf(
-					"Backup procedure ran successfully, but an error ocurred calling the registered hooks: %v",
-					err,
-				),
-			)
-			ret = err
-		}
-		s.logger.Info("Finished running backup tasks.")
-	}()
-
-	s.must(s.withLabeledCommands(lifecyclePhaseArchive, func() error {
 				restartContainersAndServices, err := s.stopContainersAndServices()
 				// The mechanism for restarting containers is not using hooks as it
 				// should happen as soon as possible (i.e. before uploading backups or
 				// similar).
 				defer func() {
-			s.must(restartContainersAndServices())
+					derr := restartContainersAndServices()
+					if err == nil {
+						err = derr
+					}
 				}()
 				if err != nil {
+					return
+				}
+				err = s.createArchive()
+				return
+			})(); err != nil {
 				return err
 			}
-		return s.createArchive()
-	})())
-
-	s.must(s.withLabeledCommands(lifecyclePhaseProcess, s.encryptArchive)())
-	s.must(s.withLabeledCommands(lifecyclePhaseCopy, s.copyArchive)())
-	s.must(s.withLabeledCommands(lifecyclePhasePrune, s.pruneBackups)())
 
+			if err := s.withLabeledCommands(lifecyclePhaseProcess, s.encryptArchive)(); err != nil {
+				return err
+			}
+			if err := s.withLabeledCommands(lifecyclePhaseCopy, s.copyArchive)(); err != nil {
+				return err
+			}
+			if err := s.withLabeledCommands(lifecyclePhasePrune, s.pruneBackups)(); err != nil {
+				return err
+			}
 			return nil
+		}()
+
+		if hookErr := s.runHooks(scriptErr); hookErr != nil {
+			if scriptErr != nil {
+				return fmt.Errorf(
+					"runScript: error %w executing the script followed by %w calling the registered hooks",
+					scriptErr,
+					hookErr,
+				)
+			}
+			return fmt.Errorf(
+				"runScript: the script ran successfully, but an error occurred calling the registered hooks: %w",
+				hookErr,
+			)
+		}
+		if scriptErr != nil {
+			return fmt.Errorf("runScript: error running script: %w", scriptErr)
+		}
+		return nil
+	}()
+
+	if runErr != nil {
+		s.logger.Error(
+			fmt.Sprintf("Script run failed: %v", runErr), "error", runErr,
+		)
+	}
+	return runErr
 }
 
-func runInForeground() error {
+func (c *command) runInForeground(profileCronExpression string) error {
 	cr := cron.New(
 		cron.WithParser(
 			cron.NewParser(
@@ -95,40 +132,86 @@ func runInForeground() error {
 		),
 	)
 
-	addJob := func(c *Config) error {
+	addJob := func(config *Config, name string) error {
-		_, err := cr.AddFunc(c.BackupCronExpression, func() {
+		if _, err := cr.AddFunc(config.BackupCronExpression, func() {
-			err := runScript(c)
+			c.logger.Info(
-			if err != nil {
+				fmt.Sprintf(
-				slog.Error("unexpected error during backup", "error", err)
+					"Now running script on schedule %s",
+					config.BackupCronExpression,
+				),
+			)
+			if err := runScript(config); err != nil {
+				c.logger.Error(
+					fmt.Sprintf(
+						"Unexpected error running schedule %s: %v",
+						config.BackupCronExpression,
+						err,
+					),
+					"error",
+					err,
+				)
 			}
-		})
+		}); err != nil {
-		return err
+			return fmt.Errorf("addJob: error adding schedule %s: %w", config.BackupCronExpression, err)
+		}
+
+		c.logger.Info(fmt.Sprintf("Successfully scheduled backup %s with expression %s", name, config.BackupCronExpression))
+		if ok := checkCronSchedule(config.BackupCronExpression); !ok {
+			c.logger.Warn(
+				fmt.Sprintf("Scheduled cron expression %s will never run, is this intentional?", config.BackupCronExpression),
+			)
+		}
+
+		return nil
 	}
 
 	cs, err := loadEnvFiles("/etc/dockervolumebackup/conf.d")
 	if err != nil {
 		if !os.IsNotExist(err) {
-			return fmt.Errorf("could not load config from environment files, error: %w", err)
+			return fmt.Errorf("runInForeground: could not load config from environment files: %w", err)
 		}
 
 		c, err := loadEnvVars()
 		if err != nil {
-			return fmt.Errorf("could not load config from environment variables")
+			return fmt.Errorf("runInForeground: could not load config from environment variables: %w", err)
 		} else {
-			err = addJob(c)
+			err = addJob(c, "from environment")
 			if err != nil {
-				return fmt.Errorf("could not add cron job, error: %w", err)
+				return fmt.Errorf("runInForeground: error adding job from env: %w", err)
 			}
 		}
 	} else {
-		for _, c := range cs {
+		c.logger.Info("/etc/dockervolumebackup/conf.d was found, using configuration files from this directory.")
-			err = addJob(c)
+		for _, config := range cs {
+			err = addJob(config.config, config.name)
 			if err != nil {
-				return fmt.Errorf("could not add cron job, error: %w", err)
+				return fmt.Errorf("runInForeground: error adding jobs from conf files: %w", err)
 			}
 		}
 	}
 
+	if profileCronExpression != "" {
+		if _, err := cr.AddFunc(profileCronExpression, func() {
+			memStats := runtime.MemStats{}
+			runtime.ReadMemStats(&memStats)
+			c.logger.Info(
+				"Collecting runtime information",
+				"num_goroutines",
+				runtime.NumGoroutine(),
+				"memory_heap_alloc",
+				formatBytes(memStats.HeapAlloc, false),
+				"memory_heap_inuse",
+				formatBytes(memStats.HeapInuse, false),
+				"memory_heap_sys",
+				formatBytes(memStats.HeapSys, false),
+				"memory_heap_objects",
+				memStats.HeapObjects,
+			)
+		}); err != nil {
+			return fmt.Errorf("runInForeground: error adding profiling job: %w", err)
+		}
+	}
+
 	var quit = make(chan os.Signal, 1)
 	signal.Notify(quit, syscall.SIGTERM, syscall.SIGINT)
 	cr.Start()
@@ -139,33 +222,28 @@ func runInForeground() error {
 	return nil
 }
 
-func runAsCommand() error {
+func (c *command) runAsCommand() error {
-	c, err := loadEnvVars()
+	config, err := loadEnvVars()
 	if err != nil {
-		return fmt.Errorf("could not load config from environment variables, error: %w", err)
+		return fmt.Errorf("runAsCommand: error loading env vars: %w", err)
 	}
-
+	err = runScript(config)
-	err = runScript(c)
 	if err != nil {
-		return fmt.Errorf("unexpected error during backup, error: %w", err)
+		return fmt.Errorf("runAsCommand: error running script: %w", err)
 	}
 
 	return nil
 }
 
 func main() {
-	serve := flag.Bool("foreground", false, "run the tool in the foreground")
+	foreground := flag.Bool("foreground", false, "run the tool in the foreground")
+	profile := flag.String("profile", "", "collect runtime metrics and log them periodically on the given cron expression")
 	flag.Parse()
 
-	var err error
+	c := newCommand()
-	if *serve {
+	if *foreground {
-		err = runInForeground()
+		c.must(c.runInForeground(*profile))
 	} else {
-		err = runAsCommand()
+		c.must(c.runAsCommand())
-	}
-
-	if err != nil {
-		slog.Error("ran into an issue during execution", "error", err)
-		os.Exit(1)
 	}
 }

cmd/backup/script.go

@@ -112,6 +112,12 @@ func newScript(c *Config) (*script, error) {
 			return nil, fmt.Errorf("newScript: failed to create docker client")
 		}
 		s.cli = cli
+		s.registerHook(hookLevelPlumbing, func(err error) error {
+			if err := s.cli.Close(); err != nil {
+				return fmt.Errorf("newScript: failed to close docker client: %w", err)
+			}
+			return nil
+		})
 	}
 
 	logFunc := func(logType storage.LogLevel, context string, msg string, params ...any) {
@@ -480,17 +486,6 @@ func (s *script) pruneBackups() error {
 	return nil
 }
 
-// must exits the script run prematurely in case the given error
-// is non-nil.
-func (s *script) must(err error) {
-	if err != nil {
-		s.logger.Error(
-			fmt.Sprintf("Fatal error running backup: %s", err),
-		)
-		panic(err)
-	}
-}
-
 // skipPrune returns true if the given backend name is contained in the
 // list of skipped backends.
 func skipPrune(name string, skippedBackends []string) bool {

test/confd/run.sh

@@ -13,6 +13,8 @@ docker compose up -d --quiet-pull
 # sleep until a backup is guaranteed to have happened on the 1 minute schedule
 sleep 100
 
+docker compose logs backup
+
 if [ ! -f "$LOCAL_DIR/conf.tar.gz" ]; then
   fail "Config from file was not used."
 fi