From b93c780dc325b529b340127e1e384fc990962059 Mon Sep 17 00:00:00 2001 From: Sam Lin Date: Thu, 14 Dec 2023 16:32:10 -0600 Subject: [PATCH] Add plan name to log messages, and improve logs (#101) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Add plan name to log messages, and improve logs * 🐞 fix: avoid security risk by not using command directly --- pkg/backup/backup.go | 1 + pkg/backup/local.go | 60 ++++++++++++++++++++++++++++++------------ pkg/backup/validate.go | 6 ++--- pkg/config/plan.go | 2 +- pkg/restore/restore.go | 10 +++---- 5 files changed, 53 insertions(+), 26 deletions(-) diff --git a/pkg/backup/backup.go b/pkg/backup/backup.go index 5650339..f6e0661 100644 --- a/pkg/backup/backup.go +++ b/pkg/backup/backup.go @@ -20,6 +20,7 @@ func Run(plan config.Plan, conf *config.AppConfig, modules *config.ModuleConfig) archive, mlog, err := dump(plan, tmpPath, t1.UTC()) log.WithFields(log.Fields{ + "plan": plan.Name, "archive": archive, "mlog": mlog, "err": err, diff --git a/pkg/backup/local.go b/pkg/backup/local.go index f40a2f7..3f9eaee 100644 --- a/pkg/backup/local.go +++ b/pkg/backup/local.go @@ -6,6 +6,7 @@ import ( "os" "path/filepath" "regexp" + "sort" "strings" "time" @@ -29,7 +30,7 @@ func localBackup(file string, storagePath string, mlog string, plan config.Plan) } // check if log file exists, is not always created if _, err := os.Stat(mlog); os.IsNotExist(err) { - log.Debug("appears no log file was generated") + log.WithField("plan", plan.Name).Debug("appears no log file was generated") } else { err = sh.Command("cp", mlog, planDir).Run() if err != nil { @@ -57,27 +58,38 @@ func dump(plan config.Plan, tmpPath string, ts time.Time) (string, string, error dumpCmd := BuildDumpCmd(archive, plan.Target) timeout := time.Duration(plan.Scheduler.Timeout) * time.Minute - log.Debugf("dump cmd: %v", strings.Replace(dumpCmd, fmt.Sprintf(`-p "%v"`, plan.Target.Password), "-p xxxx", -1)) + log.WithField("plan", plan.Name).Debugf("dump cmd: %v", strings.Replace(dumpCmd, fmt.Sprintf(`-p "%v"`, plan.Target.Password), "-p xxxx", -1)) output, retryCount, err := runDump(dumpCmd, plan.Retry, archive, retryCount, timeout) if err != nil { ex := "" if len(output) > 0 { ex = strings.Replace(string(output), "\n", " ", -1) } - return "", "", errors.Wrapf(err, "after %v retries, mongodump log %v", retryCount, ex) + return archive, mlog, errors.Wrapf(err, "after %v retries, mongodump log %v", retryCount, ex) } if plan.Validation != nil { backupResult := getDumpedDocMap(string(output)) - if isValidate, err := ValidateBackup(archive, plan, backupResult); !isValidate || err != nil { - client, ctx, err := GetMongoClient(BuildUri(plan.Validation.Database)) - if err != nil { - return "", "", errors.Wrapf(err, "Failed to validate backup, failed to get mongo client for cleanup") + isValidate, validateErr := ValidateBackup(archive, plan, backupResult) + if !isValidate || validateErr != nil { + client, ctx, mongoErr := GetMongoClient(BuildUri(plan.Validation.Database)) + if mongoErr != nil { + if validateErr != nil { + combinedError := fmt.Errorf("backup validation failed: %v; additionally, failed to get mongo client for cleanup: %v", validateErr, mongoErr) + return archive, mlog, combinedError + } + return archive, mlog, errors.Wrapf(mongoErr, "Failed to validate backup, failed to get mongo client for cleanup") } defer Dispose(client, ctx) - if err = cleanMongo(plan.Validation.Database.Database, client); err != nil { - return "", "", errors.Wrapf(err, "Failed to validate backup, failed to clean mongo validation database") + if cleanErr := cleanMongo(plan.Validation.Database.Database, client); cleanErr != nil { + if validateErr != nil { + combinedError := fmt.Errorf("backup validation failed: %v; additionally, failed to clean mongo validation database: %v", validateErr, cleanErr) + return archive, mlog, combinedError + } + return archive, mlog, errors.Wrapf(cleanErr, "Failed to validate backup, failed to clean mongo validation database") + } + if validateErr != nil { + return archive, mlog, errors.Wrapf(validateErr, "backup validation failed") } - return "", "", errors.Wrapf(err, "backup validation failed") } } logToFile(mlog, output) @@ -133,16 +145,30 @@ func logToFile(file string, data []byte) error { } func applyRetention(path string, retention int) error { - gz := fmt.Sprintf("cd %v && rm -f $(ls -1t *.gz *.gz.encrypted | tail -n +%v)", path, retention+1) - err := sh.Command("/bin/sh", "-c", gz).Run() - if err != nil { + // Function to delete files based on retention policy + deleteFiles := func(pattern string) error { + files, err := filepath.Glob(filepath.Join(path, pattern)) + if err != nil { + return err + } + sort.Sort(sort.Reverse(sort.StringSlice(files))) + if len(files) > retention { + for _, file := range files[retention:] { + if err := os.Remove(file); err != nil { + return err + } + } + } + return nil + } + + log.Debug("applying retention to *.gz* files") + if err := deleteFiles("*.gz*"); err != nil { return errors.Wrapf(err, "removing old gz files from %v failed", path) } - log.Debug("apply retention") - log := fmt.Sprintf("cd %v && rm -f $(ls -1t *.log | tail -n +%v)", path, retention+1) - err = sh.Command("/bin/sh", "-c", log).Run() - if err != nil { + log.Debug("applying retention to *.log files") + if err := deleteFiles("*.log"); err != nil { return errors.Wrapf(err, "removing old log files from %v failed", path) } diff --git a/pkg/backup/validate.go b/pkg/backup/validate.go index a2c880d..9a42b16 100644 --- a/pkg/backup/validate.go +++ b/pkg/backup/validate.go @@ -19,7 +19,7 @@ import ( func ValidateBackup(archive string, plan config.Plan, backupResult map[string]string) (bool, error) { output, err := RunRestore(archive, plan) if err != nil { - log.Error("Validation: Failed to execute restore command. restore failed, cleaning up") + log.WithField("plan", plan.Name).Error("Validation: Failed to execute restore command. restore failed, cleaning up") return false, errors.Wrapf(err, "failed to execute restore command") } if err := CheckIfAnyFailure(string(output)); err != nil { @@ -88,7 +88,7 @@ func checkRetoreDatabase(backupResult map[string]string, collectionNames []strin func RunRestore(archive string, plan config.Plan) ([]byte, error) { restoreCmd := BuildRestoreCmd(archive, plan.Target, plan.Validation.Database) - log.Infof("Validation: restore backup with : %v", restoreCmd) + log.WithField("plan", plan.Name).Infof("Validation: restore backup with : %v", restoreCmd) output, err := sh.Command("/bin/sh", "-c", restoreCmd).SetTimeout(time.Duration(plan.Scheduler.Timeout) * time.Minute).CombinedOutput() if err != nil { ex := "" @@ -97,7 +97,7 @@ func RunRestore(archive string, plan config.Plan) ([]byte, error) { } return nil, errors.Wrapf(err, "mongorestore log %v", ex) } - log.Debugf("restore output: %v", string(output)) + log.WithField("plan", plan.Name).Debugf("restore output: %v", string(output)) return output, nil } diff --git a/pkg/config/plan.go b/pkg/config/plan.go index a7fa00d..4f8888e 100644 --- a/pkg/config/plan.go +++ b/pkg/config/plan.go @@ -190,7 +190,7 @@ func LoadPlans(dir string) ([]Plan, error) { return nil, errors.Wrapf(err, "Marshaling %v failed", plan) } - log.Debugf("Loaded plan %v, plan JSON: %s", plan.Name, planJSON) + log.WithField("plan", plan.Name).Debugf("Loaded plan %v, plan JSON: %s", plan.Name, planJSON) } plans = append(plans, plan) diff --git a/pkg/restore/restore.go b/pkg/restore/restore.go index 2fa656b..6e0f277 100644 --- a/pkg/restore/restore.go +++ b/pkg/restore/restore.go @@ -15,9 +15,9 @@ import ( func Run(plan config.Plan, conf *config.AppConfig, modules *config.ModuleConfig, backupPath string) (backup.Result, error) { t1 := time.Now() - log.Debugf("Running restore for plan %v, backupPath %v", plan.Name, backupPath) + log.WithField("plan", plan.Name).Debugf("Running restore for plan %v, backupPath %v", plan.Name, backupPath) restoreCmd := backup.BuildRestoreCmd(backupPath, plan.Target, plan.Target) - log.Infof("Running restore command with : %v", restoreCmd) + log.WithField("plan", plan.Name).Infof("Running restore command with : %v", restoreCmd) fi, err := os.Stat(backupPath) res := backup.Result{ @@ -32,18 +32,18 @@ func Run(plan config.Plan, conf *config.AppConfig, modules *config.ModuleConfig, res.Size = fi.Size() output, err := backup.RunRestore(backupPath, plan) if err != nil || backup.CheckIfAnyFailure(string(output)) != nil { - log.Error("Restore failed") + log.WithField("plan", plan.Name).Error("Restore failed") res.Duration = time.Since(t1) return res, errors.Wrapf(err, "failed to execute restore command") } - log.Debugf("Restore command output: %v", string(output)) + log.WithField("plan", plan.Name).Debugf("Restore command output: %v", string(output)) res.Status = 200 res.Duration = time.Since(t1) client, ctx, err := backup.GetMongoClient(backup.BuildUri(plan.Validation.Database)) if err == nil { defer backup.Dispose(client, ctx) } else { - log.Errorf("Failed to get mongo client: %v, depose skipped", err) + log.WithField("plan", plan.Name).Errorf("Failed to get mongo client: %v, depose skipped", err) } return res, nil }