httpdirfs icon indicating copy to clipboard operation
httpdirfs copied to clipboard
verified publisher icon fangfufu

Cache_free: could not destroy w_lock!

Open trixprod opened this issue 1 year ago • 29 comments

Hello,

This error occurs quite randomly, often after a few minutes of use when I open a new file. After that the process just crash and i have to relaunch.

**Fatal:src/cache.c:509:Cache_free: could not destroy w_lock!**

Oops! HTTPDirFS crashed! :(
backtrace() returned the following 11 addresses:
httpdirfs(exit_failure+0x34)[0x558a3e0c6904]
httpdirfs(log_printf+0x19d)[0x558a3e0c6dbd]
httpdirfs(+0x1b24e)[0x558a3e0cf24e]
httpdirfs(+0x1bc05)[0x558a3e0cfc05]
/lib/x86_64-linux-gnu/libfuse.so.2(+0xc902)[0x7fa9966a0902]
/lib/x86_64-linux-gnu/libfuse.so.2(+0xfa2a)[0x7fa9966a3a2a]
/lib/x86_64-linux-gnu/libfuse.so.2(+0x16c2d)[0x7fa9966aac2d]
/lib/x86_64-linux-gnu/libfuse.so.2(+0x17353)[0x7fa9966ab353]
/lib/x86_64-linux-gnu/libfuse.so.2(+0x142e8)[0x7fa9966a82e8]
/lib/x86_64-linux-gnu/libc.so.6(+0x8f6ba)[0x7fa99568f6ba]
/lib/x86_64-linux-gnu/libc.so.6(+0x11e120)[0x7fa99571e120]

trixprod avatar Nov 21 '24 14:11 trixprod

Which distro are you using, and which version of that distro are you using? Could I potentially access the server you are using?

fangfufu avatar Nov 22 '24 00:11 fangfufu

Possibly related to: https://github.com/fangfufu/httpdirfs/issues/91 https://github.com/fangfufu/httpdirfs/issues/126

This is going to a fun one...

fangfufu avatar Nov 22 '24 01:11 fangfufu

Hello,

Unfortunately, the server contains private documents, so I cannot share it. The server is running Ubuntu 23.04, Kernel 6.2.0-39-generic. However, I can test the issue on an Arch or Debian system if needed.

Additionally, I’m open to recompiling the code with debug traces if that would be helpful. For context, the cache is written to an XFS filesystem (though I’m not sure if that detail is relevant).

I’ve reviewed #91 and #126. It’s certainly not fun, but would it be possible to handle these errors as non-fatal for the application? Specifically, I’m wondering if it’s necessary to crash the entire process due to a failure in handling a cache file.

trixprod avatar Nov 22 '24 08:11 trixprod

but would it be possible to handle these errors as non-fatal for the application

I guess you could, but IMHO failing to destroy a lock indicates a serious issue, possibly some form of memory leak. It might be safer to terminate the program. It is better for you to run the program with cache system turned off.

The man page for pthread_mutex_destroy is here: https://linux.die.net/man/3/pthread_mutex_destroy, I simply cannot think of a situation when you want to keep the program running when you can't destroy a lock.

I’m open to recompiling the code with debug traces

What do you mean by "debug traces"?

Please give 3aaf5a294ab2fa954e3969cf545819bce1734a64 a try. I re-order some of the error messages, so it would print an error before calling Cache_free(), and it should print out the reason why it couldn't destroy the lock.

If you want, in your local copy, at this line here https://github.com/fangfufu/httpdirfs/blob/master/src/log.h#L23, please add cache_lock_debug

fangfufu avatar Nov 23 '24 01:11 fangfufu

Hello, i have just tested the last master version with your commits

unique: 614, opcode: READ (15), nodeid: 3, insize: 80, pid: 1184337
read[140658435329408] 131072 bytes from 4571136 flags: 0x8000
   read[140658435329408] 131072 bytes from 4571136
   unique: 614, success, outsize: 131088
unique: 616, opcode: READ (15), nodeid: 3, insize: 80, pid: 1184337
read[140658435329408] 131072 bytes from 4702208 flags: 0x8000
   read[140658435329408] 131072 bytes from 4702208
   unique: 616, success, outsize: 131088
unique: 618, opcode: RELEASE (18), nodeid: 3, insize: 64, pid: 0
release[140658435329408] flags: 0x8000
fs_release: /ISO_2024.iso
   unique: 618, success, outsize: 16
unique: 620, opcode: RELEASE (18), nodeid: 3, insize: 64, pid: 0
release[140658435329408] flags: 0x8000
fs_release: /ISO_2024.iso
**Fatal:../src/cache.c:560:Cache_free: could not destroy w_lock: Success!**

Oops! HTTPDirFS crashed! :(
backtrace() returned the following 11 addresses:
httpdirfs(+0xae10)[0x556a47042e10]
httpdirfs(+0xc392)[0x556a47044392]
httpdirfs(+0x8afb)[0x556a47040afb]
httpdirfs(+0x53b9)[0x556a4703d3b9]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0xbb29)[0x7feda0917b29]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1065a)[0x7feda091c65a]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x11948)[0x7feda091d948]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1e803)[0x7feda092a803]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x16879)[0x7feda0922879]
/lib/x86_64-linux-gnu/libc.so.6(+0x8f6ba)[0x7feda008f6ba]
/lib/x86_64-linux-gnu/libc.so.6(+0x11e120)[0x7feda011e120]

trixprod avatar Nov 24 '24 14:11 trixprod

Apologies, I read the man pages wrong. I thought it would set the errno, but I think that's not the case and it returns error code directly. Please try 614b9d84234cf8c4ed37757baeba10d621ddd21b.

fangfufu avatar Nov 24 '24 17:11 fangfufu

By the way, where did unique: 614, opcode: READ (15), nodeid: 3, insize: 80, pid: 1184337 come from? I don't think I have ever seen httpdirfs printing those.

fangfufu avatar Nov 24 '24 17:11 fangfufu

Retested : Fatal:../src/cache.c:565:Cache_free: could not destroy w_lock: 16, Device or resource busy! I confirm all logs originate from httpdirfs (tested with the -d parameter). When reading a file, I observe numerous logs tracing range byte requests from my server.

unique: 418, opcode: READ (15), nodeid: 5, insize: 80, pid: 1235627
read[140069084081888] 131072 bytes from 327680 flags: 0x8000
   read[140069084081888] 131072 bytes from 327680
   unique: 418, success, outsize: 131088

trixprod avatar Nov 24 '24 18:11 trixprod

More logs :

Error req_size != recv, req_size: 8388608, recv: 8388608 is suspicious.

Also : Thread 69f2b6c0 read cache Thread 5bfff6c0 try to free cache ?

Debug:../src/cache.c:1100:Cache_read: thread 69f2b6c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2024.iso: 33554432-41943039
Debug:../src/link.c:56:Link_to_curl: http://xxxxxxxxxxx/ISO_2024.iso
Error:../src/link.c:1097:Link_download: req_size != recv, req_size: 8388608, recv: 8388608
   read[140069084081888] 36864 bytes from 38948864
   unique: 434, success, outsize: 36880
