borgbackup
Borg check breaks cifs mount after 1.2.0
I've been doing backups on a cifs mount for a while without any issues ([email protected], cifs-utils@2:6.14-1, [email protected], Ubuntu if that matters).
However, when trying out 1.2.0, I encounter a rather strange behaviour. When attempting a borg check, the program crashes while trying to create the lock on the repo. The filesystem returns a permission denied error, not because of filesystem permissions, but because the mountpoint gets borked. After the crash, I cannot list any file under the share, and I am forced to unmount/remount the folder in order to repair it.
I think the underlying issue is probably with cifs rather than borg, but I'm filing this here since it works before 1.2.
Test scenario
# denotes root command ; $ denotes user:group command.
Using the following mount:
# mount -t cifs //server/path/to/folder ./test -o noexec,nosuid,uid=$(id -u),gid=$(id -g),dir_mode=0770,file_mode=0660
$ ls -al ./test
drwxrwx--- 2 user group 0 Jun 2 09:42 .
drwxrwxr-x 3 user group 4096 Jun 2 10:37 ..
drwxrwx--- 2 user group 0 Jun 2 10:52 test
borg 1.2.0
Binary downloaded from the releases page
$ ./borg-1.2.0 list ./test/test
test Thu, 2022-06-02 09:43:31 [42bbcef5abf68709bfdc68c8cb30c01226bfb621ead5d48703a07300448bd6ea]
$ ./borg-1.2.0 info ./test/test
Repository ID: 7db0ea832a0571419619fb61eb404af116b7540f3031a0daf40977e810eb465f
Location: /home/user/tmp/test/test
Encrypted: No
Cache: /home/user/.cache/borg/7db0ea832a0571419619fb61eb404af116b7540f3031a0daf40977e810eb465f
Security dir: /home/user/.config/borg/security/7db0ea832a0571419619fb61eb404af116b7540f3031a0daf40977e810eb465f
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
All archives: 5.23 GB 2.67 GB 2.40 GB
Unique chunks Total chunks
Chunk index: 110911 134546
$ ./borg-1.2.0 info ./test/test::test
Archive name: test
Archive fingerprint: 42bbcef5abf68709bfdc68c8cb30c01226bfb621ead5d48703a07300448bd6ea
Comment:
Hostname: HOSTNAME
Username: user
Time (start): Thu, 2022-06-02 09:43:31
Time (end): Thu, 2022-06-02 09:47:36
Duration: 4 minutes 4.90 seconds
Number of files: 151006
Command line: /usr/bin/borg create ./test/test::test /usr
Utilization of maximum supported archive size: 0%
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
This archive: 5.23 GB 2.67 GB 2.40 GB
All archives: 5.23 GB 2.67 GB 2.40 GB
Unique chunks Total chunks
Chunk index: 110911 134546
$ ./borg-1.2.0 list ./test/test::test | wc -l
207004
$ ./borg-1.2.0 check --debug ./test/test::test
using builtin fallback logging configuration
38 self tests completed in 0.20 seconds
Starting repository check
Verified integrity of /home/user/tmp/test/test/index.21
Read committed index of transaction 21
Segment transaction is 21
Determined transaction is 21
Found 22 segments
Exception ignored in: <function Repository.__del__ at 0x7f2a810e5790>
Traceback (most recent call last):
File "borg/repository.py", line 189, in __del__
File "borg/repository.py", line 470, in close
File "borg/locking.py", line 417, in release
File "borg/locking.py", line 308, in modify
File "borg/locking.py", line 267, in load
PermissionError: [Errno 13] Permission denied: '/home/user/tmp/test/test/lock.roster'
Local Exception
Traceback (most recent call last):
File "borg/archiver.py", line 183, in wrapper
File "borg/archiver.py", line 342, in do_check
File "borg/repository.py", line 1017, in check
File "borg/repository.py", line 1305, in segment_iterator
PermissionError: [Errno 13] Permission denied: '/home/user/tmp/test/test/data'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "borg/archiver.py", line 5089, in main
File "borg/archiver.py", line 5020, in run
File "borg/archiver.py", line 183, in wrapper
File "borg/repository.py", line 214, in __exit__
File "borg/repository.py", line 470, in close
File "borg/locking.py", line 417, in release
File "borg/locking.py", line 308, in modify
File "borg/locking.py", line 267, in load
PermissionError: [Errno 13] Permission denied: '/home/user/tmp/test/test/lock.roster'
Platform: Linux HOSTNAME 5.15.0-33-generic #34-Ubuntu SMP Wed May 18 13:34:26 UTC 2022 x86_64
Linux: Unknown Linux
Borg: 1.2.0 Python: CPython 3.9.10 msgpack: 1.0.3 fuse: llfuse 1.4.1 [pyfuse3,llfuse]
PID: 8511 CWD: /home/user/tmp
sys.argv: ['./borg-1.2.0', 'check', './test/test::test']
SSH_ORIGINAL_COMMAND: None
$ ls -al ./test
ls: reading directory './test': Permission denied
total 0
# ls -al ./test
ls: reading directory './test': Permission denied
total 0
The kernel and system logs don't report anything at all. After unmounting + remounting (mount -o remount doesn't work), the lockfile has been created and we need to break the lock. Acquiring the lock from CLI and reading the repo doesn't trigger the bug.
$ ls -al ./test/test
total 10251
drwxrwx--- 2 user group 4096 Jun 2 11:00 .
drwxrwx--- 2 user group 0 Jun 2 09:42 ..
-rw-rw---- 1 user group 73 Jun 2 09:43 README
-rw-rw---- 1 user group 209 Jun 2 11:00 config
drwxrwx--- 2 user group 0 Jun 2 09:42 data
-rw-rw---- 1 user group 108 Jun 2 09:47 hints.9
-rw-rw---- 1 user group 10485898 Jun 2 09:47 index.9
-rw-rw---- 1 user group 190 Jun 2 09:47 integrity.9
drwxrwx--- 2 user group 0 Jun 2 11:00 lock.exclusive
-rw-rw---- 1 user group 54 Jun 2 11:00 lock.roster
$ ./borg-1.2.0 break-lock ./test/test
$ ./borg-1.2.0 with-lock ./test/test find test/test -type f -exec sha256sum {} \;
7ccf3f2f9085697fe82b90b0b3035d136f84ed85cbcf85ae4f6905160eab4a8b test/test/config
2f03e14bfbae316df44f182ded556e8bd197fb670282ffbfa2c13e7f7900ef66 test/test/data/0/0
0a2e55f51c5d5125dfd8d4677af5c80d5d366b65ff70838d7ced6ef3bc152361 test/test/data/0/1
82d4b05dabb69be69c8138a52925fd88bd6f81f554e4ced92289feca5ac4fe05 test/test/data/0/10
747a22e30a19b1900d49b557187487d23eac8f1eeb2342da6b0c82293635ca62 test/test/data/0/11
0a2e55f51c5d5125dfd8d4677af5c80d5d366b65ff70838d7ced6ef3bc152361 test/test/data/0/12
82d4b05dabb69be69c8138a52925fd88bd6f81f554e4ced92289feca5ac4fe05 test/test/data/0/13
747a22e30a19b1900d49b557187487d23eac8f1eeb2342da6b0c82293635ca62 test/test/data/0/14
0a2e55f51c5d5125dfd8d4677af5c80d5d366b65ff70838d7ced6ef3bc152361 test/test/data/0/15
82d4b05dabb69be69c8138a52925fd88bd6f81f554e4ced92289feca5ac4fe05 test/test/data/0/16
747a22e30a19b1900d49b557187487d23eac8f1eeb2342da6b0c82293635ca62 test/test/data/0/17
0a2e55f51c5d5125dfd8d4677af5c80d5d366b65ff70838d7ced6ef3bc152361 test/test/data/0/18
82d4b05dabb69be69c8138a52925fd88bd6f81f554e4ced92289feca5ac4fe05 test/test/data/0/19
77961b3e12c10de63561acae4a8d548b70b29a869669ebcf8492b64afc5e7617 test/test/data/0/2
747a22e30a19b1900d49b557187487d23eac8f1eeb2342da6b0c82293635ca62 test/test/data/0/20
1d7e75fe147e0203b2b8de276b223194f660303d06f67846a91ee66926842dca test/test/data/0/3
ba4bcba643965b6373351d4d1472cea3bfef34824642d8878f962f5c25926b68 test/test/data/0/4
55d3ba4182187d534956297c8db25aad47190525a1578122591e60c83775b3b4 test/test/data/0/5
4cc4b02bb1f79cd3b48f1549a7c61ee6f7d7e9a8bd7f5033999f91986ee8c343 test/test/data/0/6
82d4b05dabb69be69c8138a52925fd88bd6f81f554e4ced92289feca5ac4fe05 test/test/data/0/7
747a22e30a19b1900d49b557187487d23eac8f1eeb2342da6b0c82293635ca62 test/test/data/0/8
0a2e55f51c5d5125dfd8d4677af5c80d5d366b65ff70838d7ced6ef3bc152361 test/test/data/0/9
c5a491e623e8911e9be1710289c9f299278068d7009b82c19414192c5c06ff30 test/test/hints.18
60a474e4a830d42fb0045357ad1e2cf366e0527c2bbf8a6e9a57bf28b7d01161 test/test/index.18
70cc5373aedcd5e0ff849ce4556694fa6e47f10690b760f665779846856fa14a test/test/integrity.18
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 test/test/lock.exclusive/[email protected]
5a1ced5e030d4fb6298936ecac06c52ba13acf7ebabbbe6aa632ce28f4b827db test/test/lock.roster
2032b905ae9c36a17a955533d48c512a0c5759ef9c7d70e0c931a3026a3278fe test/test/README
borg 1.1.17
Binary downloaded from the release page
$ ./borg-1.1.17 list ./test/test
test Thu, 2022-06-02 09:43:31 [42bbcef5abf68709bfdc68c8cb30c01226bfb621ead5d48703a07300448bd6ea]
$ ./borg-1.1.17 info ./test/test
Repository ID: 7db0ea832a0571419619fb61eb404af116b7540f3031a0daf40977e810eb465f
Location: /home/user/tmp/test/test
Encrypted: No
Cache: /home/user/.cache/borg/7db0ea832a0571419619fb61eb404af116b7540f3031a0daf40977e810eb465f
Security dir: /home/user/.config/borg/security/7db0ea832a0571419619fb61eb404af116b7540f3031a0daf40977e810eb465f
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
All archives: 5.24 GB 2.67 GB 2.40 GB
Unique chunks Total chunks
Chunk index: 110911 134546
$ ./borg-1.1.17 info ./test/test::test
Archive name: test
Archive fingerprint: 42bbcef5abf68709bfdc68c8cb30c01226bfb621ead5d48703a07300448bd6ea
Comment:
Hostname: HOSTNAME
Username: user
Time (start): Thu, 2022-06-02 09:43:31
Time (end): Thu, 2022-06-02 09:47:36
Duration: 4 minutes 4.90 seconds
Number of files: 151006
Command line: /usr/bin/borg create ./test/test::test /usr
Utilization of maximum supported archive size: 0%
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
This archive: 5.20 GB 2.66 GB 2.40 GB
All archives: 5.24 GB 2.67 GB 2.40 GB
Unique chunks Total chunks
Chunk index: 110911 134546
$ ./borg-1.1.17 list ./test/test::test | wc -l
207004
$ ./borg-1.1.17 check ./test/test::test
using builtin fallback logging configuration
35 self tests completed in 0.21 seconds
Starting repository check
Verified integrity of /home/user/tmp/test/test/index.21
Read committed index of transaction 21
Segment transaction is 21
Determined transaction is 21
Found 22 segments
checking segment file /home/user/tmp/test/test/data/0/0...
checking segment file /home/user/tmp/test/test/data/0/1...
checking segment file /home/user/tmp/test/test/data/0/2...
checking segment file /home/user/tmp/test/test/data/0/3...
checking segment file /home/user/tmp/test/test/data/0/4...
checking segment file /home/user/tmp/test/test/data/0/5...
checking segment file /home/user/tmp/test/test/data/0/6...
checking segment file /home/user/tmp/test/test/data/0/7...
checking segment file /home/user/tmp/test/test/data/0/8...
checking segment file /home/user/tmp/test/test/data/0/9...
checking segment file /home/user/tmp/test/test/data/0/10...
checking segment file /home/user/tmp/test/test/data/0/11...
checking segment file /home/user/tmp/test/test/data/0/12...
checking segment file /home/user/tmp/test/test/data/0/13...
checking segment file /home/user/tmp/test/test/data/0/14...
checking segment file /home/user/tmp/test/test/data/0/15...
checking segment file /home/user/tmp/test/test/data/0/16...
checking segment file /home/user/tmp/test/test/data/0/17...
checking segment file /home/user/tmp/test/test/data/0/18...
checking segment file /home/user/tmp/test/test/data/0/19...
checking segment file /home/user/tmp/test/test/data/0/20...
checking segment file /home/user/tmp/test/test/data/0/21...
Starting repository index check
Index object count match.
Completed repository check, no problems found.
Starting archive consistency check...
Verified integrity of /home/user/tmp/test/test/index.21
TAM-verified manifest
Analyzing archive test (1/1)
Orphaned objects check skipped (needs all archives checked).
Archive consistency check complete, no problems found.
Strange error, but I'ld say file a bug against the cifs filesystem, borg only does normal filesystem operations and they should work without the filesystem going nuts.
Specifically:
- File "borg/locking.py", line 267, in load - this is a normal open() call, nothing special at all.
- File "borg/repository.py", line 1305, in segment_iterator - this is a normal os.listdir() call, nothing special at all.
You could also try to reproduce with the 1.2.0 package from https://launchpad.net/~costamagnagianfranco/+archive/ubuntu/borgbackup .
What you could also try is using that cifs mount manually, just use some file manager and copy a bigger amount of files into it, do some renames, deletes, copies in there.
Strange error, but I'ld say file a bug against the cifs filesystem, borg only does normal filesystem operations and they should work without the filesystem going nuts.
I completely agree, the blame almost certainly lies with cifs. But something must be different between the two versions to trigger the bug. I consistently have the issue with 1.2, and never with 1.1.
You could also try to reproduce with the 1.2.0 package from https://launchpad.net/~costamagnagianfranco/+archive/ubuntu/borgbackup .
I didn't try this one, but the system version from ubuntu exhibits the same behaviour.
What you could also try is using that cifs mount manually, just use some file manager and copy a bigger amount of files into it, do some renames, deletes, copies in there.
I'll try a few things and report back here if I find something interesting.
Fine, the jammy 1.2.0 version is from same maintainer. I just wanted to exclude any strange effects potentially coming from the pyinstaller-made fat binary (it bundles python and misc libs into the binary, but also uses kernel/glibc/related libs from the system).
I'll review locking and repository fs-related changes between 1.1.17 and 1.2.0, let's see if there is anything interesting...
notable fs-related change between 1.1.17 and 1.2.0 i found:
repository code:
borg checkwrites to repo config (to supportborg check --partial --max-duration)os.statvfs(repo_path)-->shutil.disk_usage(repo_path)(this is to check free disk space before committing)truncate_and_unlink(file)-->safe_unlink(file)(this was changed to avoid collateral damage to hardlinked copies of repos. under normal conditions (== space is available on the fs), safe_unlink is justos.unlink.)
locking code:
- uses
tempfile.mkdtemp+os.renamenow (fixes some race conditions the 1.1 code had) - always kills stale locks
Maybe producing a log with strace could give some additional insights about where the problems begin and what was done immediately before that.
I got the same error here. Nothing changed ever side and it was working some months ago.
some ideas from today's perspective:
- the above bug (this issue here, #6740) is still not clear - if you can reproduce it with borg 1.2.2, please post a new traceback here and how to reproduce.
- there was another issue in the locking code (caused by a fix to yet another issue). this was due to chmod not being supported by some filesystems. the bug was in borg 1.2.1 and was fixed in 1.2.2.
- we also have seen some strange issues that might have their root cause in
cifs(not in borg), maybe including this issue here.
1.2.2 is available from the borgbackup ppa and also from the github releases page here.
I edited the title slightly to reflect that we currently only have evidence about this happening with borg 1.2.0 (and cifs).
Seems like I'm still on 1.1.16, so my comment is not relevant. I'll try to upgrade and see if I still stumble upon this problem.