From 65626dd3d4369efe8b024fa9880b8ff9b4127dc2 Mon Sep 17 00:00:00 2001 From: Frederik Ring Date: Fri, 9 Feb 2024 10:24:28 +0100 Subject: [PATCH] Hoist control for exiting script a level up (#348) * 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 | 44 +++--- cmd/backup/cron.go | 29 ++++ cmd/backup/exec.go | 15 +- cmd/backup/main.go | 256 ++++++++++++++++++++-------------- cmd/backup/script.go | 11 -- test/confd/run.sh | 2 + 6 files changed, 221 insertions(+), 136 deletions(-) create mode 100644 cmd/backup/cron.go diff --git a/cmd/backup/config_provider.go b/cmd/backup/config_provider.go index 424afab..50a588d 100644 --- a/cmd/backup/config_provider.go +++ b/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,33 +48,39 @@ 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() { - 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) + if item.IsDir() { + continue } + 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 diff --git a/cmd/backup/cron.go b/cmd/backup/cron.go new file mode 100644 index 0000000..9416591 --- /dev/null +++ b/cmd/backup/cron.go @@ -0,0 +1,29 @@ +// Copyright 2024 - Offen Authors +// 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 +} diff --git a/cmd/backup/exec.go b/cmd/backup/exec.go index 0f4f7b5..1fa0997 100644 --- a/cmd/backup/exec.go +++ b/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 { - 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) + 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 } 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 } } diff --git a/cmd/backup/main.go b/cmd/backup/main.go index c10b9b1..34211ee 100644 --- a/cmd/backup/main.go +++ b/cmd/backup/main.go @@ -14,79 +14,115 @@ import ( "github.com/robfig/cron/v3" ) -func runScript(c *Config) (ret error) { - s, err := newScript(c) - if err != nil { - return err - } - - unlock, err := s.lock("/var/lock/dockervolumebackup.lock") - if err != nil { - return err - } - - defer func() { - err = unlock() - if err != nil { - ret = err - } - }() - - 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 +type command struct { + logger *slog.Logger } -func runInForeground() error { +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 { + 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 { + err = fmt.Errorf("runScript: error acquiring file lock: %w", err) + return + } + + 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 +} + +func (c *command) runInForeground() error { cr := cron.New( cron.WithParser( cron.NewParser( @@ -95,36 +131,60 @@ func runInForeground() error { ), ) - 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) + 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, + ) } - }) - return 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 } 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 { - err = addJob(c) + 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) 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) } } } @@ -139,33 +199,27 @@ func runInForeground() error { return nil } -func runAsCommand() error { - c, err := loadEnvVars() +func (c *command) runAsCommand() error { + 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(c) + err = runScript(config) 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") flag.Parse() - var err error - if *serve { - err = runInForeground() + c := newCommand() + if *foreground { + c.must(c.runInForeground()) } else { - err = runAsCommand() - } - - if err != nil { - slog.Error("ran into an issue during execution", "error", err) - os.Exit(1) + c.must(c.runAsCommand()) } } diff --git a/cmd/backup/script.go b/cmd/backup/script.go index 324f5a0..fa9719f 100644 --- a/cmd/backup/script.go +++ b/cmd/backup/script.go @@ -480,17 +480,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 { diff --git a/test/confd/run.sh b/test/confd/run.sh index 3a5fca9..f81407a 100755 --- a/test/confd/run.sh +++ b/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