OSError: [Errno 39] Directory not empty: '/.../lock.exclusive' (borg 1.1.x) #7154

isshwar · 2022-11-22T10:02:06Z

Hi,

I am seeing borg unable to delete lock.exclusive directory even though the directory is empty. This started happening since 10days ago and prior to that it was running without any issues.

Setup:

borg is running in a docker container - alpine:3.11.3
mounting S3 storage as filesystem using s3fs
backup is taken on the mounted file-system

was running fine until 10days ago and also is not happening every time. some days, backup is running just fine.


Exception ignored in: <function Repository.__del__ at 0x7f0087f1e8b0>
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/borg/repository.py", line 178, in __del__
    self.close()
  File "/usr/lib/python3.8/site-packages/borg/repository.py", line 427, in close
    self.lock.release()
  File "/usr/lib/python3.8/site-packages/borg/locking.py", line 383, in release
    self._roster.modify(EXCLUSIVE, REMOVE)
  File "/usr/lib/python3.8/site-packages/borg/locking.py", line 282, in modify
    elements.remove(self.id)
KeyError: ('runner-6e2b1c97-project-456-concurrent-0@24853
Local Exception
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/borg/archiver.py", line 4501, in main
    exit_code = archiver.run(args)
  File "/usr/lib/python3.8/site-packages/borg/archiver.py", line 4433, in run
    return set_ec(func(args))
  File "/usr/lib/python3.8/site-packages/borg/archiver.py", line 166, in wrapper
    return method(self, args, repository=repository, **kwargs)
  File "/usr/lib/python3.8/site-packages/borg/repository.py", line 203, in __exit__
    self.close()
  File "/usr/lib/python3.8/site-packages/borg/repository.py", line 427, in close
    self.lock.release()
  File "/usr/lib/python3.8/site-packages/borg/locking.py", line 3, in release
    self._lock.release()
  File "/usr/lib/python3.8/site-packages/borg/locking.py", line 150, in release
    os.rmdir(self.path)
OSError: [Errno 39] Directory not empty: '/mnt/prod/lock.exclusive'

The text was updated successfully, but these errors were encountered:

ThomasWaldmann · 2022-11-22T10:42:47Z

Well, your OS is telling that the directory is not empty. Maybe OS or fs are not running reliably.

LM2001 · 2022-12-08T02:21:49Z

I get the same exact error running Proxmox 7.3-3, which is Debian 11 Bullseye, except Borgbackup fully completes and so does prune. All files I selected backup and the prune function completes, but shows this error. The lock.exclusive directory remains and is empty. The backups are valid, as I can restore and run them.

This did not happen for many months while running an earlier version of Proxmox on Debian 11 Bullseye. I'm attributing this to some weird OS interaction that may or may not resolve itself on the next Proxmox or Debian update.

ThomasWaldmann · 2022-12-08T12:33:50Z

@LM2001 Usually Debian/Proxmox is rather well-behaved and stable overall, what filesystem do you use for the repository (assuming the lock issue is in the repository)?

LM2001 · 2022-12-08T16:19:12Z

An NFS mount on my UnRaid server.

The error is not always triggered . In the past 7 days I had 4 errors and 3 completions without errors.

ThomasWaldmann · 2023-01-16T19:53:48Z

Note: The borg version is missing in the top post.

mbaker3 · 2023-03-03T15:36:20Z

Chiming in with the same issue and setup as the other commenters. Here's some more info as well as what I've tried so far. I've also included logs from my desktop client (Vorta) which show the error's that borg is emitting.

Let me know if there's more info I can provide or something I can try.

When running a prune operation I get the following error message. I've been able to reproduce every time I run prune today.

OSError: [Errno 39] Directory not empty: '{repo-path}/lock.exclusive'

Note: In all logs and messages I've replaced personal info with {user}, {host}, {repo-path}

Looking at the repo directory I can see that there are two lock files present

lock.exclusive/
lock.roster

lock.exclusive/ does not have any files in it (hidden or otherwise).
I was able to delete these directories/files myself without issue.

I tried all of the following and re-running prune

Deleting the lock files/directories in the repository's directory on the server.
- lock.exclusive/
- lock.roster
Restarted server
Restarted desktop

Client OS: MacOS 13.2.1
Client Borg Version: 1.2.3

Server OS: Debian 10.13 running in a container on Proxmox 6.4-15
Server Borg Version: 1.1.9
Server Python: 3.7.3
Server Repo Location: An NFS mount on a NAS server

Mounted with {NAS Host}:{NFS Share Path} {local mount point} nfs rw,bg 0 2
Server is connected to NAS with NFS version 4.2

Logs

These are from Vorta but the errors are coming from the borg binary.

2023-03-03 09:32:41,187 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg prune --list --info --log-json --keep-hourly 2 --keep-daily 7 --keep-weekly 4 --keep-monthly 6 --keep-yearly 2 -a sh:Mikes-MacBook-Pro.local-* --keep-within 10H {user}@{host}:{repo-path}
2023-03-03 09:32:42,414 - vorta.borg.borg_job - WARNING - Remote: Removed stale shared roster lock for host {host}@169379503131883 pid 374 thread 0.
2023-03-03 09:32:42,415 - vorta.borg.borg_job - WARNING - Remote: Removed stale shared roster lock for host {host}@169379503131883 pid 374 thread 0.
2023-03-03 09:32:42,801 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 1
2023-03-03 09:32:42,801 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 1
2023-03-03 09:32:42,802 - vorta.scheduler - INFO - Setting timer for profile 1
2023-03-03 09:32:42,803 - vorta.scheduler - DEBUG - Scheduling next run for 2023-03-04 03:42:00
2023-03-03 09:32:42,965 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-03-03 09:32:42,966 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-03-03 09:32:42,966 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-03-03 09:32:42,971 - vorta.keyring.darwin - DEBUG - Retrieved password for repo {user}@{host}:{repo-path}
2023-03-03 09:32:42,975 - vorta.borg.jobs_manager - DEBUG - Add job for site 1
2023-03-03 09:32:42,976 - vorta.borg.jobs_manager - DEBUG - Start job on site: 1
2023-03-03 09:32:42,978 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg list --info --log-json --json {user}@{host}:{repo-path}
2023-03-03 09:32:44,005 - vorta.borg.borg_job - ERROR - Traceback (most recent call last):

  File "/usr/lib/python3/dist-packages/borg/remote.py", line 248, in serve
    res = f(**args)

  File "/usr/lib/python3/dist-packages/borg/remote.py", line 376, in open
    self.repository.__enter__()  # clean exit handled by serve() method

  File "/usr/lib/python3/dist-packages/borg/repository.py", line 189, in __enter__
    self.open(self.path, bool(self.exclusive), lock_wait=self.lock_wait, lock=self.do_lock)

  File "/usr/lib/python3/dist-packages/borg/repository.py", line 392, in open
    self.lock = Lock(os.path.join(path, 'lock'), exclusive, timeout=lock_wait, kill_stale_locks=hostname_is_unique()).acquire()

  File "/usr/lib/python3/dist-packages/borg/locking.py", line 356, in acquire
    self._roster.modify(SHARED, ADD)

  File "/usr/lib/python3/dist-packages/borg/locking.py", line 117, in __exit__
    self.release()

  File "/usr/lib/python3/dist-packages/borg/locking.py", line 150, in release
    os.rmdir(self.path)

OSError: [Errno 39] Directory not empty: '{repo-path}/lock.exclusive'

2023-03-03 09:32:44,007 - vorta.borg.borg_job - ERROR - Borg server: Platform: Linux borg 5.4.203-1-pve #1 SMP PVE 5.4.203-1 (Fri, 26 Aug 2022 14:43:35 +0200) x86_64
Borg server: Linux: debian 10.13 
Borg server: Borg: 1.1.9  Python: CPython 3.7.3
Borg server: PID: 398  CWD: /root
Borg server: sys.argv: ['/usr/bin/borg', 'serve', '--info']
Borg server: SSH_ORIGINAL_COMMAND: None
Platform: Darwin Mikes-MacBook-Pro.local 22.3.0 Darwin Kernel Version 22.3.0: Mon Jan 30 20:38:37 PST 2023; root:xnu-8792.81.3~2/RELEASE_ARM64_T6000 arm64
Borg: 1.2.3  Python: CPython 3.11.2 msgpack: 1.0.4 fuse: None [pyfuse3,llfuse]
PID: 1589  CWD: /
sys.argv: ['/opt/homebrew/bin/borg', 'list', '--info', '--log-json', '--json', '{user}@{host}:{repo-path}']
SSH_ORIGINAL_COMMAND: None

2023-03-03 09:32:44,141 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 1
2023-03-03 09:32:44,142 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 1
2023-03-03 09:32:44,143 - vorta.scheduler - INFO - Setting timer for profile 1
2023-03-03 09:32:44,144 - vorta.scheduler - DEBUG - Scheduling next run for 2023-03-04 03:42:00

ThomasWaldmann · 2023-03-03T17:37:45Z

@mbaker3 that's a rather old borg on the server, could you try to reproduce with something more recent?

Like something from buster-backports or bullseye-backports? Or just use the binary from github releases page?

mbaker3 · 2023-03-05T22:49:55Z

Good point. I've been leaning too heavy on automatic updates with this instance.

I upgraded to Debian 11 which delivers borg 1.1.16.
Same issue, slightly different line numbers on the stack.

2023-03-05 09:26:57,417 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg list --info --log-json --json {user}@{host}:{repo-path}
2023-03-05 09:27:23,389 - vorta.borg.borg_job - ERROR - Traceback (most recent call last):

  File "/usr/lib/python3/dist-packages/borg/remote.py", line 247, in serve
    res = f(**args)

  File "/usr/lib/python3/dist-packages/borg/remote.py", line 375, in open
    self.repository.__enter__()  # clean exit handled by serve() method

  File "/usr/lib/python3/dist-packages/borg/repository.py", line 190, in __enter__
    self.open(self.path, bool(self.exclusive), lock_wait=self.lock_wait, lock=self.do_lock)

  File "/usr/lib/python3/dist-packages/borg/repository.py", line 421, in open
    self.lock = Lock(os.path.join(path, 'lock'), exclusive, timeout=lock_wait, kill_stale_locks=hostname_is_unique()).acquire()

  File "/usr/lib/python3/dist-packages/borg/locking.py", line 356, in acquire
    self._roster.modify(SHARED, ADD)

  File "/usr/lib/python3/dist-packages/borg/locking.py", line 117, in __exit__
    self.release()

  File "/usr/lib/python3/dist-packages/borg/locking.py", line 150, in release
    os.rmdir(self.path)

OSError: [Errno 39] Directory not empty: '{repo-path}/lock.exclusive'

2023-03-05 09:27:23,392 - vorta.borg.borg_job - ERROR - Borg server: Platform: Linux borg 5.4.203-1-pve #1 SMP PVE 5.4.203-1 (Fri, 26 Aug 2022 14:43:35 +0200) x86_64
Borg server: Linux: Unknown Linux  
Borg server: Borg: 1.1.16  Python: CPython 3.9.2 msgpack: 0.5.6.+borg1
Borg server: PID: 420  CWD: /root
Borg server: sys.argv: ['/usr/bin/borg', 'serve', '--info']
Borg server: SSH_ORIGINAL_COMMAND: None
Platform: Darwin Mikes-MacBook-Pro.local 22.3.0 Darwin Kernel Version 22.3.0: Mon Jan 30 20:38:37 PST 2023; root:xnu-8792.81.3~2/RELEASE_ARM64_T6000 arm64
Borg: 1.2.3  Python: CPython 3.11.2 msgpack: 1.0.4 fuse: None [pyfuse3,llfuse]
PID: 41892  CWD: /
sys.argv: ['/opt/homebrew/bin/borg', 'list', '--info', '--log-json', '--json', '{user}@{host}:{repo-path}']
SSH_ORIGINAL_COMMAND: None

I also tried upgrading to 1.2.3 using bullseye-backports and that seemed to do the trick. I was able to run a prune successfully. The newer server version was even able to detect an remove the stale lock.roster.

So I suppose there's an incompatibility between a 1.2.x client and a 1.1.x server?

ThomasWaldmann · 2023-03-06T00:00:12Z

I would rather assume that there was a bug fix in the locking code after 1.1.16 (#5828 was fixed in 1.1.17).

There were bigger locking changes in borg 1.2:
dfc5e91

ThomasWaldmann · 2023-04-06T23:35:20Z

Related: #6736.

ThomasWaldmann changed the title ~~OSError: [Errno 39] Directory not empty: '/mnt/mysql01-prod-cis/lock.exclusive'~~ OSError: [Errno 39] Directory not empty: '/.../lock.exclusive' (borg 1.1.x) Apr 6, 2023

ThomasWaldmann mentioned this issue Nov 16, 2023

Non fatal bug in removing lock after archive creation #7937

Closed

ThomasWaldmann mentioned this issue Aug 30, 2024

use borgstore and other big changes #8332

Merged

ThomasWaldmann closed this as completed in #8332 Sep 8, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

OSError: [Errno 39] Directory not empty: '/.../lock.exclusive' (borg 1.1.x) #7154

OSError: [Errno 39] Directory not empty: '/.../lock.exclusive' (borg 1.1.x) #7154

isshwar commented Nov 22, 2022 •

edited by ThomasWaldmann

Loading

ThomasWaldmann commented Nov 22, 2022

LM2001 commented Dec 8, 2022

ThomasWaldmann commented Dec 8, 2022 •

edited

Loading

LM2001 commented Dec 8, 2022

ThomasWaldmann commented Jan 16, 2023

mbaker3 commented Mar 3, 2023

ThomasWaldmann commented Mar 3, 2023

mbaker3 commented Mar 5, 2023

ThomasWaldmann commented Mar 6, 2023 •

edited

Loading

ThomasWaldmann commented Apr 6, 2023

OSError: [Errno 39] Directory not empty: '/.../lock.exclusive' (borg 1.1.x) #7154

OSError: [Errno 39] Directory not empty: '/.../lock.exclusive' (borg 1.1.x) #7154

Comments

isshwar commented Nov 22, 2022 • edited by ThomasWaldmann Loading

ThomasWaldmann commented Nov 22, 2022

LM2001 commented Dec 8, 2022

ThomasWaldmann commented Dec 8, 2022 • edited Loading

LM2001 commented Dec 8, 2022

ThomasWaldmann commented Jan 16, 2023

mbaker3 commented Mar 3, 2023

Logs

ThomasWaldmann commented Mar 3, 2023

mbaker3 commented Mar 5, 2023

ThomasWaldmann commented Mar 6, 2023 • edited Loading

ThomasWaldmann commented Apr 6, 2023

isshwar commented Nov 22, 2022 •

edited by ThomasWaldmann

Loading

ThomasWaldmann commented Dec 8, 2022 •

edited

Loading

ThomasWaldmann commented Mar 6, 2023 •

edited

Loading