diff --git a/constants/global.go b/constants/global.go index 487a4004..519f80ef 100644 --- a/constants/global.go +++ b/constants/global.go @@ -31,7 +31,7 @@ const ( MinResticLockRetryDelay = 15 * time.Second MaxResticLockRetryDelay = 30 * time.Minute MaxResticLockRetryTimeArgument = 10 * time.Minute - MinResticStaleLockAge = 30 * time.Minute + MinResticStaleLockAge = 15 * time.Minute ) // Schedule lock mode config options diff --git a/docs/content/usage/locks/index.md b/docs/content/usage/locks/index.md index 77336c5c..b9341560 100644 --- a/docs/content/usage/locks/index.md +++ b/docs/content/usage/locks/index.md @@ -121,7 +121,7 @@ In some cases, resticprofile as well as restic may leave a lock behind if the pr For that matter, if you add the flag `force-inactive-lock` to your profile, resticprofile will detect and remove stale locks: * **resticprofile locks**: Check for the presence of a process with the PID indicated in the lockfile. If it can't find any, it will try to delete the lock and continue the operation (locking again, running profile and so on...) -* **restic locks**: Evaluate if a restic command failed on acquiring a lock. If the lock is older than `restic-stale-lock-age`, invoke `restic unlock` and retry the command that failed (can be disabled by setting `restic-stale-lock-age` to 0, default is 2h). +* **restic locks**: Evaluate if a restic command failed on acquiring a lock. If the lock is older than `restic-stale-lock-age`, invoke `restic unlock` and retry the command that failed (can be disabled by setting `restic-stale-lock-age` to 0, default is 1h). {{< tabs groupId="config-with-json" >}} {{% tab name="toml" %}} diff --git a/wrapper.go b/wrapper.go index c83add0d..1bab9fca 100644 --- a/wrapper.go +++ b/wrapper.go @@ -370,8 +370,7 @@ func (r *resticWrapper) prepareCommand(command string, args *shell.Args, allowEx } // Add retry-lock (supported from restic 0.16, depends on filter being enabled) - lockRetryFlag := fmt.Sprintf("--%s", constants.ParameterRetryLock) - if enabled, lockRetryTime := r.remainingLockRetryTime(); enabled && filter != nil { + if lockRetryTime, enabled := r.remainingLockRetryTime(); enabled && filter != nil { // limiting the retry handling in restic, we need to make sure we can retry internally so that unlock is called. lockRetryTime = lockRetryTime - r.global.ResticLockRetryAfter - constants.MinResticLockRetryDelay if lockRetryTime > constants.MaxResticLockRetryTimeArgument { @@ -379,7 +378,7 @@ func (r *resticWrapper) prepareCommand(command string, args *shell.Args, allowEx } lockRetryTime = lockRetryTime.Truncate(time.Minute) - if lockRetryTime > 0 && !r.containsArguments(args.GetAll(), lockRetryFlag) { + if lockRetryTime > 0 && !r.containsArguments(args.GetAll(), fmt.Sprintf("--%s", constants.ParameterRetryLock)) { args.AddFlag(constants.ParameterRetryLock, fmt.Sprintf("%.0fm", lockRetryTime.Minutes()), shell.ArgConfigEscape) } } @@ -760,7 +759,7 @@ func (r *resticWrapper) canRetryAfterError(command string, summary monitor.Summa if r.executionTime < 0 { r.executionTime = 0 } - clog.Debugf("repository lock failed when running '%s', counted execution time %s", command, r.executionTime) + clog.Debugf("repository lock failed when running '%s', counted execution time %s", command, r.executionTime.Truncate(time.Second)) retry, sleep = r.canRetryAfterRemoteLockFailure(output) } @@ -816,7 +815,7 @@ func (r *resticWrapper) canRetryAfterRemoteLockFailure(output monitor.OutputAnal } // Check if we have time left to wait on a non-stale lock - if enabled, remainingTime := r.remainingLockRetryTime(); enabled && remainingTime > 0 { + if remainingTime, enabled := r.remainingLockRetryTime(); enabled && remainingTime > 0 { retryDelay := r.global.ResticLockRetryAfter if retryDelay < constants.MinResticLockRetryDelay { retryDelay = constants.MinResticLockRetryDelay @@ -834,7 +833,7 @@ func (r *resticWrapper) canRetryAfterRemoteLockFailure(output monitor.OutputAnal lockName = fmt.Sprintf("%s locked by %s", lockName, lockedBy) } if r.lockWait != nil { - logLockWait(lockName, r.startTime, time.Unix(0, 0), *r.lockWait) + logLockWait(lockName, r.startTime, time.Unix(0, 0), r.executionTime, *r.lockWait) } return true, retryDelay @@ -845,7 +844,7 @@ func (r *resticWrapper) canRetryAfterRemoteLockFailure(output monitor.OutputAnal return false, 0 } -func (r *resticWrapper) remainingLockRetryTime() (enabled bool, remaining time.Duration) { +func (r *resticWrapper) remainingLockRetryTime() (remaining time.Duration, enabled bool) { enabled = r.global.ResticLockRetryAfter > 0 && r.lockWait != nil if enabled { elapsedTime := time.Since(r.startTime) @@ -911,7 +910,7 @@ func lockRun(lockFile string, force bool, lockWait *time.Duration, run func(setP } if time.Since(start) < *lockWait { lockName := fmt.Sprintf("%s locked by %s", lockFile, locker) - lockWaitLogged = logLockWait(lockName, start, lockWaitLogged, *lockWait) + lockWaitLogged = logLockWait(lockName, start, lockWaitLogged, 0, *lockWait) sleep := 3 * time.Second if sleep > *lockWait { @@ -932,15 +931,16 @@ func lockRun(lockFile string, force bool, lockWait *time.Duration, run func(setP const logLockWaitEvery = 5 * time.Minute -func logLockWait(lockName string, started, lastLogged time.Time, maxLockWait time.Duration) time.Time { +func logLockWait(lockName string, started, lastLogged time.Time, executed, maxLockWait time.Duration) time.Time { now := time.Now() lastLog := now.Sub(lastLogged) elapsed := now.Sub(started).Truncate(time.Second) + waited := (elapsed - executed).Truncate(time.Second) remaining := (maxLockWait - elapsed).Truncate(time.Second) if lastLog > logLockWaitEvery { if elapsed > logLockWaitEvery { - clog.Infof("lock wait (remaining %s / elapsed %s): %s", remaining, elapsed, strings.TrimSpace(lockName)) + clog.Infof("lock wait (remaining %s / waited %s / elapsed %s): %s", remaining, waited, elapsed, strings.TrimSpace(lockName)) } else { clog.Infof("lock wait (remaining %s): %s", remaining, strings.TrimSpace(lockName)) }