Debug:../src/cache.c:1019:Cache_bgdl: thread 5bfff6c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2024.iso: 41943040-50331647
Debug:../src/link.c:56:Link_to_curl: http://xxxxxxxxxx/ISO_2024.iso
unique: 436, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140069084081888] flags: 0x8000
fs_release: /ISO_2024.iso
Fatal:../src/cache.c:565:Cache_free: could not destroy w_lock: 16, Device or resource busy!

trixprod avatar Nov 24 '24 18:11 trixprod

Thanks, this log is helpful.

Btw to resolve the crash for now, you can try running httpdirfs in single threaded mode, or turn off the cache system. I am looking into your log right now.

fangfufu avatar Nov 25 '24 00:11 fangfufu

Hi, please try out 6cd006c530dc7bba1cec3a0e3da559fbf18c1c3e. I improved some of the error messages.

Please post a longer log. I want to see when https://github.com/fangfufu/httpdirfs/blob/master/src/cache.c#L945 gets called.

It looks like the lock is being prematurely destroyed. Something is holding the lock open.

fangfufu avatar Nov 25 '24 01:11 fangfufu

Hello, here we go !

LOOKUP /ISOS/202X
getattr[NULL] /ISOS/202X
   NODEID: 3
   unique: 758, success, outsize: 144
unique: 760, opcode: LOOKUP (1), nodeid: 3, insize: 65, pid: 1644951
LOOKUP /ISOS/202X/ISO_2024.iso
getattr[NULL] /ISOS/202X/ISO_2024.iso
   NODEID: 10
   unique: 760, success, outsize: 144
unique: 762, opcode: LOOKUP (1), nodeid: 1, insize: 52, pid: 1639333
LOOKUP /ISOS
getattr[NULL] /ISOS
   NODEID: 2
   unique: 762, success, outsize: 144
unique: 764, opcode: LOOKUP (1), nodeid: 2, insize: 50, pid: 1639333
LOOKUP /ISOS/202X
getattr[NULL] /ISOS/202X
   NODEID: 3
   unique: 764, success, outsize: 144
unique: 766, opcode: LOOKUP (1), nodeid: 3, insize: 65, pid: 1639333
LOOKUP /ISOS/202X/ISO_2024.iso
getattr[NULL] /ISOS/202X/ISO_2024.iso
   NODEID: 10
   unique: 766, success, outsize: 144
unique: 768, opcode: OPEN (14), nodeid: 10, insize: 48, pid: 1645331
open flags: 0x8000 /ISOS/202X/ISO_2024.iso
fs_open: /ISOS/202X/ISO_2024.iso
Debug:../src/fuse_local.c:101:fs_open: /ISOS/202X/ISO_2024.iso found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/ISOS/202X/ISO_2024.iso);
Debug:../src/cache.c:609:Cache_exist: metafn: /ISOS/.cache/meta/ISOS/202X/ISO_2024.iso
Debug:../src/cache.c:611:Cache_exist: datafn: /ISOS/.cache/data/ISOS/202X/ISO_2024.iso
Debug:../src/fuse_local.c:113:fs_open: Cache_delete(/ISOS/202X/ISO_2024.iso);
Debug:../src/fuse_local.c:115:fs_open: Cache_create(/ISOS/202X/ISO_2024.iso);
Debug:../src/cache.c:750:Cache_create: Creating cache files for /ISOS/202X/ISO_2024.iso.
Debug:../src/cache.c:609:Cache_exist: metafn: /ISOS/.cache/meta/ISOS/202X/ISO_2024.iso
Debug:../src/cache.c:611:Cache_exist: datafn: /ISOS/.cache/data/ISOS/202X/ISO_2024.iso
Debug:../src/fuse_local.c:117:fs_open: Cache_open(/ISOS/202X/ISO_2024.iso);
Debug:../src/cache.c:609:Cache_exist: metafn: /ISOS/.cache/meta/ISOS/202X/ISO_2024.iso
Debug:../src/cache.c:611:Cache_exist: datafn: /ISOS/.cache/data/ISOS/202X/ISO_2024.iso
   open[140119281547888] flags: 0x8000 /ISOS/202X/ISO_2024.iso
   unique: 768, success, outsize: 32
unique: 770, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 65536 bytes from 0 flags: 0x8000
Debug:../src/cache.c:1102:Cache_read: thread ffff6c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2024.iso: 0-8388607
Debug:../src/link.c:56:Link_to_curl: http://iso_host:8081/ISOS/202X/ISO_2024.iso
   read[140119281547888] 65536 bytes from 0
   unique: 770, success, outsize: 65552
unique: 772, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645331
getattr[NULL] /ISOS/202X/ISO_2024.iso
   unique: 772, success, outsize: 120
unique: 774, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 65536 flags: 0x8000
   read[140119281547888] 131072 bytes from 65536
   unique: 774, success, outsize: 131088
unique: 776, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 196608 flags: 0x8000
   read[140119281547888] 131072 bytes from 196608
   unique: 776, success, outsize: 131088
unique: 778, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 327680 flags: 0x8000
   read[140119281547888] 131072 bytes from 327680
   unique: 778, success, outsize: 131088
unique: 780, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 458752 flags: 0x8000
   read[140119281547888] 131072 bytes from 458752
   unique: 780, success, outsize: 131088
unique: 782, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 589824 flags: 0x8000
   read[140119281547888] 131072 bytes from 589824
   unique: 782, success, outsize: 131088
unique: 784, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 720896 flags: 0x8000
   read[140119281547888] 131072 bytes from 720896
   unique: 784, success, outsize: 131088
unique: 786, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 851968 flags: 0x8000
   read[140119281547888] 131072 bytes from 851968
   unique: 786, success, outsize: 131088
unique: 788, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645331
getattr[140119281] /ISOS/202X/ISO_2024.iso
   unique: 788, success, outsize: 120
unique: 790, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 983040 flags: 0x8000
   read[140119281547888] 131072 bytes from 983040
   unique: 790, success, outsize: 131088
unique: 792, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1114112 flags: 0x8000
   read[140119281547888] 131072 bytes from 1114112
   unique: 792, success, outsize: 131088
unique: 794, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1245184 flags: 0x8000
   read[140119281547888] 131072 bytes from 1245184
   unique: 794, success, outsize: 131088
unique: 796, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1376256 flags: 0x8000
   read[140119281547888] 131072 bytes from 1376256
   unique: 796, success, outsize: 131088
unique: 798, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1507328 flags: 0x8000
   read[140119281547888] 131072 bytes from 1507328
   unique: 798, success, outsize: 131088
unique: 800, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1638400 flags: 0x8000
   read[140119281547888] 131072 bytes from 1638400
   unique: 800, success, outsize: 131088
