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

@@ -760,7 +760,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)
 	}
 
@@ -834,7 +834,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
@@ -911,7 +911,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 +932,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))
 		}