Operation not permitted (EPERM) on some files

[sbond75]

For some .DS_Store files and a zip file on an HFS+ drive I've been copying from, the read syscall fails with EPERM:

]$ sudo strace xxd /mnt/SeagateFireCuda/Downloads/.DS_Store
execve("/run/current-system/sw/bin/xxd", ["xxd", "/mnt/SeagateFireCuda/Downloads/."...], 0x7ffcea971df8 /* 27 vars */) = 0
brk(NULL)                               = 0x1f39000
access("/etc/ld-nix.so.preload", R_OK)  = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/glibc-hwcaps/x86-64-v3/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/glibc-hwcaps/x86-64-v3", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/glibc-hwcaps/x86-64-v2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/glibc-hwcaps/x86-64-v2", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/x86_64/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/x86_64/x86_64", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/x86_64", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/x86_64", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/tls", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/x86_64/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/x86_64/x86_64", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/x86_64", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/x86_64", 0x7fffc18d8570, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/65hafbsx91127farbmyyv4r5ifgjdg43-glibc-2.33-117/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320x\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\200\0\300\4\0\0\0\1\0\0\0\0\0\0\0", 32, 848) = 32
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\232\17\220\304\277(;P\314\302\373R\250lL\236"..., 68, 880) = 68
newfstatat(3, "", {st_mode=S_IFREG|0555, st_size=2141272, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f293de9a000
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
mmap(NULL, 1917264, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f293dcc5000
mmap(0x7f293dceb000, 1384448, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26000) = 0x7f293dceb000
mmap(0x7f293de3d000, 319488, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x178000) = 0x7f293de3d000
mmap(0x7f293de8b000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c5000) = 0x7f293de8b000
mmap(0x7f293de91000, 33104, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f293de91000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f293dcc3000
arch_prctl(ARCH_SET_FS, 0x7f293de9b5c0) = 0
mprotect(0x7f293de8b000, 12288, PROT_READ) = 0
mprotect(0x404000, 4096, PROT_READ)     = 0
mprotect(0x7f293decb000, 8192, PROT_READ) = 0
brk(NULL)                               = 0x1f39000
brk(0x1f5a000)                          = 0x1f5a000
openat(AT_FDCWD, "/mnt/SeagateFireCuda/Downloads/.DS_Store", O_RDONLY) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=8196, ...}, AT_EMPTY_PATH) = 0
read(3, 0x1f39480, 4096)                = -1 EPERM (Operation not permitted)
write(2, "xxd: ", 5xxd: )                    = 5
write(2, "Operation not permitted\n", 24Operation not permitted
) = 24
exit_group(2)                           = ?
+++ exited with 2 +++

This file is readable when using the hfsplus driver on Linux and has some binary content, so it seems to be an hfsfuse issue. Upon checking with hfsdump with sudo ./hfsdump /dev/sdf2 read /Downloads/.DS_Store, it returns exit code 255. I used gdb on it and found that hfslib_get_file_extents was returning 0, meaning there are no extents for the file but there should probably be extents?

How can this be debugged further?

[0x09]

@sbond75 can you post the output of these:

hfsfuse -v
sudo ./hfsdump /dev/sdf2 xattr /Downloads/.DS_Store
sudo ./hfsdump /dev/sdf2 stat /Downloads/.DS_Store

I'm mostly looking to see if the second command lists an com.apple.decmpfs attribute and whether zlib or lzfse appear in the first. Files that use HFS+'s compression mechanism have no extents, but if hfsfuse can't decompress those the size ought to be 0 and it looks like from your trace that it's 8196, so I'm wondering if it's a bug with decmpfs handling.

[sbond75]

Here is is:

$ ./hfsfuse -v
hfsfuse version 0.214-529cb8b
Built with:
    FUSE API v2.9
    libhfs RCSID $NetBSD: libhfs.c,v 1.19 2023/08/11 05:51:34 mrg Exp $
    ublio v0.1
    utf8proc v2.9.0
    zlib v1.3.1
    lzfse

$ sudo ./hfsdump /dev/sdf2 xattr /Downloads/.DS_Store

$ echo $?
0

$ sudo ./hfsdump /dev/sdf2 stat /Downloads/.DS_Store
path: /Downloads/.DS_Store
type: file
flags: 130
cnid: 397670
date_created: Sat May 22 15:40:20 2021
date_content_mod: Wed Apr 17 14:17:35 2024
date_attrib_mod: Wed Apr 17 14:17:35 2024
date_accessed: Wed Apr 17 16:12:40 2024
date_backedup: Wed Dec 31 19:00:00 1969
encoding: 0
permissions.owner_id: 501
permissions.group_id: 20
permissions.admin_flags: 0
permissions.owner_flags: 0
permissions.file_mode: 100644
permissions.special: 1
user_info.file_type:
user_info.file_creator:
user_info.finder_flags: 16400
user_info.location:  0, 0
finder_info.extended_finder_flags: 0
finder_info.put_away_folder_cnid: 217
data_fork.logical_size: 34820
rsrc_fork.logical_size: 0

[0x09]

Thanks, that rules out compression. Nothing looks unusual about the record info from hfsdump stat either.

If there weren't any messages like "read of x bytes at offset y failed (block size z)" or any other errors when you ran hfsdump read, then I think that narrows it down to a problem locating the extent records themselves in hfslib_get_file_extents. This will be a bit tricky to debug, but if it'd be possible to set a breakpoint there and step until this jumps to the error label, that would tell us where exactly this is failing. What this function is trying to do is locate and read the list of byte offsets (extents) that tell it where to read the actual file data off the filesystem.

Just to be sure, it might be worth first rebuilding with make WITH_UBLIO=none and re-running the hfsdump read command. This won't resolve it if the issue is with the extents but it should rule out any issues at the read layer.

[0x09]

I was able to reproduce this. It's a bug during the extents lookup mentioned above that's causing the search to be cancelled early with no results when it shouldn't be, specifically at this point

hfsfuse/lib/libhfs/libhfs.c

Lines 653 to 658 in 5a7de8c

	/* ...unless this is a leaf node, which means we've gone from
	* a key which is smaller than the search key, in the previous
	* loop, to a key which is larger, in this loop, and that
	* implies that our search key does not exist on the volume. */
	if (nd.kind == HFS_LEAFNODE)
	result = -1;

The Apple driver also confirms this shouldn't be the case here.

I'll need to debug this a bit more but should be able to sort it out now that I have a repro.

Edit: found the issue, this ought to fix it cc49395

[sbond75]

The fix works, thanks!