unique: 802, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645331
getattr[140119281] /ISOS/202X/ISO_2024.iso
   unique: 802, success, outsize: 120
unique: 804, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1769472 flags: 0x8000
   read[140119281547888] 131072 bytes from 1769472
   unique: 804, success, outsize: 131088
unique: 806, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 1900544 flags: 0x8000
   read[140119281547888] 131072 bytes from 1900544
   unique: 806, success, outsize: 131088
unique: 808, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 2031616 flags: 0x8000
   read[140119281547888] 131072 bytes from 2031616
   unique: 808, success, outsize: 131088
unique: 810, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 2162688 flags: 0x8000
   read[140119281547888] 131072 bytes from 2162688
   unique: 810, success, outsize: 131088
unique: 812, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 2293760 flags: 0x8000
   read[140119281547888] 131072 bytes from 2293760
   unique: 812, success, outsize: 131088
unique: 814, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645331
read[140119281547888] 131072 bytes from 2424832 flags: 0x8000
   read[140119281547888] 131072 bytes from 2424832
   unique: 814, success, outsize: 131088
unique: 816, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645331
getattr[140119281] /ISOS/202X/ISO_2024.iso
   unique: 816, success, outsize: 120
unique: 818, opcode: LOOKUP (1), nodeid: 1, insize: 52, pid: 1645303
LOOKUP /ISOS
getattr[NULL] /ISOS
   NODEID: 2
   unique: 818, success, outsize: 144
unique: 820, opcode: LOOKUP (1), nodeid: 2, insize: 50, pid: 1645303
LOOKUP /ISOS/202X
getattr[NULL] /ISOS/202X
   NODEID: 3
   unique: 820, success, outsize: 144
unique: 822, opcode: LOOKUP (1), nodeid: 3, insize: 65, pid: 1645303
LOOKUP /ISOS/202X/ISO_2024.iso
getattr[NULL] /ISOS/202X/ISO_2024.iso
   NODEID: 10
   unique: 822, success, outsize: 144
unique: 824, opcode: RELEASE (18), nodeid: 10, insize: 64, pid: 0
release[140119281547888] flags: 0x8000
fs_release: /ISOS/202X/ISO_2024.iso
   unique: 824, success, outsize: 16
unique: 826, opcode: OPEN (14), nodeid: 10, insize: 48, pid: 1645356
open flags: 0x8000 /ISOS/202X/ISO_2024.iso
fs_open: /ISOS/202X/ISO_2024.iso
Debug:../src/fuse_local.c:101:fs_open: /ISOS/202X/ISO_2024.iso found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/ISOS/202X/ISO_2024.iso);
Debug:../src/cache.c:609:Cache_exist: metafn: /ISOS/.cache/meta/ISOS/202X/ISO_2024.iso
Debug:../src/cache.c:611:Cache_exist: datafn: /ISOS/.cache/data/ISOS/202X/ISO_2024.iso
   open[140119013090176] flags: 0x8000 /ISOS/202X/ISO_2024.iso
   unique: 826, success, outsize: 32
unique: 828, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 65536 bytes from 0 flags: 0x8000
   read[140119013090176] 65536 bytes from 0
   unique: 828, success, outsize: 65552
unique: 830, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645356
getattr[NULL] /ISOS/202X/ISO_2024.iso
   unique: 830, success, outsize: 120
unique: 832, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 12288 bytes from 171675648 flags: 0x8000
Debug:../src/cache.c:1102:Cache_read: thread f7fe6c0: spawned.
 Link_download: requested size larger than remaining size, request_end: 176160768, content-length: 171687104
Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2024.iso: 167772160-171687103
Debug:../src/link.c:56:Link_to_curl: http://iso_host:8081/ISOS/202X/ISO_2024.iso
   read[140119013090176] 11456 bytes from 171675648
   unique: 832, success, outsize: 11472
unique: 834, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645356
getattr[140119013] /ISOS/202X/ISO_2024.iso
   unique: 834, success, outsize: 120
unique: 836, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 36864 bytes from 31932416 flags: 0x8000
Debug:../src/cache.c:1102:Cache_read: thread ffff6c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2024.iso: 25165824-33554431
Debug:../src/link.c:56:Link_to_curl: http://iso_host:8081/ISOS/202X/ISO_2024.iso
   read[140119013090176] 36864 bytes from 31932416
   unique: 836, success, outsize: 36880
Debug:../src/cache.c:1021:Cache_bgdl: thread effd6c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2024.iso: 33554432-41943039
Debug:../src/link.c:56:Link_to_curl: http://iso_host:8081/ISOS/202X/ISO_2024.iso
unique: 838, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645356
getattr[140119013] /ISOS/202X/ISO_2024.iso
   unique: 838, success, outsize: 120
unique: 840, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 65536 bytes from 31969280 flags: 0x8000
   read[140119013090176] 65536 bytes from 31969280
   unique: 840, success, outsize: 65552
unique: 842, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32034816 flags: 0x8000
   read[140119013090176] 131072 bytes from 32034816
   unique: 842, success, outsize: 131088
unique: 844, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32165888 flags: 0x8000
   read[140119013090176] 131072 bytes from 32165888
   unique: 844, success, outsize: 131088
unique: 846, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32296960 flags: 0x8000
   read[140119013090176] 131072 bytes from 32296960
   unique: 846, success, outsize: 131088
unique: 848, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32428032 flags: 0x8000
   read[140119013090176] 131072 bytes from 32428032
   unique: 848, success, outsize: 131088
unique: 850, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32559104 flags: 0x8000
   read[140119013090176] 131072 bytes from 32559104
   unique: 850, success, outsize: 131088
unique: 852, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32690176 flags: 0x8000
   read[140119013090176] 131072 bytes from 32690176
   unique: 852, success, outsize: 131088
unique: 854, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32821248 flags: 0x8000
   read[140119013090176] 131072 bytes from 32821248
   unique: 854, success, outsize: 131088
unique: 856, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 32952320 flags: 0x8000
   read[140119013090176] 131072 bytes from 32952320
   unique: 856, success, outsize: 131088
unique: 858, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 33083392 flags: 0x8000
   read[140119013090176] 131072 bytes from 33083392
   unique: 858, success, outsize: 131088
unique: 860, opcode: READ (15), nodeid: 10, insize: 80, pid: 1645356
read[140119013090176] 131072 bytes from 33214464 flags: 0x8000
   read[140119013090176] 131072 bytes from 33214464
   unique: 860, success, outsize: 131088
unique: 862, opcode: GETATTR (3), nodeid: 10, insize: 56, pid: 1645356
getattr[140119013] /ISOS/202X/ISO_2024.iso
   unique: 862, success, outsize: 120
unique: 864, opcode: LOOKUP (1), nodeid: 1, insize: 52, pid: 1639333
LOOKUP /ISOS
getattr[NULL] /ISOS
   NODEID: 2
   unique: 864, success, outsize: 144
