Locked issue every now and then?

Getting Help
1

Hi,
I was wondering if someone could shed some light on the issue im having. Every now and then im getting this

Fatal: unable to create lock in backend: repository is already locked exclusively by PID 29772 on artemis by  (UID 0, GID 0) lock was created at 2018-12-20 23:50:24 (23h38m40.644634632s ago) storage ID 86c670a2
   Fatal: unable to create lock in backend: repository is already locked exclusively by PID 29772 on artemis by  (UID 0, GID 0) lock was created at 2018-12-20 23:50:24 (23h38m41.174926977s ago) storage ID 86c670a2
       Fatal: unable to create lock in backend: repository is already locked exclusively by PID 29772 on artemis by  (UID 0, GID 0) lock was created at 2018-12-20 23:50:24 (23h38m41.765175592s ago) storage ID 86c670a2 using temporary cache in /tmp/restic-check-cache-460364597 create exclusive lock for repository
       Fatal: unable to create lock in backend: repository is already locked exclusively by PID 29772 on artemis by  (UID 0, GID 0) lock was created at 2018-12-20 23:50:24 (23h38m42.291814773s ago) storage ID 86c670a2

i can fix the issue temporary with this

     restic -r /media/mybackuplocation/ unlock --cleanup-cache

around 3-5 days later the same issue any ideas??

Thank you

2

Could it be that you use a script of some sort? Did you check what is behind PID 29772?

3

Thanks for the reply, sorry for the late reply as i thought i was going to get a notification by email when someone posts. I going to check again as after running the command unlock have to wait around 2-3 days till it happens ill post back

4

So i got this today

     Dec 29 2018 10:58:54 -05: backup-script started
  open repository
      Fatal: unable to create lock in backend: repository is already locked exclusively by PID 25567 on  artemis by  (UID 0, GID 0)
     lock was created at 2018-12-28 04:04:05 (30h54m49.001449248s ago)
      storage ID a1af4939
      Fatal: unable to create lock in backend: repository is already locked exclusively by PID 25567 on artemis by  (UID 0, GID 0)
    lock was created at 2018-12-28 04:04:05 (30h54m49.526534737s ago)
   storage ID a1af4939
  Fatal: unable to create lock in backend: repository is already locked exclusively by PID 25567 on artemis    by  (UID 0, GID 0)
   lock was created at 2018-12-28 04:04:05 (30h54m50.049234939s ago)
  storage ID a1af4939
   using temporary cache in /tmp/restic-check-cache-798180258
  create exclusive lock for repository
    Fatal: unable to create lock in backend: repository is already locked exclusively by PID 25567 on artemis by  (UID 0, GID 0)
  lock was created at 2018-12-28 04:04:05 (30h54m50.579373155s ago)
 storage ID a1af4939

i ran htop but did not find that PID not sure what service its using with that PID

5

Ok so again, are you running restic manually or are you runnning restic via a script?

If it is automated using a script, are you sure that there is no prune job running still? Because prune exclusively locks the repository.
Also one thing that comes to mind is: if you are using a script/automation maybe your restic command did not successfully finish and the lock is still on the repository; a stale lock.
Something at “2018-12-28 04:04:05” must be running that created this lock.

My recommendation is that you should find out what is running during this time and then move on from there.

6

Thanks for the reply, yes a script im running, funny thing is that i have the same script for another box and works perfectly. i ran this manually and got this not sure if its supposed to say killed rather then no errors found?

root@artemis:~# restic -r /media/myresticfiles/ check --cleanup-cache
 using temporary cache in /tmp/restic-check-cache-688441610
enter password for repository:
 repository e6b69cb5 opened successfully, password is correct
   create exclusive lock for repository
  load indexes
  check all packs
  check snapshots, trees and blobs
 Killed
7

“Killed” is definitely not normal.

Check the kernel logs. My suspicion is that the system ran out of memory, and the kernel’s OOM killer decided to kill restic.

1 Like
8

Thanks for the reply, you were right

  Dec 30 12:07:04 artemis kernel: [1514035.558175] Out of memory: Kill process 29516 (restic) score 874 or    sacrifice child
   Dec 30 12:07:04 artemis kernel: [1514035.558634] Killed process 29516 (restic) total-vm:1100440kB,       anon-rss:493068kB, file-rss:0kB

Im going to give more ran and check it out ill post back

9

so after running check again and gave it more ram still getting an issue but im getting a different error. Whats odd i also have another 3 restic backups on the same machine and no issue

 goroutine 181 [select]:
github.com/restic/restic/internal/checker.(*Checker).checkTreeWorker(0xc42001c90                                                                                                                                                                0, 0xc0a2a0, 0xc42001dbc0, 0xc420bae780, 0xc420ccc960, 0xc4202194b0)
     src/github.com/restic/restic/internal/checker/checker.go:390 +0x254
 created by github.com/restic/restic/internal/checker.(*Checker).Structure
    src/github.com/restic/restic/internal/checker/checker.go:552 +0x44c

goroutine 182 [select]:
    github.com/restic/restic/internal/checker.loadTreeWorker(0xc0a2a0, 0xc42001dbc0,                                                                                                                                                                     0xc125a0, 0xc4201d76c0, 0xc420bae6c0, 0xc420bae720, 0xc4202194b0)
      src/github.com/restic/restic/internal/checker/checker.go:351 +0x1f6
   created by github.com/restic/restic/internal/checker.(*Checker).Structure
    src/github.com/restic/restic/internal/checker/checker.go:551 +0x3e6

 goroutine 183 [select]:
github.com/restic/restic/internal/checker.(*Checker).checkTreeWorker(0xc42001c90                                                                                                                                                                0, 0xc0a2a0, 0xc42001dbc0, 0xc420bae780, 0xc420ccc960, 0xc4202194b0)
      src/github.com/restic/restic/internal/checker/checker.go:390 +0x254
created by github.com/restic/restic/internal/checker.(*Checker).Structure
    src/github.com/restic/restic/internal/checker/checker.go:552 +0x44c
10

Is there any more of the backtrace? This output doesn’t contain any kind of error description.

11

what i ended up doing is deleting and creating a new repo and fixed that issue and that fixed the issue funny how it was saying out of ram on the logs.

12

Memory usage is proportional to the number of files saved in all the snapshots combined. Did you maybe backup directories with a huge number of files, like e.g. maildirs?

13

Thanks for the reply, what i did was to delete and recreate the repo and fixed it same procedure and same script odd but i guess it did the trick