Borg check breaks cifs mount in 1.2.0

svvac commented 2 years ago

I've been doing backups on a cifs mount for a while without any issues (borg@1.1.15, cifs-utils@2:6.14-1, linux@5.15.0, 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/HOSTNAME@91766653968.8956-0
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.

ThomasWaldmann commented 2 years ago

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 .

ThomasWaldmann commented 2 years ago

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.

svvac commented 2 years ago

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.

ThomasWaldmann commented 2 years ago

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...

ThomasWaldmann commented 2 years ago

notable fs-related change between 1.1.17 and 1.2.0 i found:

repository code:

borg check writes to repo config (to support borg 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 just os.unlink.)

locking code:

uses tempfile.mkdtemp + os.rename now (fixes some race conditions the 1.1 code had)
always kills stale locks

ThomasWaldmann commented 2 years ago

Maybe producing a log with strace could give some additional insights about where the problems begin and what was done immediately before that.

ThomasWaldmann commented 2 years ago

@svvac Do you have any new information about this?

shad-lp commented 2 years ago

I got the same error here. Nothing changed ever side and it was working some months ago.

ThomasWaldmann commented 2 years 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.

ThomasWaldmann commented 2 years ago

1.2.2 is available from the borgbackup ppa and also from the github releases page here.

ThomasWaldmann commented 2 years ago

I edited the title slightly to reflect that we currently only have evidence about this happening with borg 1.2.0 (and cifs).

shad-lp commented 2 years ago

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.

borgbackup / borg