unique: 866, opcode: LOOKUP (1), nodeid: 2, insize: 50, pid: 1639333
LOOKUP /ISOS/202X
getattr[NULL] /ISOS/202X
   NODEID: 3
   unique: 866, success, outsize: 144
unique: 868, opcode: LOOKUP (1), nodeid: 3, insize: 65, pid: 1639333
LOOKUP /ISOS/202X/ISO_2024.iso
getattr[NULL] /ISOS/202X/ISO_2024.iso
   NODEID: 10
   unique: 868, success, outsize: 144
unique: 870, opcode: RELEASE (18), nodeid: 10, insize: 64, pid: 0
release[140119013090176] flags: 0x8000
fs_release: /ISOS/202X/ISO_2024.iso
Fatal:../src/cache.c:565:Cache_free: could not destroy w_lock: 16, Device or resource busy!

Oops! HTTPDirFS crashed! :(
backtrace() returned the following 11 addresses:
httpdirfs(+0xae10)[0x55b3dfeede10]
httpdirfs(+0xc392)[0x55b3dfeef392]
httpdirfs(+0x8b03)[0x55b3dfeebb03]
httpdirfs(+0x53b9)[0x55b3dfee83b9]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0xbb29)[0x7f7015ea8b29]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1065a)[0x7f7015ead65a]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x11948)[0x7f7015eae948]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1e803)[0x7f7015ebb803]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x16879)[0x7f7015eb3879]
/lib/x86_64-linux-gnu/libc.so.6(+0x8f6ba)[0x7f701568f6ba]
/lib/x86_64-linux-gnu/libc.so.6(+0x11e120)[0x7f701571e120]

trixprod avatar Nov 26 '24 06:11 trixprod

Hello @fangfufu, let me know if you need additional logs or any specific tests.

trixprod avatar Nov 28 '24 18:11 trixprod

More log ( with cache log traces )


LOOKUP /ISO_2023.iso
getattr[NULL] /ISO_2023.iso
   NODEID: 4
   unique: 1278, success, outsize: 144
unique: 1280, opcode: OPEN (14), nodeid: 4, insize: 48, pid: 2588785
open flags: 0x8000 /ISO_2023.iso
Debug:../src/fuse_local.c:103:fs_open: /ISO_2023.iso found.
Debug:../src/fuse_local.c:108:fs_open: Cache_open(/ISO_2023.iso);
Debug:../src/cache.c:610:Cache_exist: metafn: /ISOS/.cache/meta/ISO_2023.iso
Debug:../src/cache.c:612:Cache_exist: datafn: /ISOS/.cache/data/ISO_2023.iso
Debug:../src/fuse_local.c:115:fs_open: Cache_delete(/ISO_2023.iso);
Debug:../src/fuse_local.c:117:fs_open: Cache_create(/ISO_2023.iso);
Debug:../src/cache.c:751:Cache_create: Creating cache files for /ISO_2023.iso.
Debug:../src/cache.c:610:Cache_exist: metafn: /ISOS/.cache/meta/ISO_2023.iso
Debug:../src/cache.c:612:Cache_exist: datafn: /ISOS/.cache/data/ISO_2023.iso
Debug:../src/fuse_local.c:119:fs_open: Cache_open(/ISO_2023.iso);
Debug:../src/cache.c:610:Cache_exist: metafn: /ISOS/.cache/meta/ISO_2023.iso
Debug:../src/cache.c:612:Cache_exist: datafn: /ISOS/.cache/data/ISO_2023.iso
   open[140208940004720] flags: 0x8000 /ISO_2023.iso
   unique: 1280, success, outsize: 32
unique: 1282, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140208940004720] 131072 bytes from 0 flags: 0x8000
Debug:../src/cache.c:1103:Cache_read: thread f91316c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2023.iso: 0-8388607
Debug:../src/link.c:56:Link_to_curl: http://isos:8080/ISO_2023.iso
   read[140208940004720] 131072 bytes from 0
   unique: 1282, success, outsize: 131088
unique: 1284, opcode: GETATTR (3), nodeid: 4, insize: 56, pid: 2588785
getattr[140208940] /ISO_2023.iso
   unique: 1284, success, outsize: 120
unique: 1286, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140208940004720] 69632 bytes from 455340032 flags: 0x8000
Debug:../src/cache.c:1103:Cache_read: thread fa96a6c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2023.iso: 452984832-455407909
Debug:../src/link.c:56:Link_to_curl: http://isos:8080/ISO_2023.iso
   read[140208940004720] 67878 bytes from 455340032
   unique: 1286, success, outsize: 67894
unique: 1288, opcode: RELEASE (18), nodeid: 4, insize: 64, pid: 0
release[140208940004720] flags: 0x8000
   unique: 1288, success, outsize: 16
unique: 1290, opcode: LOOKUP (1), nodeid: 1, insize: 66, pid: 2588785
LOOKUP /ISO_2023.iso
getattr[NULL] /ISO_2023.iso
   NODEID: 4
   unique: 1290, success, outsize: 144
unique: 1292, opcode: OPEN (14), nodeid: 4, insize: 48, pid: 2588785
open flags: 0x8000 /ISO_2023.iso
Debug:../src/fuse_local.c:103:fs_open: /ISO_2023.iso found.
Debug:../src/fuse_local.c:108:fs_open: Cache_open(/ISO_2023.iso);
Debug:../src/cache.c:610:Cache_exist: metafn: /ISOS/.cache/meta/ISO_2023.iso
Debug:../src/cache.c:612:Cache_exist: datafn: /ISOS/.cache/data/ISO_2023.iso
   open[140209007135296] flags: 0x8000 /ISO_2023.iso
   unique: 1292, success, outsize: 32
unique: 1294, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140209007135296] 65536 bytes from 0 flags: 0x8000
   read[140209007135296] 65536 bytes from 0
   unique: 1294, success, outsize: 65552
unique: 1296, opcode: GETATTR (3), nodeid: 4, insize: 56, pid: 2588785
getattr[NULL] /ISO_2023.iso
   unique: 1296, success, outsize: 120
unique: 1298, opcode: RELEASE (18), nodeid: 4, insize: 64, pid: 0
release[140209007135296] flags: 0x8000
   unique: 1298, success, outsize: 16
unique: 1300, opcode: OPEN (14), nodeid: 4, insize: 48, pid: 2588785
open flags: 0x8000 /ISO_2023.iso
Debug:../src/fuse_local.c:103:fs_open: /ISO_2023.iso found.
Debug:../src/fuse_local.c:108:fs_open: Cache_open(/ISO_2023.iso);
Debug:../src/cache.c:610:Cache_exist: metafn: /ISOS/.cache/meta/ISO_2023.iso
Debug:../src/cache.c:612:Cache_exist: datafn: /ISOS/.cache/data/ISO_2023.iso
   open[140209007111872] flags: 0x8000 /ISO_2023.iso
   unique: 1300, success, outsize: 32
unique: 1302, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140209007111872] 65536 bytes from 0 flags: 0x8000
   read[140209007111872] 65536 bytes from 0
   unique: 1302, success, outsize: 65552
