Add plan name to log messages, and improve logs (#101)

* Add plan name to log messages, and improve logs

* 🐞 fix: avoid security risk by not using command directly

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,

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)
 	}
 

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
 }
 

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)

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
 }