Improved logging and aligned documentation

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

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" %}}

wrapper.go

@@ -370,16 +370,15 @@ 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 {
 			lockRetryTime = constants.MaxResticLockRetryTimeArgument
 		}
 		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))
 		}