unique: 1304, opcode: GETATTR (3), nodeid: 4, insize: 56, pid: 2588785
getattr[NULL] /ISO_2023.iso
   unique: 1304, success, outsize: 120
unique: 1306, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140209007111872] 32768 bytes from 455376896 flags: 0x8000
   read[140209007111872] 31014 bytes from 455376896
   unique: 1306, success, outsize: 31030
unique: 1308, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140209007111872] 36864 bytes from 248619008 flags: 0x8000
Debug:../src/cache.c:1103:Cache_read: thread fb16b6c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2023.iso: 243269632-251658239
Debug:../src/link.c:56:Link_to_curl: http://isos:8080/ISO_2023.iso
   read[140209007111872] 36864 bytes from 248619008
   unique: 1308, success, outsize: 36880
Debug:../src/cache.c:1022:Cache_bgdl: thread f99686c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2023.iso: 251658240-260046847
Debug:../src/link.c:56:Link_to_curl: http://isos:8080/ISO_2023.iso
unique: 1310, opcode: GETATTR (3), nodeid: 4, insize: 56, pid: 2588785
getattr[140209007] /ISO_2023.iso
   unique: 1310, success, outsize: 120
unique: 1312, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140209007111872] 36864 bytes from 252698624 flags: 0x8000
unique: 1314, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 2585024
getattr[NULL] /
   unique: 1314, success, outsize: 120
   read[140209007111872] 36864 bytes from 252698624
   unique: 1312, success, outsize: 36880
unique: 1316, opcode: GETATTR (3), nodeid: 4, insize: 56, pid: 2588785
getattr[140209007] /ISO_2023.iso
   unique: 1316, success, outsize: 120
unique: 1318, opcode: READ (15), nodeid: 4, insize: 80, pid: 2588785
read[140209007111872] 36864 bytes from 257052672 flags: 0x8000
   read[140209007111872] 36864 bytes from 257052672
   unique: 1318, success, outsize: 36880
Debug:../src/cache.c:1022:Cache_bgdl: thread f99686c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: ISO_2023.iso: 260046848-268435455
Debug:../src/link.c:56:Link_to_curl: http://isos:8080/ISO_2023.iso
unique: 1320, opcode: RELEASE (18), nodeid: 4, insize: 64, pid: 0
release[140209007111872] flags: 0x8000
Fatal:../src/cache.c:566:Cache_free: could not destroy w_lock: 16, Device or resource busy!

Oops! HTTPDirFS crashed! :(
backtrace() returned the following 11 addresses:
httpdirfs(+0xae50)[0x55b998184e50]
httpdirfs(+0xc3d2)[0x55b9981863d2]
httpdirfs(+0x8b43)[0x55b998182b43]
httpdirfs(+0x53f9)[0x55b99817f3f9]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0xbb29)[0x7f84fc2d4b29]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1065a)[0x7f84fc2d965a]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x11948)[0x7f84fc2da948]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1e803)[0x7f84fc2e7803]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x16879)[0x7f84fc2df879]
/lib/x86_64-linux-gnu/libc.so.6(+0x8f6ba)[0x7f84fba8f6ba]
/lib/x86_64-linux-gnu/libc.so.6(+0x11e120)[0x7f84fbb1e120]
unique: 1322, opcode: LOOKUP (1), nodeid: 1, insize: 66, pid: 2588785
LOOKUP /ISO_2023.iso
getattr[NULL] /ISO_2023.iso
   NODEID: 4
   unique: 1322, success, outsize: 144
unique: 1324, opcode: OPEN (14), nodeid: 4, insize: 48, pid: 2588785
open flags: 0x8000 /ISO_2023.iso
Debug:../src/fuse_local.c:103:fs_open: /ISO_2023.iso found.
Debug:../src/fuse_local.c:108:fs_open: Cache_open(/ISO_2023.iso);
Debug:../src/cache.c:610:Cache_exist: metafn: /ISOS/.cache/meta/ISO_2023.iso
Debug:../src/cache.c:612:Cache_exist: datafn: /ISOS/.cache/data/ISO_2023.iso

trixprod avatar Nov 29 '24 10:11 trixprod

I am in the middle of house moving, so I won't have much time to work for this in the next few weeks. In the mean time please turn off the cache system. It should work fine.

From a quick look, I can't figure out why Cache_free was called. Your debug message is incomplete. Please try eca4375c3530c835644a61d272aba7b470d7d76d, you also need to do the following:

in your local copy, at this line here https://github.com/fangfufu/httpdirfs/blob/master/src/log.h#L23, please add cache_lock_debug

This was mentioned in the comment from a week ago: https://github.com/fangfufu/httpdirfs/issues/174#issuecomment-2495188200. If you do that, there will be more messages about when Cache_free was called. I don't want to enable those messages in the default debug build, as it generates quite a bit of noise.

fangfufu avatar Dec 01 '24 03:12 fangfufu

Hello @fangfufu , I hope your move is going well. No worries, no one is in a rush. Following your recommandation of setting cache_lock_debug.

#define DEFAULT_LOG_LEVEL fatal | error | warning | info | cache_lock_debug Here is the log ( tested on another server but same result )

LOOKUP /FLAT_ISO_ARCH.ISO
getattr[NULL] /FLAT_ISO_ARCH.ISO
   NODEID: 5
   unique: 1302, success, outsize: 144
unique: 1304, opcode: OPEN (14), nodeid: 5, insize: 48, pid: 2272427
open flags: 0x8000 /FLAT_ISO_ARCH.ISO
fs_open: /FLAT_ISO_ARCH.ISO
Debug:../src/fuse_local.c:101:fs_open: /FLAT_ISO_ARCH.ISO found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/FLAT_ISO_ARCH.ISO);
Debug(80):../src/cache.c:810:Cache_open: thread f51a06c0: locking cf_lock;
Debug:../src/cache.c:609:Cache_exist: metafn: /cache_dir/meta//FLAT_ISO_ARCH.ISO
Debug:../src/cache.c:611:Cache_exist: datafn: /cache_dir/data//FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:829:Cache_open: thread f51a06c0: unlocking cf_lock;
Debug:../src/fuse_local.c:113:fs_open: Cache_delete(/FLAT_ISO_ARCH.ISO);
Debug:../src/fuse_local.c:115:fs_open: Cache_create(/FLAT_ISO_ARCH.ISO);
Debug:../src/cache.c:750:Cache_create: Creating cache files for /FLAT_ISO_ARCH.ISO.
Debug(80):../src/cache.c:779:Cache_create: Flusing cache file for /FLAT_ISO_ARCH.ISO after creating.
Debug:../src/cache.c:609:Cache_exist: metafn: /cache_dir/meta//FLAT_ISO_ARCH.ISO
Debug:../src/cache.c:611:Cache_exist: datafn: /cache_dir/data//FLAT_ISO_ARCH.ISO
Debug:../src/fuse_local.c:117:fs_open: Cache_open(/FLAT_ISO_ARCH.ISO);
Debug(80):../src/cache.c:810:Cache_open: thread f51a06c0: locking cf_lock;
Debug:../src/cache.c:609:Cache_exist: metafn: /cache_dir/meta//FLAT_ISO_ARCH.ISO
Debug:../src/cache.c:611:Cache_exist: datafn: /cache_dir/data//FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:940:Cache_open: thread f51a06c0: unlocking cf_lock;
   open[140062709787840] flags: 0x8000 /FLAT_ISO_ARCH.ISO
   unique: 1304, success, outsize: 32
