test_fuse: weird test failure only on freebsd #6871

ThomasWaldmann · 2022-07-17T12:25:23Z

borg 2.0.0a4, python 3.9.13, vagrant, freebsd13, pytest 7.0.1 and 6.2.5:

with open(in_fn, "rb") as in_f, open(out_fn, "rb") as out_f:
    indata = in_f.read()
    outdata = out_f.read()
    print(repr(indata))  # prints b'XXXX...'
    print(repr(outdata))  # prints b'XXXX...'
    assert type(indata) == bytes
    assert type(outdata) == bytes
>   assert indata == outdata
OSError: [Errno 78] Function not implemented

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

ThomasWaldmann · 2022-07-17T12:32:01Z

Hah. It always happens in the last line of that block, no matter what it is. __exit__ of context manager maybe?

Yup, it is out_f.close() that produces this OSError.

ThomasWaldmann · 2022-07-17T12:43:53Z

I don't think I've seen that for borg 2.0.0a3 recently. So, is something broken in borg, on freebsd, in llfuse?

ThomasWaldmann · 2022-07-17T14:29:04Z

I also tested on 3 different Linux dists, netbsd, openbsd and macOS - that issue did not show up there.

ThomasWaldmann · 2022-08-16T17:10:50Z

still broken for 2.0.0b1 and freebsd 13.1-release-p1.

ThomasWaldmann · 2023-04-02T01:05:59Z

And it's still broken. Any freebsd user out there who could debug / fix this?

ThomasWaldmann · 2023-04-02T01:07:27Z

I added the "bug" label to get this better visibility.

It doesn't look like a bug in borg though, but rather in freebsd's FUSE implementation.

Jamie-Landeg-Jones · 2023-04-07T23:47:25Z

Longtime FreeBSD user here, borg user since January, and little to none python skills!

What can I do to help?

ThomasWaldmann · 2023-04-08T13:25:07Z

@Jamie-Landeg-Jones thanks for helping. The "Function not implemented" is only seen on FreeBSD (not on linux, not on macOS) and even on FreeBSD, this has worked before, so I suspect a bug / regression in FreeBSD's FUSE infrastructure.

Can you maybe check the changes to the fuse stuff done in freebsd, whether something looks suspect?

Jamie-Landeg-Jones · 2023-04-08T15:09:50Z

Hi. What I'd like to do first is replicate the error you posted and trace it from there.
I can download borg from git, and the relevant dependencies, but I'm unclear what I need to run to trigger the error.

Cheers

ThomasWaldmann · 2023-04-08T15:32:26Z

Our docs have instructions for developers, see there for the set up:

https://borgbackup.readthedocs.io/en/1.2.4/development.html (maybe rather check out the 1.2-maint branch than master, the 1.2.x stable releases are made from this branch)

For the fuse issue, you do not need to use fakeroot and you could limit pytest to only run the fuse related tests (which triggers the error):

pip install -r requirements.d/development.txt
python setup.py clean clean2
pip install -e .[llfuse]
pytest -v --show-locals --benchmark-skip -k "not remote and fuse"

Jamie-Landeg-Jones · 2023-04-09T03:42:09Z

Thanks for that. I've replicated the issue in C, and with a sshfs mounted fuse filesystem.

Of course, this isn't a fix, but it will make it easier to track down the problem.

Here's what I've noticed:

As you said, it works fine on FreeBSD 12, just not on 13. I'll narrow down where tomorrow.

