Locked issue every now and then?


#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


Fatal unable to create lock?
#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.


#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