unique: 1306, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062709787840] 131072 bytes from 0 flags: 0x8000
Debug(80):../src/cache.c:1078:Cache_read: thread 140063031330496: locking w_lock;
Debug:../src/cache.c:1103:Cache_read: thread f73a86c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: FLAT_ISO_ARCH.ISO: 0-8388607
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:461:Data_write: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:492:Data_write: thread f73a86c0: unlocking seek_lock;
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
Debug(80):../src/cache.c:1127:Cache_read: thread f73a86c0: unlocking w_lock;
   read[140062709787840] 131072 bytes from 0
   unique: 1306, success, outsize: 131088
unique: 1308, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[140062709] /FLAT_ISO_ARCH.ISO
   unique: 1308, success, outsize: 120
unique: 1310, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062709787840] 69632 bytes from 63352832 flags: 0x8000
Debug(80):../src/cache.c:1078:Cache_read: thread 140063021881024: locking w_lock;
Debug:../src/cache.c:1103:Cache_read: thread f6aa56c0: spawned.
 Link_download: requested size larger than remaining size, request_end: 67108864, content-length: 63418454
Debug:../src/link.c:1004:Link_download_curl_setup: FLAT_ISO_ARCH.ISO: 58720256-63418453
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:461:Data_write: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:492:Data_write: thread f6aa56c0: unlocking seek_lock;
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
Debug(80):../src/cache.c:1127:Cache_read: thread f6aa56c0: unlocking w_lock;
   read[140062709787840] 65622 bytes from 63352832
   unique: 1310, success, outsize: 65638
unique: 1312, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140062709787840] flags: 0x8000
fs_release: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:948:Cache_close: thread f51a06c0: locking cf_lock: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:977:Cache_close: thread f51a06c0: unlocking cf_lock, cache closed: /FLAT_ISO_ARCH.ISO
   unique: 1312, success, outsize: 16
unique: 1314, opcode: LOOKUP (1), nodeid: 1, insize: 62, pid: 2272427
LOOKUP /FLAT_ISO_ARCH.ISO
getattr[NULL] /FLAT_ISO_ARCH.ISO
   NODEID: 5
   unique: 1314, success, outsize: 144
unique: 1316, opcode: OPEN (14), nodeid: 5, insize: 48, pid: 2272427
open flags: 0x8000 /FLAT_ISO_ARCH.ISO
fs_open: /FLAT_ISO_ARCH.ISO
Debug:../src/fuse_local.c:101:fs_open: /FLAT_ISO_ARCH.ISO found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/FLAT_ISO_ARCH.ISO);
Debug(80):../src/cache.c:810:Cache_open: thread f59a16c0: locking cf_lock;
Debug:../src/cache.c:609:Cache_exist: metafn: /cache_dir/meta//FLAT_ISO_ARCH.ISO
Debug:../src/cache.c:611:Cache_exist: datafn: /cache_dir/data//FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:940:Cache_open: thread f59a16c0: unlocking cf_lock;
   open[140062844015392] flags: 0x8000 /FLAT_ISO_ARCH.ISO
   unique: 1316, success, outsize: 32
unique: 1318, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 65536 bytes from 0 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 65536 bytes from 0
   unique: 1318, success, outsize: 65552
unique: 1320, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1320, success, outsize: 120
unique: 1322, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 65536 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 65536
   unique: 1322, success, outsize: 131088
unique: 1324, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 196608 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 196608
   unique: 1324, success, outsize: 131088
unique: 1326, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 327680 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 327680
   unique: 1326, success, outsize: 131088
unique: 1328, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 458752 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 458752
   unique: 1328, success, outsize: 131088
unique: 1330, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 589824 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 589824
   unique: 1330, success, outsize: 131088
unique: 1332, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 720896 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 720896
   unique: 1332, success, outsize: 131088
unique: 1334, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 851968 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 851968
   unique: 1334, success, outsize: 131088
unique: 1336, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 983040 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 983040
   unique: 1336, success, outsize: 131088
unique: 1338, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 1114112 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 1114112
   unique: 1338, success, outsize: 131088
unique: 1340, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1340, success, outsize: 120
unique: 1342, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 1245184 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 1245184
   unique: 1342, success, outsize: 131088
unique: 1344, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1344, success, outsize: 120
unique: 1346, opcode: OPEN (14), nodeid: 5, insize: 48, pid: 2272427
open flags: 0x8000 /FLAT_ISO_ARCH.ISO
fs_open: /FLAT_ISO_ARCH.ISO
Debug:../src/fuse_local.c:101:fs_open: /FLAT_ISO_ARCH.ISO found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/FLAT_ISO_ARCH.ISO);
Debug(80):../src/cache.c:810:Cache_open: thread f73a86c0: locking cf_lock;
Debug(80):../src/cache.c:817:Cache_open: thread f73a86c0: unlocking cf_lock;
   open[140062844015392] flags: 0x8000 /FLAT_ISO_ARCH.ISO
   unique: 1346, success, outsize: 32
unique: 1348, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 16384 bytes from 0 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062844015392] 16384 bytes from 0
   unique: 1348, success, outsize: 16400
unique: 1352, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 65536 bytes from 49152 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062844015392] 65536 bytes from 49152
   unique: 1352, success, outsize: 65552
unique: 1350, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 32768 bytes from 16384 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 32768 bytes from 16384
   unique: 1350, success, outsize: 32784
unique: 1354, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 114688 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 114688
   unique: 1354, success, outsize: 131088
unique: 1356, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 245760 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 245760
   unique: 1356, success, outsize: 131088
unique: 1358, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 376832 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 376832
   unique: 1358, success, outsize: 131088
unique: 1360, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 507904 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
unique: 1362, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 638976 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 638976
   unique: 1362, success, outsize: 131088
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 507904
   unique: 1360, success, outsize: 131088
unique: 1364, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 770048 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 770048
   unique: 1364, success, outsize: 131088
unique: 1366, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 901120 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 901120
   unique: 1366, success, outsize: 131088
unique: 1368, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 1032192 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 1032192
   unique: 1368, success, outsize: 131088
unique: 1370, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062844015392] 131072 bytes from 1163264 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062844015392] 131072 bytes from 1163264
   unique: 1370, success, outsize: 131088
unique: 1372, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140062844015392] flags: 0x8000
fs_release: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:948:Cache_close: thread f59a16c0: locking cf_lock: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:956:Cache_close: thread f59a16c0: unlocking cf_lock: /FLAT_ISO_ARCH.ISO, cache_opened: 1
   unique: 1372, success, outsize: 16