The error only occurs under our use case if you read from the file. (if you disable the read-check in your tests, the close works ok) [N.B. I didn't test writing]

To highlight this, I ran your test without the read check, then from the command line, run a bit of c code that simply opens the file... then closes it.... then opens it... reads 100 bytes. then closes it. then opens it then closes it.

I also did similar on a sshfs filesystem, and got the same effect, but with a different error message, leading me to believe that there is some unset / previously initialised variable leaking through.

I tested mounting ro and rw - no difference. I also tried using the "cat" unix command on one test file. The "cat" showed no error message, but again, by virtue of it reading the file, any subsequent fclose test failed.

So, basically, any file that has had some bytes read, produces that error on close, and continues to do so for the duration of the mount.

I now have enough to look at the fusefs source, and if I can't work it out, at least I'll have enough evidence to prod someone with!

bb@catwalk:~/borg % file-close-check /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1
/tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 | open: ok, close: ok | open: ok, read: 100 bytes, close: Function not implemented | open: ok, close: Function not implemented
bb@catwalk:~/borg %
bb@catwalk:~/borg % file-close-check /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1
/tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 | open: ok, close: Function not implemented | open: ok, read: 100 bytes, close: Function not implemented | open: ok, close: Function not implemented
bb@catwalk:~/borg % file-close-check /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1
/tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 | open: ok, close: Function not implemented | open: ok, read: 100 bytes, close: Function not implemented | open: ok, close: Function not implemented
bb@catwalk:~/borg %
bb@catwalk:~/borg %
bb@catwalk:~/borg % sshfs jamie@catflap.org:/tmp b1
bb@catwalk:~/borg %
bb@catwalk:~/borg % file-close-check b1/*
b1/COPYRIGHT                   | open: ok, close: ok | open: ok, read: 100 bytes, close: ok | open: ok, close: ok
b1/file-close-check.c          | open: ok, close: ok | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied
b1/x                           | open: ok, close: ok | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied
bb@catwalk:~/borg %
bb@catwalk:~/borg %
bb@catwalk:~/borg % file-close-check b1/*
b1/COPYRIGHT                   | open: ok, close: ok | open: ok, read: 100 bytes, close: ok | open: ok, close: ok
b1/file-close-check.c          | open: ok, close: Permission denied | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied
b1/x                           | open: ok, close: Permission denied | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied
bb@catwalk:~/borg %
bb@catwalk:~/borg % l b1
total 59
 4 drwxrwxrwt   1 root   wheel  -        256  9 Apr 04:00 ./
 3 drwxr-xr-x  14 bb     bb     uarch     36  9 Apr 03:58 ../
 8 -r--r-----   1 jamie  wheel  -      6,197  9 Apr 04:09 COPYRIGHT
 4 -rw-r-----   1 root   wheel  -      1,554  9 Apr 03:39 file-close-check.c
16 -rwxr-x---   1 root   wheel  -     13,550  9 Apr 03:51 x
bb@catwalk:~/borg %

ThomasWaldmann · 2023-04-09T11:34:05Z

great that you could reproduce it outside of borg! btw, was it freebsd that changed the kernel module name? i remember having to update the Vagrantfile. Am 9. Apr. 2023, 05:42 +0200 schrieb Jamie Landeg Jones ***@***.***>:

…

Thanks for that. I've replicated the issue in C, and with a sshfs mounted fuse filesystem. Of course, this isn't a fix, but it will make it easier to track down the problem. Here's what I've noticed: As you said, it works fine on FreeBSD 12, just not on 13. I'll narrow down where tomorrow. The error only occurs under our use case if you read from the file. (if you disable the read-check in your tests, the close works ok) [N.B. I didn't test writing] To highlight this, I ran your test without the read check, then from the command line, run a bit of c code that simply opens the file... then closes it.... then opens it... reads 100 bytes. then closes it. then opens it then closes it. I also did similar on a sshfs filesystem, and got the same effect, but with a different error message, leading me to believe that there is some unset / previously initialised variable leaking through. I tested mounting ro and rw - no difference. I also tried using the "cat" unix command on one test file. The "cat" showed no error message, but again, by virtue of it reading the file, any subsequent fclose test failed. So, basically, any file that has had some bytes read, produces that error on close, and continues to do so for the duration of the mount. I now have enough to look at the fusefs source, and if I can't work it out, at least I'll have enough evidence to prod someone with! ***@***.***:~/borg % file-close-check /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 | open: ok, close: ok | open: ok, read: 100 bytes, close: Function not implemented | open: ok, close: Function not implemented ***@***.***:~/borg % ***@***.***:~/borg % file-close-check /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 | open: ok, close: Function not implemented | open: ok, read: 100 bytes, close: Function not implemented | open: ok, close: Function not implemented ***@***.***:~/borg % file-close-check /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 /tmp/tmp5bsl1_xh/mountpoint/archive/input/file1 | open: ok, close: Function not implemented | open: ok, read: 100 bytes, close: Function not implemented | open: ok, close: Function not implemented ***@***.***:~/borg % ***@***.***:~/borg % ***@***.***:~/borg % sshfs ***@***.***:/tmp b1 ***@***.***:~/borg % ***@***.***:~/borg % file-close-check b1/* b1/COPYRIGHT | open: ok, close: ok | open: ok, read: 100 bytes, close: ok | open: ok, close: ok b1/file-close-check.c | open: ok, close: ok | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied b1/x | open: ok, close: ok | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied ***@***.***:~/borg % ***@***.***:~/borg % ***@***.***:~/borg % file-close-check b1/* b1/COPYRIGHT | open: ok, close: ok | open: ok, read: 100 bytes, close: ok | open: ok, close: ok b1/file-close-check.c | open: ok, close: Permission denied | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied b1/x | open: ok, close: Permission denied | open: ok, read: 100 bytes, close: Permission denied | open: ok, close: Permission denied ***@***.***:~/borg % ***@***.***:~/borg % l b1 total 59 4 drwxrwxrwt 1 root wheel - 256 9 Apr 04:00 ./ 3 drwxr-xr-x 14 bb bb uarch 36 9 Apr 03:58 ../ 8 -r--r----- 1 jamie wheel - 6,197 9 Apr 04:09 COPYRIGHT 4 -rw-r----- 1 root wheel - 1,554 9 Apr 03:39 file-close-check.c 16 -rwxr-x--- 1 root wheel - 13,550 9 Apr 03:51 x ***@***.***:~/borg % — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you authored the thread.Message ID: ***@***.***>

Jamie-Landeg-Jones · 2023-04-09T23:14:47Z

Been a bit busy today, but will have another look tomorrow.

Yes, Freebsd changed it from fuse.ko to fusefs.ko in 2019, which is roughly FreeBSD 12.1 upwards. As the oldest officially supported version is 12.4, all supported versions now use fusefs.

https://cgit.freebsd.org/src/commit/sys/modules/fusefs?id=123af6ec70016f5556da5972d4d63c7d175c06d3

ThomasWaldmann · 2023-04-10T12:12:51Z

Ah, so this was just a rename! Good.

I had the suspicion that they might have switched to a completely new implementation (including new bugs).

Jamie-Landeg-Jones · 2023-04-11T00:08:28Z

Yeah, just a rename, (I have one box that has the renamed name, but none of the bugs you discovered)

However, a number of changes since then, and other sorts of new bugs!

Anyway, I've tracked down the commit that caused the issue, and have reported it, and also posted a fix (it works, but I don't know enough about the fusefs subsystem to know if the fix is correct)

Basically, it appears to be due to an attempt to update atime on a file with no write-access. The close fails because of this (whilst it checks for write-access before attempting to write data, it doesn't seem to do so for metadata)

If you're interested, I've posted lots more information to the bug report, here: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=270749

And in case there are followups there, here is my email letting people know about the bug:
https://lists.freebsd.org/archives/freebsd-current/2023-April/003435.html

As for borg-tests, even when this issue is fixed, it doesn't help people running FreeBSD 13.0 and 13.1

Can you try changing the test to use '-no-atime" on the fusefs? ("-readonly" makes no difference, but if you can mount with "no-atime" I think it might.)

Of course, that only helps if no-atime is acceptable to you -- I assume it is, as the fuse mounted borgbackup is only ever read-only anyway

I hope this helps!

Cheers, Jamie.

P.s. I've found a couple of potential borg issues recently, but I've not tested them on 2.X yet, and need to narrow them down (and make sure it's not user error!) before posting them.

Cheers, Jamie

Jamie-Landeg-Jones · 2023-05-04T13:11:37Z

No update yet ... :-(

ThomasWaldmann · 2023-08-26T13:20:04Z

Considering that this does not seem to be a borg bug, I'll keep this open as a reminder, but move it to rc1 milestone.

Jamie-Landeg-Jones · 2023-09-21T21:36:31Z

The official fix has now been applied to "MAIN', and will hit all supported stable channels in a week.

This means, the fix should be all release versions AFTER 13.2-RELEASE (I don't know if there is going to be a 13.3-RELEASE, but 14.0-RELEASE is imminent)

Ref: https://cgit.freebsd.org/src/commit/?id=fb619c94c679e939496fe0cf94b8d2cba95e6e63

Cheers! Jamie

ThomasWaldmann · 2023-09-22T09:32:10Z

@Jamie-Landeg-Jones great news, thanks!

So guess it might be in the next release there (which is what I use for borg release testing and pyinstaller borg binary building):

https://app.vagrantup.com/generic/boxes/freebsd13

Jamie-Landeg-Jones · 2023-09-22T13:07:41Z

I'm not familiar with vagrant, but I just had a look at your link, and that version they updated a few days ago is indeed based on FreeBSD-13.2-RELEASE so yes, their next release should have it.

Of course, vagrant cloud may stop at 13.2 seeing that 14.0 will be released soon, I don't know, but if they keep updating their freebsd13 branch, then yes, the next update will presumably be 13.3-release, which will have the fix.

One thing, 13.2 was released on April 11th, so there may be a bit of a lag on vagrant providing the upgrade when/if 13.3 comes out.

Cheers!

ThomasWaldmann · 2023-12-23T18:42:55Z

borg todo: upgrade the freebsd vagrant machine to a more recent freebsd and check if the issue disappears.

update:

did a test on freebsd14 and the error has vanished, all borg tests pass.
running same borg code and tests in my freebsd13 vagrant VM still reproduces the issue.

So I will just upgrade all the vagrant VMs to 14.

@Jamie-Landeg-Jones thanks for helping!

    freebsd64:   py39-fuse2: OK (900.77=setup[109.99]+cmd[790.78] seconds)
    freebsd64:   py310-fuse2: OK (993.96=setup[211.16]+cmd[782.79] seconds)
    freebsd64:   py311-fuse2: OK (987.43=setup[212.72]+cmd[774.71] seconds)
    freebsd64:   py312-fuse2: OK (1046.30=setup[224.04]+cmd[822.25] seconds)
    freebsd64:   congratulations :) (3930.93 seconds)

Jamie-Landeg-Jones · 2023-12-24T03:16:50Z

No problem!

For reference, this fix has entered the FreeBSD 13 tree, but there hasn't been a release yet - 13.2 has been around a while. When 13.3 is out, the fix will be in there.

Still, 13.X is still running for those who have problems upgrading, so if you've got 14.X running, it's best to stick with that!

ThomasWaldmann · 2023-12-25T01:51:06Z

1.4-maint: fixed in #7988

ThomasWaldmann changed the title ~~weird test failure only on freebsd~~ test_fuse: weird test failure only on freebsd Jul 17, 2022

ThomasWaldmann added the help wanted label Jul 17, 2022

ThomasWaldmann added this to the 2.0.0b1 milestone Jul 17, 2022

ThomasWaldmann mentioned this issue Jul 27, 2022

borg2: hints for maintainers #6458

Open

ThomasWaldmann removed this from the 2.0.0b1 milestone Jul 27, 2022

ThomasWaldmann added the os: bsd FreeBSD, NetBSD, OpenBSD, ... label Sep 17, 2022

ThomasWaldmann added the bug label Apr 2, 2023

ThomasWaldmann mentioned this issue Apr 6, 2023

FreeBSD export BORG_PASSPHRASE doesn't seem to work properly #7502

Closed

ThomasWaldmann added this to the 2.0.0b6 milestone Apr 11, 2023

ThomasWaldmann modified the milestones: 2.0.0b6, 2.0.0rc1 May 12, 2023

ThomasWaldmann modified the milestones: 2.0.0rc1, 2.0.0b7 Jun 10, 2023

ThomasWaldmann modified the milestones: 2.0.0b7, 2.0.0rc1 Aug 26, 2023

ThomasWaldmann modified the milestones: 2.0.0rc1, 1.4.0a1 Dec 23, 2023

ThomasWaldmann self-assigned this Dec 24, 2023

ThomasWaldmann added a commit to ThomasWaldmann/borg that referenced this issue Dec 24, 2023

vagrant: use freebsd 14, fixes borgbackup#6871

1081825

ThomasWaldmann modified the milestones: 1.4.0a1, 2.0.0rc1 Dec 25, 2023

ThomasWaldmann removed the help wanted label Jan 3, 2024

ThomasWaldmann closed this as completed in c96fe77 Jan 10, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test_fuse: weird test failure only on freebsd #6871

test_fuse: weird test failure only on freebsd #6871

ThomasWaldmann commented Jul 17, 2022 •

edited

Loading

ThomasWaldmann commented Jul 17, 2022 •

edited

Loading

ThomasWaldmann commented Jul 17, 2022

ThomasWaldmann commented Jul 17, 2022

ThomasWaldmann commented Aug 16, 2022

ThomasWaldmann commented Apr 2, 2023

ThomasWaldmann commented Apr 2, 2023

Jamie-Landeg-Jones commented Apr 7, 2023

ThomasWaldmann commented Apr 8, 2023

Jamie-Landeg-Jones commented Apr 8, 2023

ThomasWaldmann commented Apr 8, 2023 •

edited

Loading

Jamie-Landeg-Jones commented Apr 9, 2023

ThomasWaldmann commented Apr 9, 2023 via email

Jamie-Landeg-Jones commented Apr 9, 2023

ThomasWaldmann commented Apr 10, 2023

Jamie-Landeg-Jones commented Apr 11, 2023

Jamie-Landeg-Jones commented May 4, 2023

ThomasWaldmann commented Aug 26, 2023

Jamie-Landeg-Jones commented Sep 21, 2023

ThomasWaldmann commented Sep 22, 2023 •

edited

Loading

Jamie-Landeg-Jones commented Sep 22, 2023

ThomasWaldmann commented Dec 23, 2023 •

edited

Loading

Jamie-Landeg-Jones commented Dec 24, 2023

ThomasWaldmann commented Dec 25, 2023

test_fuse: weird test failure only on freebsd #6871

test_fuse: weird test failure only on freebsd #6871

Comments

ThomasWaldmann commented Jul 17, 2022 • edited Loading

ThomasWaldmann commented Jul 17, 2022 • edited Loading

ThomasWaldmann commented Jul 17, 2022

ThomasWaldmann commented Jul 17, 2022

ThomasWaldmann commented Aug 16, 2022

ThomasWaldmann commented Apr 2, 2023

ThomasWaldmann commented Apr 2, 2023

Jamie-Landeg-Jones commented Apr 7, 2023

ThomasWaldmann commented Apr 8, 2023

Jamie-Landeg-Jones commented Apr 8, 2023

ThomasWaldmann commented Apr 8, 2023 • edited Loading

Jamie-Landeg-Jones commented Apr 9, 2023

ThomasWaldmann commented Apr 9, 2023 via email

Jamie-Landeg-Jones commented Apr 9, 2023

ThomasWaldmann commented Apr 10, 2023

Jamie-Landeg-Jones commented Apr 11, 2023

Jamie-Landeg-Jones commented May 4, 2023

ThomasWaldmann commented Aug 26, 2023

Jamie-Landeg-Jones commented Sep 21, 2023

ThomasWaldmann commented Sep 22, 2023 • edited Loading

Jamie-Landeg-Jones commented Sep 22, 2023

ThomasWaldmann commented Dec 23, 2023 • edited Loading

Jamie-Landeg-Jones commented Dec 24, 2023

ThomasWaldmann commented Dec 25, 2023

ThomasWaldmann commented Jul 17, 2022 •

edited

Loading

ThomasWaldmann commented Jul 17, 2022 •

edited

Loading

ThomasWaldmann commented Apr 8, 2023 •

edited

Loading

ThomasWaldmann commented Sep 22, 2023 •

edited

Loading

ThomasWaldmann commented Dec 23, 2023 •

edited

Loading