Help: "Failed to create/acquire the lock" #508

New Issue

tomtjes · 2022-03-10T22:51:23Z

tomtjes commented

2022-03-10 22:51:23 +00:00

My backup worked flawlessly for a while, then suddenly stopped working (maybe after updating the container using docker pull).

borg break-lock /mnt/borg-repository and borgmatic borg break-lock commands seem to work (i.e. don't produce errors), but backups still fail.

(...)
/mnt/borg-repository: Pruning archives
borg prune --keep-hourly 2 --keep-daily 7 --keep-weekly 4 --keep-monthly 12 --keep-yearly 10 --prefix backup- --lock-wait 5 --stats --list --debug --show-rc /mnt/borg-repository
using builtin fallback logging configuration
38 self tests completed in 0.28 seconds
Killed stale lock c6e500bab8a2@2485378744322.47-0.
Killed stale lock c6e500bab8a2@2485378744322.49-0.
Verified integrity of /mnt/borg-repository/index.214
TAM-verified manifest
security: read previous location '/mnt/borg-repository'
security: read manifest timestamp '2022-03-10T21:23:07.942598'
security: determined newest manifest timestamp as 2022-03-10T21:23:07.942598
security: repository checks ok, allowing access
Verified integrity of /root/.cache/borg/883502b3e4b1073f7b2eca649eb1f598e35a8560f4f050d8aa6234940d41bc7b/chunks
security: read previous location '/mnt/borg-repository'
security: read manifest timestamp '2022-03-10T21:23:07.942598'
security: determined newest manifest timestamp as 2022-03-10T21:23:07.942598
security: repository checks ok, allowing access
Keeping archive (rule: hourly #1):       backup-2022-03-10T22:22:57           Thu, 2022-03-10 22:22:58 [6478f582a6d9ebf5c4993d1ef281ea0d59488523653067d921b50cb84656323f]
Cleaned up 0 uncommitted segment files (== everything after segment 214).
Verified integrity of /mnt/borg-repository/hints.214
Pruning archive (1/1):                   backup-2022-03-10T22:19:45           Thu, 2022-03-10 22:19:46 [ea5cef0c9b1d2f8b6e41b80e1adab1b1ae03538502c94bdd6f2c4e32364b308b]
Keeping archive (rule: hourly #2):       backup-2022-03-10T21:43:43           Thu, 2022-03-10 21:43:44 [d81ae8377b0af9a7130d2441b4ed26658b6e4457de17ca245f0594bf0b86db1f]
Keeping archive (rule: daily #1):        backup-2022-03-05T06:00:12           Sat, 2022-03-05 06:00:13 [8356136c7b1ec844b587a00a3753f9783c90bc7f031f58e1d2edf87e21836231]
Keeping archive (rule: daily #2):        backup-2022-03-04T06:00:10           Fri, 2022-03-04 06:00:10 [241833e486ca57e7c198538c9f00a2e211ff7b7480c80ea4e2aa0a24968bbd8b]
Keeping archive (rule: daily #3):        backup-2022-03-03T06:00:04           Thu, 2022-03-03 06:00:05 [e69e9d52b006589ac1a4928547c27da7ce1061f64d6901f1e99ac9f2da29edbc]
Keeping archive (rule: daily #4):        backup-2022-03-02T06:00:04           Wed, 2022-03-02 06:00:05 [c3a6eae3ff4691cd500106731a1d6550e8869d982b128156cf5c2fa582f8ca28]
Keeping archive (rule: daily #5):        backup-2022-03-01T06:00:10           Tue, 2022-03-01 06:00:11 [2f4473a14af648cd72b8487ca09886e84da71318a70b795fb8147eddc7a1bae9]
Keeping archive (rule: daily #6):        backup-2022-02-28T06:00:04           Mon, 2022-02-28 06:00:05 [76ed0aca89e6bc4f6f4a814584e1afed235655c1808dddec3e8501e9a38daa77]
Keeping archive (rule: daily #7):        backup-2022-02-27T06:00:04           Sun, 2022-02-27 06:00:05 [bd2f889812a4bf11d43c672f2bf1524591e05866adbecca8ede850ce81b87aae]
Keeping archive (rule: weekly[oldest] #1): backup-2022-02-24T06:00:05           Thu, 2022-02-24 06:00:06 [f2f4f3ae1e8fa609be57b22cb9ae4d3430b0a319b026baa0804b4422963734cc]
check_free_space: required bytes 546577408, free bytes 1125899906842624
security: saving state for 883502b3e4b1073f7b2eca649eb1f598e35a8560f4f050d8aa6234940d41bc7b to /root/.config/borg/security/883502b3e4b1073f7b2eca649eb1f598e35a8560f4f050d8aa6234940d41bc7b
security: current location   /mnt/borg-repository
security: key type           3
security: manifest timestamp 2022-03-10T22:36:03.542207
Verified integrity of /mnt/borg-repository/index.218
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
Deleted data:             -205.08 MB           -149.01 MB             -1.87 MB
All archives:                1.97 GB              1.46 GB            158.27 MB
                       Unique chunks         Total chunks
Chunk index:                    4307                70649
------------------------------------------------------------------------------
terminating with success status, rc 0
/mnt/borg-repository: Compacting segments
borg compact --lock-wait 5 --debug --show-rc /mnt/borg-repository
using builtin fallback logging configuration
38 self tests completed in 0.29 seconds
Failed to create/acquire the lock /mnt/borg-repository/lock.exclusive (timeout).
Traceback (most recent call last):
  File "/usr/lib/python3.9/borg/archiver.py", line 5089, in main
    exit_code = archiver.run(args)
  File "/usr/lib/python3.9/borg/archiver.py", line 5020, in run
    return set_ec(func(args))
  File "/usr/lib/python3.9/borg/archiver.py", line 168, in wrapper
    with repository:
  File "/usr/lib/python3.9/borg/repository.py", line 200, in __enter__
    self.open(self.path, bool(self.exclusive), lock_wait=self.lock_wait, lock=self.do_lock)
  File "/usr/lib/python3.9/borg/repository.py", line 431, in open
    self.lock = Lock(os.path.join(path, 'lock'), exclusive, timeout=lock_wait).acquire()
  File "/usr/lib/python3.9/borg/locking.py", line 384, in acquire
    self._wait_for_readers_finishing(remove, sleep)
  File "/usr/lib/python3.9/borg/locking.py", line 397, in _wait_for_readers_finishing
    self._lock.acquire()
  File "/usr/lib/python3.9/borg/locking.py", line 148, in acquire
    raise LockTimeout(self.path) from None
borg.locking.LockTimeout: Failed to create/acquire the lock /mnt/borg-repository/lock.exclusive (timeout).
Platform: Linux c6e500bab8a2 5.4.0-91-generic #102-Ubuntu SMP Fri Nov 5 16:31:28 UTC 2021 x86_64
Linux: Unknown Linux
Borg: 1.2.0  Python: CPython 3.9.7 msgpack: 1.0.2 fuse: llfuse 1.4.1 [pyfuse3,llfuse]
PID: 73  CWD: /root
sys.argv: ['/usr/bin/borg', 'compact', '--lock-wait', '5', '--debug', '--show-rc', '/mnt/borg-repository']
SSH_ORIGINAL_COMMAND: None
terminating with error status, rc 2
/mnt/borg-repository: Error running actions for repository
Command 'borg compact --lock-wait 5 --debug --show-rc /mnt/borg-repository' returned non-zero exit status 2.
/etc/borgmatic.d/config.yaml: Running command for on-error hook
echo "Error while creating a backup."
Error while creating a backup.
/etc/borgmatic.d/config.yaml: Error running configuration file
/etc/borgmatic.d/config.yaml: No commands to run for post-everything hook

Environment

borgmatic version: latest docker container

My backup worked flawlessly for a while, then suddenly stopped working (maybe after updating the container using `docker pull`). `borg break-lock /mnt/borg-repository` and `borgmatic borg break-lock` commands seem to work (i.e. don't produce errors), but backups still fail. ``` (...) /mnt/borg-repository: Pruning archives borg prune --keep-hourly 2 --keep-daily 7 --keep-weekly 4 --keep-monthly 12 --keep-yearly 10 --prefix backup- --lock-wait 5 --stats --list --debug --show-rc /mnt/borg-repository using builtin fallback logging configuration 38 self tests completed in 0.28 seconds Killed stale lock c6e500bab8a2@2485378744322.47-0. Killed stale lock c6e500bab8a2@2485378744322.49-0. Verified integrity of /mnt/borg-repository/index.214 TAM-verified manifest security: read previous location '/mnt/borg-repository' security: read manifest timestamp '2022-03-10T21:23:07.942598' security: determined newest manifest timestamp as 2022-03-10T21:23:07.942598 security: repository checks ok, allowing access Verified integrity of /root/.cache/borg/883502b3e4b1073f7b2eca649eb1f598e35a8560f4f050d8aa6234940d41bc7b/chunks security: read previous location '/mnt/borg-repository' security: read manifest timestamp '2022-03-10T21:23:07.942598' security: determined newest manifest timestamp as 2022-03-10T21:23:07.942598 security: repository checks ok, allowing access Keeping archive (rule: hourly #1): backup-2022-03-10T22:22:57 Thu, 2022-03-10 22:22:58 [6478f582a6d9ebf5c4993d1ef281ea0d59488523653067d921b50cb84656323f] Cleaned up 0 uncommitted segment files (== everything after segment 214). Verified integrity of /mnt/borg-repository/hints.214 Pruning archive (1/1): backup-2022-03-10T22:19:45 Thu, 2022-03-10 22:19:46 [ea5cef0c9b1d2f8b6e41b80e1adab1b1ae03538502c94bdd6f2c4e32364b308b] Keeping archive (rule: hourly #2): backup-2022-03-10T21:43:43 Thu, 2022-03-10 21:43:44 [d81ae8377b0af9a7130d2441b4ed26658b6e4457de17ca245f0594bf0b86db1f] Keeping archive (rule: daily #1): backup-2022-03-05T06:00:12 Sat, 2022-03-05 06:00:13 [8356136c7b1ec844b587a00a3753f9783c90bc7f031f58e1d2edf87e21836231] Keeping archive (rule: daily #2): backup-2022-03-04T06:00:10 Fri, 2022-03-04 06:00:10 [241833e486ca57e7c198538c9f00a2e211ff7b7480c80ea4e2aa0a24968bbd8b] Keeping archive (rule: daily #3): backup-2022-03-03T06:00:04 Thu, 2022-03-03 06:00:05 [e69e9d52b006589ac1a4928547c27da7ce1061f64d6901f1e99ac9f2da29edbc] Keeping archive (rule: daily #4): backup-2022-03-02T06:00:04 Wed, 2022-03-02 06:00:05 [c3a6eae3ff4691cd500106731a1d6550e8869d982b128156cf5c2fa582f8ca28] Keeping archive (rule: daily #5): backup-2022-03-01T06:00:10 Tue, 2022-03-01 06:00:11 [2f4473a14af648cd72b8487ca09886e84da71318a70b795fb8147eddc7a1bae9] Keeping archive (rule: daily #6): backup-2022-02-28T06:00:04 Mon, 2022-02-28 06:00:05 [76ed0aca89e6bc4f6f4a814584e1afed235655c1808dddec3e8501e9a38daa77] Keeping archive (rule: daily #7): backup-2022-02-27T06:00:04 Sun, 2022-02-27 06:00:05 [bd2f889812a4bf11d43c672f2bf1524591e05866adbecca8ede850ce81b87aae] Keeping archive (rule: weekly[oldest] #1): backup-2022-02-24T06:00:05 Thu, 2022-02-24 06:00:06 [f2f4f3ae1e8fa609be57b22cb9ae4d3430b0a319b026baa0804b4422963734cc] check_free_space: required bytes 546577408, free bytes 1125899906842624 security: saving state for 883502b3e4b1073f7b2eca649eb1f598e35a8560f4f050d8aa6234940d41bc7b to /root/.config/borg/security/883502b3e4b1073f7b2eca649eb1f598e35a8560f4f050d8aa6234940d41bc7b security: current location /mnt/borg-repository security: key type 3 security: manifest timestamp 2022-03-10T22:36:03.542207 Verified integrity of /mnt/borg-repository/index.218 ------------------------------------------------------------------------------ Original size Compressed size Deduplicated size Deleted data: -205.08 MB -149.01 MB -1.87 MB All archives: 1.97 GB 1.46 GB 158.27 MB Unique chunks Total chunks Chunk index: 4307 70649 ------------------------------------------------------------------------------ terminating with success status, rc 0 /mnt/borg-repository: Compacting segments borg compact --lock-wait 5 --debug --show-rc /mnt/borg-repository using builtin fallback logging configuration 38 self tests completed in 0.29 seconds Failed to create/acquire the lock /mnt/borg-repository/lock.exclusive (timeout). Traceback (most recent call last): File "/usr/lib/python3.9/borg/archiver.py", line 5089, in main exit_code = archiver.run(args) File "/usr/lib/python3.9/borg/archiver.py", line 5020, in run return set_ec(func(args)) File "/usr/lib/python3.9/borg/archiver.py", line 168, in wrapper with repository: File "/usr/lib/python3.9/borg/repository.py", line 200, in __enter__ self.open(self.path, bool(self.exclusive), lock_wait=self.lock_wait, lock=self.do_lock) File "/usr/lib/python3.9/borg/repository.py", line 431, in open self.lock = Lock(os.path.join(path, 'lock'), exclusive, timeout=lock_wait).acquire() File "/usr/lib/python3.9/borg/locking.py", line 384, in acquire self._wait_for_readers_finishing(remove, sleep) File "/usr/lib/python3.9/borg/locking.py", line 397, in _wait_for_readers_finishing self._lock.acquire() File "/usr/lib/python3.9/borg/locking.py", line 148, in acquire raise LockTimeout(self.path) from None borg.locking.LockTimeout: Failed to create/acquire the lock /mnt/borg-repository/lock.exclusive (timeout). Platform: Linux c6e500bab8a2 5.4.0-91-generic #102-Ubuntu SMP Fri Nov 5 16:31:28 UTC 2021 x86_64 Linux: Unknown Linux Borg: 1.2.0 Python: CPython 3.9.7 msgpack: 1.0.2 fuse: llfuse 1.4.1 [pyfuse3,llfuse] PID: 73 CWD: /root sys.argv: ['/usr/bin/borg', 'compact', '--lock-wait', '5', '--debug', '--show-rc', '/mnt/borg-repository'] SSH_ORIGINAL_COMMAND: None terminating with error status, rc 2 /mnt/borg-repository: Error running actions for repository Command 'borg compact --lock-wait 5 --debug --show-rc /mnt/borg-repository' returned non-zero exit status 2. /etc/borgmatic.d/config.yaml: Running command for on-error hook echo "Error while creating a backup." Error while creating a backup. /etc/borgmatic.d/config.yaml: Error running configuration file /etc/borgmatic.d/config.yaml: No commands to run for post-everything hook ``` #### Environment **borgmatic version:** latest docker container

witten commented

2022-03-10 23:19:04 +00:00

Huh.. I'm not sure what's going on, but it does look like Borg is indeed failing to acquire the lock. Are you sure there's not another Borg process running against that repository? Have you tried manually removing the lock file (/mnt/borg-repository/lock.exclusive)? Do you happen to know what Borg version you upgraded from and to (I assume 1.2.0)?

Huh.. I'm not sure what's going on, but it does look like Borg is indeed failing to acquire the lock. Are you sure there's not another Borg process running against that repository? Have you tried manually removing the lock file (`/mnt/borg-repository/lock.exclusive`)? Do you happen to know what Borg version you upgraded from and to (I assume 1.2.0)?

witten commented

2022-03-10 23:21:08 +00:00

Another thing to check: Does your user have permissions to actually create the lock in /mnt/borg-repository/?

Another thing to check: Does your user have permissions to actually create the lock in `/mnt/borg-repository/`?

witten added the

question / support

label 2022-03-10 23:21:16 +00:00

tomtjes commented

2022-03-11 00:04:22 +00:00

Thanks for the quick response! Yes, I'm sure there's no other Borg process. I can manually delete the lock file from inside the container and I can also create a new file (using touch test.txt). Current version is 1.2.0 but I first installed Borgmatic only 2 weeks ago or so, so not sure if there was actually an update in the meantime.

Thanks for the quick response! Yes, I'm sure there's no other Borg process. I can manually delete the lock file from inside the container and I can also create a new file (using `touch test.txt`). Current version is 1.2.0 but I first installed Borgmatic only 2 weeks ago or so, so not sure if there was actually an update in the meantime.

witten commented

2022-03-11 00:15:20 +00:00

Gotcha. A few more questions:

How is the repository mounted within the container?
When you manually delete the lock file or create a new file within the container with its mounted repository path, do those changes show up in the repository path on the host machine (outside the container)?
After you delete the lock file from inside the container, if you immediately run borgmatic in the container, do you get the same error as above (Failed to create/acquire the lock)?

Gotcha. A few more questions: * How is the repository mounted within the container? * When you manually delete the lock file or create a new file within the container with its mounted repository path, do those changes show up in the repository path on the host machine (outside the container)? * After you delete the lock file from inside the container, if you immediately run borgmatic in the container, do you get the same error as above (Failed to create/acquire the lock)?

tomtjes commented

2022-03-11 16:16:18 +00:00

How is the repository mounted within the container?

I use the Rclone docker plugin.

docker-compose.yml

services:
  borgmatic:
    image: b3vis/borgmatic
    container_name: borgmatic
    volumes:
      - ${VOLUME_SOURCE}:/mnt/source_home:ro           # backup source
      - ${VOLUME_SOURCE2}:/mnt/source_opt:ro
      - ${VOLUME_TARGET}:/mnt/borg-repository     # backup target
      - ${VOLUME_ETC_BORGMATIC}:/etc/borgmatic.d/ # borgmatic config file(s) + crontab.txt
      - ${VOLUME_BORG_CONFIG}:/root/.config/borg  # config and keyfiles
      - ${VOLUME_SSH}:/root/.ssh                  # ssh key for remote repositories
      - ${VOLUME_BORG_CACHE}:/root/.cache/borg    # checksums used for deduplication
      - /var/run/docker.sock:/var/run/docker.sock
    environment:
      - TZ=${TZ}
      - BORG_PASSPHRASE=${BORG_PASSPHRASE}
(...)
volumes:
  myserver:
    driver: rclone:latest
    driver_opts:
      remote: 'myserver_ftp:borg'
      allow_other: 'true'
      vfs_cache_mode: full
      poll_interval: 0

.env

VOLUME_TARGET=myserver

When you manually delete the lock file or create a new file within the container with its mounted repository path, do those changes show up in the repository path on the host machine (outside the container)?

yes, changes appear on the server that is mounted via rclone

After you delete the lock file from inside the container, if you immediately run borgmatic in the container, do you get the same error as above (Failed to create/acquire the lock)?

yes

> * How is the repository mounted within the container? I use the [Rclone docker plugin](https://rclone.org/docker/). docker-compose.yml ``` services: borgmatic: image: b3vis/borgmatic container_name: borgmatic volumes: - ${VOLUME_SOURCE}:/mnt/source_home:ro # backup source - ${VOLUME_SOURCE2}:/mnt/source_opt:ro - ${VOLUME_TARGET}:/mnt/borg-repository # backup target - ${VOLUME_ETC_BORGMATIC}:/etc/borgmatic.d/ # borgmatic config file(s) + crontab.txt - ${VOLUME_BORG_CONFIG}:/root/.config/borg # config and keyfiles - ${VOLUME_SSH}:/root/.ssh # ssh key for remote repositories - ${VOLUME_BORG_CACHE}:/root/.cache/borg # checksums used for deduplication - /var/run/docker.sock:/var/run/docker.sock environment: - TZ=${TZ} - BORG_PASSPHRASE=${BORG_PASSPHRASE} (...) volumes: myserver: driver: rclone:latest driver_opts: remote: 'myserver_ftp:borg' allow_other: 'true' vfs_cache_mode: full poll_interval: 0 ``` .env ``` VOLUME_TARGET=myserver ``` > * When you manually delete the lock file or create a new file within the container with its mounted repository path, do those changes show up in the repository path on the host machine (outside the container)? yes, changes appear on the server that is mounted via rclone > * After you delete the lock file from inside the container, if you immediately run borgmatic in the container, do you get the same error as above (Failed to create/acquire the lock)? yes

witten commented

2022-03-15 23:36:48 +00:00

A couple of thoughts.

You could try running the break-lock command and then borgmatic compact by itself. That would prevent any other borgmatic actions from running as well. If that works, it tells you it's some (strange) interaction with multiple borgmatic actions.
Have you tried running Borg directly to see if the problem still occurs? For instance, if you run borg compact --lock-wait 5 --debug --show-rc /mnt/borg-repository within the container and you get the same lock traceback, then that indicates an issue with Borg (and/or the rclone-mounted repository).
Given the fact that the lock is "still there" even after deleting the lock, that makes me suspect an issue with the rclone volume mount. Have you looked into clearing out the rclone cache directory?

A couple of thoughts. * You could try running the `break-lock` command and then `borgmatic compact` by itself. That would prevent any other borgmatic actions from running as well. If that works, it tells you it's some (strange) interaction with multiple borgmatic actions. * Have you tried running Borg directly to see if the problem still occurs? For instance, if you run `borg compact --lock-wait 5 --debug --show-rc /mnt/borg-repository` within the container and you get the same lock traceback, then that indicates an issue with Borg (and/or the rclone-mounted repository). * Given the fact that the lock is "still there" even after deleting the lock, that makes me suspect an issue with the rclone volume mount. Have you looked into clearing out the rclone cache directory?

tomtjes commented

2022-04-01 23:58:20 +00:00

Thanks for your ideas. I played around with them, especially with the rclone cache, but couldn't get it to work. I'm now using a local repository and rclone on the host with a cronjob.