Move cron scheduling inside application (#338)

* Move cron scheduling inside application

* Make envvar a fallback and check for errors

* Panic significantly less

* propagate error out of runBackup

* Add structured logging

* FIx error propagation to exit

* Enable the new scheduler by default

* Review fixes

* Added docs and better error propagation

Dockerfile

@@ -16,5 +16,6 @@ WORKDIR /root
 RUN apk add --no-cache ca-certificates
 
 COPY --from=builder /app/cmd/backup/backup /usr/bin/backup
+COPY --chmod=755 ./entrypoint.sh /root/
 
 ENTRYPOINT ["/usr/bin/backup", "-foreground"]

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

cmd/backup/cron.go

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

cmd/backup/main.go

@@ -9,121 +9,84 @@ import (
 	"log/slog"
 	"os"
 	"os/signal"
-	"runtime"
 	"syscall"
 
 	"github.com/robfig/cron/v3"
 )
 
-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)
-		}
-	}()
-
+func runScript(c *Config) (ret error) {
 	s, err := newScript(c)
 	if err != nil {
-		err = fmt.Errorf("runScript: error instantiating script: %w", err)
-		return
+		return err
 	}
 
-	runErr := func() (err error) {
-		unlock, err := s.lock("/var/lock/dockervolumebackup.lock")
+	unlock, err := s.lock("/var/lock/dockervolumebackup.lock")
+	if err != nil {
+		return err
+	}
+
+	defer func() {
+		err = unlock()
 		if err != nil {
-			err = fmt.Errorf("runScript: error acquiring file lock: %w", err)
-			return
+			ret = err
 		}
-
-		defer func() {
-			derr := unlock()
-			if err == nil && derr != nil {
-				err = fmt.Errorf("runScript: error releasing file lock: %w", derr)
-			}
-		}()
-
-		scriptErr := func() error {
-			if err := s.withLabeledCommands(lifecyclePhaseArchive, func() (err 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() {
-					derr := restartContainersAndServices()
-					if err == nil {
-						err = derr
-					}
-				}()
-				if err != nil {
-					return
-				}
-				err = s.createArchive()
-				return
-			})(); err != nil {
-				return err
-			}
-
-			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
+	defer func() {
+		if pArg := recover(); pArg != nil {
+			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())
+		}()
+		if 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)())
+
+	return nil
 }
 
-func (c *command) runInForeground(profileCronExpression string) error {
+func runInForeground() error {
 	cr := cron.New(
 		cron.WithParser(
 			cron.NewParser(
@@ -132,86 +95,40 @@ func (c *command) runInForeground(profileCronExpression string) error {
 		),
 	)
 
-	addJob := func(config *Config, name string) error {
-		if _, err := cr.AddFunc(config.BackupCronExpression, func() {
-			c.logger.Info(
-				fmt.Sprintf(
-					"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,
-				)
+	addJob := func(c *Config) error {
+		_, err := cr.AddFunc(c.BackupCronExpression, func() {
+			err := runScript(c)
+			if err != nil {
+				slog.Error("unexpected error during backup", "error", err)
 			}
-		}); err != nil {
-			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
+		})
+		return err
 	}
 
 	cs, err := loadEnvFiles("/etc/dockervolumebackup/conf.d")
 	if err != nil {
 		if !os.IsNotExist(err) {
-			return fmt.Errorf("runInForeground: could not load config from environment files: %w", err)
+			return fmt.Errorf("could not load config from environment files, error: %w", err)
 		}
 
 		c, err := loadEnvVars()
 		if err != nil {
-			return fmt.Errorf("runInForeground: could not load config from environment variables: %w", err)
+			return fmt.Errorf("could not load config from environment variables")
 		} else {
-			err = addJob(c, "from environment")
+			err = addJob(c)
 			if err != nil {
-				return fmt.Errorf("runInForeground: error adding job from env: %w", err)
+				return fmt.Errorf("could not add cron job, error: %w", err)
 			}
 		}
 	} else {
-		c.logger.Info("/etc/dockervolumebackup/conf.d was found, using configuration files from this directory.")
-		for _, config := range cs {
-			err = addJob(config.config, config.name)
+		for _, c := range cs {
+			err = addJob(c)
 			if err != nil {
-				return fmt.Errorf("runInForeground: error adding jobs from conf files: %w", err)
+				return fmt.Errorf("could not add cron job, error: %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()
@@ -222,28 +139,33 @@ func (c *command) runInForeground(profileCronExpression string) error {
 	return nil
 }
 
-func (c *command) runAsCommand() error {
-	config, err := loadEnvVars()
+func runAsCommand() error {
+	c, err := loadEnvVars()
 	if err != nil {
-		return fmt.Errorf("runAsCommand: error loading env vars: %w", err)
+		return fmt.Errorf("could not load config from environment variables, error: %w", err)
 	}
-	err = runScript(config)
+
+	err = runScript(c)
 	if err != nil {
-		return fmt.Errorf("runAsCommand: error running script: %w", err)
+		return fmt.Errorf("unexpected error during backup, error: %w", err)
 	}
 
 	return nil
 }
 
 func main() {
-	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")
+	serve := flag.Bool("foreground", false, "run the tool in the foreground")
 	flag.Parse()
 
-	c := newCommand()
-	if *foreground {
-		c.must(c.runInForeground(*profile))
+	var err error
+	if *serve {
+		err = runInForeground()
 	} else {
-		c.must(c.runAsCommand())
+		err = runAsCommand()
+	}
+
+	if err != nil {
+		slog.Error("ran into an issue during execution", "error", err)
+		os.Exit(1)
 	}
 }

cmd/backup/script.go

@@ -112,12 +112,6 @@ 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) {
@@ -486,6 +480,17 @@ 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 {

entrypoint.sh

@@ -0,0 +1,26 @@
+#!/bin/sh
+
+# Copyright 2021 - Offen Authors <hioffen@posteo.de>
+# SPDX-License-Identifier: MPL-2.0
+
+set -e
+
+if [ ! -d "/etc/dockervolumebackup/conf.d" ]; then
+  BACKUP_CRON_EXPRESSION="${BACKUP_CRON_EXPRESSION:-@daily}"
+
+  echo "Installing cron.d entry with expression $BACKUP_CRON_EXPRESSION."
+  echo "$BACKUP_CRON_EXPRESSION backup 2>&1" | crontab -
+else
+  echo "/etc/dockervolumebackup/conf.d was found, using configuration files from this directory."
+
+  crontab -r && crontab /dev/null
+  for file in /etc/dockervolumebackup/conf.d/*; do
+    source $file
+    BACKUP_CRON_EXPRESSION="${BACKUP_CRON_EXPRESSION:-@daily}"
+    echo "Appending cron.d entry with expression $BACKUP_CRON_EXPRESSION and configuration file $file"
+    (crontab -l; echo "$BACKUP_CRON_EXPRESSION /bin/sh -c 'set -a; source $file; set +a && backup' 2>&1") | crontab -
+  done
+fi
+
+echo "Starting cron in foreground."
+crond -f -d 8

go.mod

@@ -10,14 +10,12 @@ require (
 	github.com/docker/cli v24.0.1+incompatible
 	github.com/docker/docker v24.0.7+incompatible
 	github.com/gofrs/flock v0.8.1
-	github.com/joho/godotenv v1.5.1
 	github.com/klauspost/compress v1.17.6
 	github.com/leekchan/timeutil v0.0.0-20150802142658-28917288c48d
 	github.com/minio/minio-go/v7 v7.0.66
 	github.com/offen/envconfig v1.5.0
 	github.com/otiai10/copy v1.14.0
 	github.com/pkg/sftp v1.13.6
-	github.com/robfig/cron/v3 v3.0.0
 	github.com/studio-b12/gowebdav v0.9.0
 	golang.org/x/crypto v0.18.0
 	golang.org/x/oauth2 v0.16.0
@@ -30,6 +28,8 @@ require (
 	github.com/golang-jwt/jwt/v5 v5.2.0 // indirect
 	github.com/golang/protobuf v1.5.3 // indirect
 	golang.org/x/time v0.0.0-20220609170525-579cf78fd858 // indirect
+	github.com/joho/godotenv v1.5.1 // indirect
+	github.com/robfig/cron/v3 v3.0.0 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
 	google.golang.org/protobuf v1.31.0 // indirect
 )

test/confd/run.sh

@@ -13,8 +13,6 @@ 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