Prune/Clean not working

[JaneJeon]

The backups and the prune/clean are running with an hour+ of interval in-between, so I know for a fact that it's not actually a concurrency problem.

However, I noticed that for months, the prune/clean steps haven't been running:

Starting prune at 2023-02-08 04:00:00
unable to create lock in backend: repository is already locked by PID 56 on docker by root (UID 0, GID 0)
lock was created at 2023-02-05 19:58:26 (56h1m37.11065948s ago)
storage ID 7b519053
the `unlock` command can be used to remove stale locks

I thought maybe there's a stale lock? So I dropped a shell onto the prune container, and typed restic unlock. It worked:

# restic unlock
repository e3497749 opened successfully, password is correct
successfully removed locks

except when I try to run prune after, it complains about the exact same lock issue.

Something weird is going on with the backup/prune/clean containers and locks - it spans hours after a backup has finished, so it's not a matter of "race condition". Thoughts?

[djmaze]

So did I get you right, you run restic unlock and then prune one after another inside the prune container and it complains that the repository is locked?

[JaneJeon]

Yep - all in one shell session, too.

[djmaze]

Which type of repository do you use? Sounds like a problem in the backend.

[JaneJeon]

It is on backblaze b2, which is well-supported and I've never had issues with that backend using restic manually.

[djmaze]

I don't have an idea about this right now.

[JaneJeon]

No worries - hopefully someone else who has run into this eventually finds this thread and are able to provide some insight into this.

[gcrow]

Chiming in. I set up resticker to replace my former directly invoked restric process with b2 and am still proving it out. Today I noticed the three restic pods were in a restart loop because of a stale lock from 59 hours prior.

After clearing the lock I was unable to reproduce the full restart loop. I did however observed the same as @JaneJeon reports in my prune logs. And check my backup logs - this behaviour happens everytime.

Sharing here if it helps or if any further knowledge is out there. Will report if I find anything more useful.

restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 552.330144ms: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 720.254544ms: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 873.42004ms: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 703.28564ms: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 1.040217184s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 1.335175957s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 954.512469ms: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 1.107876242s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 1.511079094s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 2.027308147s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 3.854635449s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 4.987726727s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 4.067955962s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 5.015617898s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 6.988645419s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 8.277195667s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 10.034154425s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 10.163166574s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/1f4932b5ef>, 0, 0) returned error, retrying after 22.663987965s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Load(<lock/d890ce19ef>, 0, 0) returned error, retrying after 13.811796615s: b2_download_file_by_name: 404: File with such name does not exist.
restic-backup  | Repository found.

restic-check  | Checking configured repository 'b2:namename:/restic' ...
restic-check  | Repository found.
restic-check  |
restic-check  |
restic-check  | Scheduling check job according to cron expression.
restic-check  | new cron: 0 0 6 * * *

restic-prune  | Checking configured repository 'b2:namename:/restic' ...
restic-prune  | Repository found.
restic-prune  |
restic-prune  |
restic-prune  | Executing prune job on startup ...
restic-prune  |
restic-prune  | Starting prune at 2023-04-30 16:53:00
restic-prune  | Fatal: unable to create lock in backend: repository is already locked by PID 8 on docker by root (UID 0, GID 0)
restic-prune  | lock was created at 2023-04-30 16:52:57 (12.004408814s ago)
restic-prune  | storage ID e25eb87e
restic-prune  |
restic-prune  |
restic-prune  | Scheduling prune job according to cron expression.
restic-prune  | new cron: 0 30 4 * * *