Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 2 commits into from
Dec 14, 2023
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions pkg/backup/backup.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
31 changes: 21 additions & 10 deletions pkg/backup/local.go
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@
}
// 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 {
Expand Down Expand Up @@ -57,27 +57,38 @@
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))

Check failure

Code scanning / CodeQL

Clear-text logging of sensitive information High

Sensitive data returned by an access to Password
flows to a logging call.
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)
Expand Down Expand Up @@ -134,14 +145,14 @@

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

Check failure

Code scanning / CodeQL

Command built from user-controlled sources Critical

This command depends on a
user-provided value
.
if 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()

Check failure

Code scanning / CodeQL

Command built from user-controlled sources Critical

This command depends on a
user-provided value
.
if err != nil {
return errors.Wrapf(err, "removing old log files from %v failed", path)
}
Expand Down
6 changes: 3 additions & 3 deletions pkg/backup/validate.go
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@
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 {
Expand Down Expand Up @@ -88,7 +88,7 @@

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)
Dismissed Show dismissed Hide dismissed
output, err := sh.Command("/bin/sh", "-c", restoreCmd).SetTimeout(time.Duration(plan.Scheduler.Timeout) * time.Minute).CombinedOutput()
if err != nil {
ex := ""
Expand All @@ -97,7 +97,7 @@
}
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
}

Expand Down
2 changes: 1 addition & 1 deletion pkg/config/plan.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
10 changes: 5 additions & 5 deletions pkg/restore/restore.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,9 +15,9 @@
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)

Check failure

Code scanning / CodeQL

Clear-text logging of sensitive information High

Sensitive data returned by an access to Password
flows to a logging call.
fi, err := os.Stat(backupPath)

res := backup.Result{
Expand All @@ -32,18 +32,18 @@
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
}
Loading