unique: 1374, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140062844015392] flags: 0x8000
fs_release: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:948:Cache_close: thread f51a06c0: locking cf_lock: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:977:Cache_close: thread f51a06c0: unlocking cf_lock, cache closed: /FLAT_ISO_ARCH.ISO
   unique: 1374, success, outsize: 16
unique: 1376, opcode: OPEN (14), nodeid: 5, insize: 48, pid: 2272427
open flags: 0x8000 /FLAT_ISO_ARCH.ISO
fs_open: /FLAT_ISO_ARCH.ISO
Debug:../src/fuse_local.c:101:fs_open: /FLAT_ISO_ARCH.ISO found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/FLAT_ISO_ARCH.ISO);
Debug(80):../src/cache.c:810:Cache_open: thread f73a86c0: locking cf_lock;
Debug:../src/cache.c:609:Cache_exist: metafn: /cache_dir/meta//FLAT_ISO_ARCH.ISO
Debug:../src/cache.c:611:Cache_exist: datafn: /cache_dir/data//FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:940:Cache_open: thread f73a86c0: unlocking cf_lock;
   open[140062910144448] flags: 0x8000 /FLAT_ISO_ARCH.ISO
   unique: 1376, success, outsize: 32
unique: 1378, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1378, success, outsize: 120
unique: 1380, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 65536 bytes from 0 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062910144448] 65536 bytes from 0
   unique: 1380, success, outsize: 65552
unique: 1382, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1382, success, outsize: 120
unique: 1384, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 65536 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 65536
   unique: 1384, success, outsize: 131088
unique: 1386, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 196608 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 196608
   unique: 1386, success, outsize: 131088
unique: 1388, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 327680 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 327680
   unique: 1388, success, outsize: 131088
unique: 1390, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 458752 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 458752
   unique: 1390, success, outsize: 131088
unique: 1392, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 589824 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 589824
   unique: 1392, success, outsize: 131088
unique: 1394, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 720896 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f6aa56c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f6aa56c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 720896
   unique: 1394, success, outsize: 131088
unique: 1396, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 851968 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 851968
   unique: 1396, success, outsize: 131088
unique: 1398, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 983040 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f51a06c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f51a06c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 983040
   unique: 1398, success, outsize: 131088
unique: 1400, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 1114112 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 1114112
   unique: 1400, success, outsize: 131088
unique: 1402, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1402, success, outsize: 120
unique: 1404, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 131072 bytes from 1245184 flags: 0x8000
Debug(80):../src/cache.c:387:Data_read: thread f59a16c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f59a16c0: unlocking seek_lock;
   read[140062910144448] 131072 bytes from 1245184
   unique: 1404, success, outsize: 131088
unique: 1406, opcode: GETATTR (3), nodeid: 5, insize: 56, pid: 2272427
getattr[NULL] /FLAT_ISO_ARCH.ISO
   unique: 1406, success, outsize: 120
unique: 1408, opcode: READ (15), nodeid: 5, insize: 80, pid: 2272427
read[140062910144448] 36864 bytes from 32964608 flags: 0x8000
Debug(80):../src/cache.c:1078:Cache_read: thread 140063031330496: locking w_lock;
Debug:../src/cache.c:1103:Cache_read: thread f73a86c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: FLAT_ISO_ARCH.ISO: 25165824-33554431
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/FLAT_ISO_ARCH.ISO
unique: 1410, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 2272267
getattr[NULL] /
   unique: 1410, success, outsize: 120
Debug(80):../src/cache.c:461:Data_write: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:492:Data_write: thread f73a86c0: unlocking seek_lock;
Debug(80):../src/cache.c:387:Data_read: thread f73a86c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread f73a86c0: unlocking seek_lock;
Debug(80):../src/cache.c:1127:Cache_read: thread f73a86c0: unlocking w_lock;
Debug(80):../src/cache.c:1143:Cache_read: thread f73a86c0: trylocked bgt_lock;
   read[140062910144448] 36864 bytes from 32964608
   unique: 1408, success, outsize: 36880
Debug(80):../src/cache.c:1017:Cache_bgdl: thread f61a26c0: locking w_lock;
Debug:../src/cache.c:1022:Cache_bgdl: thread f61a26c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: FLAT_ISO_ARCH.ISO: 33554432-41943039
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/FLAT_ISO_ARCH.ISO
unique: 1412, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140062910144448] flags: 0x8000
fs_release: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:948:Cache_close: thread f59a16c0: locking cf_lock: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:977:Cache_close: thread f59a16c0: unlocking cf_lock, cache closed: /FLAT_ISO_ARCH.ISO
Fatal:../src/cache.c:565:Cache_free: could not destroy w_lock: 16, Device or resource busy!

Oops! HTTPDirFS crashed! :(
backtrace() returned the following 11 addresses:
httpdirfs(+0xae30)[0x56549b046e30]
httpdirfs(+0xc3b2)[0x56549b0483b2]
httpdirfs(+0x8b03)[0x56549b044b03]
httpdirfs(+0x53b9)[0x56549b0413b9]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0xbb29)[0x7f62f8511b29]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1065a)[0x7f62f851665a]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x11948)[0x7f62f8517948]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x1e803)[0x7f62f8524803]
/lib/x86_64-linux-gnu/libfuse3.so.3(+0x16879)[0x7f62f851c879]
/lib/x86_64-linux-gnu/libc.so.6(+0x8f6ba)[0x7f62f7c8f6ba]
/lib/x86_64-linux-gnu/libc.so.6(+0x11e120)[0x7f62f7d1e120]

trixprod avatar Dec 05 '24 22:12 trixprod

Okat this new log is far more useful. I will have a look over the weekend. I am still in the process of cleaning my old flat and unpacking. I will only have time to work on this project when I want to relax. :/ I /need/ to return the key for my old flat next Monday...

fangfufu avatar Dec 06 '24 00:12 fangfufu 

Debug(80):../src/cache.c:1017:Cache_bgdl: thread f61a26c0: locking w_lock;
Debug:../src/cache.c:1022:Cache_bgdl: thread f61a26c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: FLAT_ISO_ARCH.ISO: 33554432-41943039
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/FLAT_ISO_ARCH.ISO
unique: 1412, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140062910144448] flags: 0x8000
fs_release: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:948:Cache_close: thread f59a16c0: locking cf_lock: /FLAT_ISO_ARCH.ISO
Debug(80):../src/cache.c:977:Cache_close: thread f59a16c0: unlocking cf_lock, cache closed: /FLAT_ISO_ARCH.ISO
Fatal:../src/cache.c:565:Cache_free: could not destroy w_lock: 16, Device or resource busy!

You can see here that w_lock got locked once, and it wasn't unlocked before Cache_close() was called.

fangfufu avatar Dec 06 '24 00:12 fangfufu

It looks to me that Cache_bgdl might not have finished when Cache_close() was called. This seems to be proper race condition to me.

Well, thanks for reporting this bug, I find it surprising that nobody has triggered this before. What distro is your client running again?

fangfufu avatar Dec 06 '24 00:12 fangfufu

Just to clarify, this has got nothing to do with your server, this has got to do with your client. It is my implementation's problem.

fangfufu avatar Dec 06 '24 01:12 fangfufu

Okay, please try this: 36b5b44ffc26e4afca41bb589dbc36e38bc701a1

Please enable all the debug features I mentioned previous.

Please note that this revision might just hang. It might not be working correctly. But do let me know how it performs.

fangfufu avatar Dec 06 '24 01:12 fangfufu

Hello @fangfufu, I'm heavily testing under Ubuntu 23 ( client )

First error when the backend is returning a bad receiving size : -2. I think this should not be fatal. (imo)

Warning:../src/link.c:1053:Link_download_cleanup: Could not download http://localhost:10002/TEST_ISO_ARCH_124.iso, HTTP 302
Error:../src/link.c:1096:Link_download: req_size != recv, req_size: 8388608, recv: -2
Error:../src/cache.c:1113:Cache_read: thread ffff6c0 received -2 bytes, which doesn't make sense
Error:../src/cache.c:1127:Cache_read: received -2 rather than 8388608, possible network error.
double free or corruption (!prev)

Second error, more cache related :

getattr[NULL] /TEST_ISO_ARCH_500.iso
   unique: 9248, success, outsize: 120
unique: 9250, opcode: READ (15), nodeid: 212, insize: 80, pid: 53547
read[140698900839712] 36864 bytes from 24035328 flags: 0x8000
Debug(80):../src/cache.c:1084:Cache_read: thread 140699133585088: locking w_lock;
Debug:../src/cache.c:1109:Cache_read: thread 11e0a6c0: spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: TEST_ISO_ARCH_500.iso: 16777216-25165823
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/TEST_ISO_ARCH_500.iso
Debug(80):../src/cache.c:461:Data_write: thread 11e0a6c0: locking seek_lock;
Debug(80):../src/cache.c:492:Data_write: thread 11e0a6c0: unlocking seek_lock;
Debug(80):../src/cache.c:387:Data_read: thread 11e0a6c0: locking seek_lock;
Debug(80):../src/cache.c:435:Data_read: thread 11e0a6c0: unlocking seek_lock;
Debug(80):../src/cache.c:1133:Cache_read: thread 11e0a6c0: unlocking w_lock;
Debug(80):../src/cache.c:1149:Cache_read: thread 11e0a6c0: trylocked bgt_lock;
   read[140698900839712] 36864 bytes from 24035328
   unique: 9250, success, outsize: 36880
Debug(80):../src/cache.c:1023:Cache_bgdl: thread 10bdf6c0: locking w_lock;
Debug:../src/cache.c:1028:Cache_bgdl: thread 10bdf6c0 spawned.
 Debug:../src/link.c:1004:Link_download_curl_setup: TEST_ISO_ARCH_500.iso: 25165824-33554431
Debug:../src/link.c:56:Link_to_curl: http://localhost:10002/TEST_ISO_ARCH_500.iso
unique: 9252, opcode: RELEASE (18), nodeid: 212, insize: 64, pid: 0
release[140698900839712] flags: 0x8000
fs_release: /TEST_ISO_ARCH_500.iso
Debug(80):../src/cache.c:954:Cache_close: thread 114eb6c0: locking cf_lock: /TEST_ISO_ARCH_500.iso
Debug(80):../src/cache.c:983:Cache_close: thread 114eb6c0: unlocking cf_lock, cache closed: /TEST_ISO_ARCH_500.iso
unique: 9254, opcode: LOOKUP (1), nodeid: 1, insize: 65, pid: 52708
LOOKUP /TEST_ISO_ARCH_500.iso
getattr[NULL] /TEST_ISO_ARCH_500.iso
   NODEID: 212
   unique: 9254, success, outsize: 144
unique: 9256, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 53488
getattr[NULL] /
   unique: 9256, success, outsize: 120
unique: 9258, opcode: OPEN (14), nodeid: 212, insize: 48, pid: 53574
open flags: 0x8000 /TEST_ISO_ARCH_500.iso
fs_open: /TEST_ISO_ARCH_500.iso
Debug:../src/fuse_local.c:101:fs_open: /TEST_ISO_ARCH_500.iso found.
Debug:../src/fuse_local.c:106:fs_open: Cache_open(/TEST_ISO_ARCH_500.iso);
Debug(80):../src/cache.c:816:Cache_open: thread 1270d6c0: locking cf_lock;
Debug(80):../src/cache.c:461:Data_write: thread 10bdf6c0: locking seek_lock;
Fatal:../src/util.c:72:PTHREAD_MUTEX_LOCK: thread 10bdf6c0: 22, Invalid argument

Oops! HTTPDirFS crashed! :(
backtrace() returned the following 7 addresses:
httpdirfs(+0xae50)[0x56022b4b5e50]
httpdirfs(+0xc3d2)[0x56022b4b73d2]
httpdirfs(+0xae0c)[0x56022b4b5e0c]
httpdirfs(+0x8ef0)[0x56022b4b3ef0]
httpdirfs(+0x91ee)[0x56022b4b41ee]
/lib/x86_64-linux-gnu/libc.so.6(+0x8f6ba)[0x7ff712e8f6ba]
/lib/x86_64-linux-gnu/libc.so.6(+0x11e120)[0x7ff712f1e120]

trixprod avatar Dec 06 '24 11:12 trixprod

The first error is related to https://github.com/fangfufu/httpdirfs/issues/175, I agree it should really be fixed.

fangfufu avatar Dec 07 '24 06:12 fangfufu

Sorry, I am just really busy with my personal life. I will get this sorted when I have some time.

fangfufu avatar Dec 17 '24 13:12 fangfufu

Hi @fangfufu, no worries! I'm still here to help with debugging if needed. I'm currently testing without the cache, and it's working fine. That said, performance is noticeably better with the cache. I assume fetching content in slices makes a big difference. Talk to you soon!

trixprod avatar Dec 26 '24 17:12 trixprod

Thanks @trixprod ! I am currently just celebrating Christmas with friends. I hope you are having a good celebration too. :) I will get back to you probably in early January.

fangfufu avatar Dec 26 '24 17:12 fangfufu

Hi @trixprod, I just want to say, this issue is still on my todo list. It is not exactly easy to solve. I need some more time to think about it. It is definitely an issue, however it seems that not many people are reporting this.

fangfufu avatar Aug 11 '25 13:08 fangfufu

@trixprod , I think I might have fixed it, let me know what you think!

fangfufu avatar Aug 11 '25 18:08 fangfufu

Hello @fangfufu, great to hear from you! I can’t reply in detail right now, but I’ve taken note of the update and will test it before the end of the month. Thanks !

trixprod avatar Aug 12 '25 18:08 trixprod