Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Cache_free: could not destroy w_lock! #174

Open
trixprod opened this issue Nov 21, 2024 · 23 comments
Open

Cache_free: could not destroy w_lock! #174

trixprod opened this issue Nov 21, 2024 · 23 comments
Labels
bug Something isn't working help wanted Extra attention is needed major Important issues

Comments

@trixprod
Copy link

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]
@fangfufu fangfufu added bug Something isn't working major Important issues labels Nov 22, 2024
@fangfufu
Copy link
Owner

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

@fangfufu fangfufu pinned this issue Nov 22, 2024
@fangfufu fangfufu added the help wanted Extra attention is needed label Nov 22, 2024
@fangfufu
Copy link
Owner

Possibly related to:
#91
#126

This is going to a fun one...

@trixprod
Copy link
Author

trixprod commented Nov 22, 2024 •
edited
Loading

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.

fangfufu added a commit that referenced this issue Nov 23, 2024
@fangfufu
Add debug message for Cache_free()
adac52c 
This is related to
#174
fangfufu added a commit that referenced this issue Nov 23, 2024
@fangfufu
Reorder the position of the error messages
3aaf5a2 
This is related to:
#174
@fangfufu
Copy link
Owner

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 3aaf5a2 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

@trixprod
Copy link
Author

trixprod commented Nov 24, 2024 •
edited
Loading

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]

@fangfufu
Copy link
Owner

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

@fangfufu
Copy link
Owner

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.

@trixprod
Copy link
Author

trixprod commented Nov 24, 2024 •
edited
Loading

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
Copy link
Author

trixprod commented Nov 24, 2024 •
edited
Loading

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!

@fangfufu
Copy link
Owner

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
Copy link
Owner

Hi, please try out 6cd006c. 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.

@trixprod
Copy link
Author

trixprod commented Nov 26, 2024 •
edited
Loading

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
Copy link
Author

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

@trixprod
Copy link
Author

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

@fangfufu
Copy link
Owner

fangfufu commented Dec 1, 2024 •
edited
Loading

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 eca4375, 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: #174 (comment). 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.

@trixprod
Copy link
Author

trixprod commented Dec 5, 2024

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]

@fangfufu
Copy link
Owner

fangfufu commented Dec 6, 2024

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
Copy link
Owner

fangfufu commented Dec 6, 2024 

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
Copy link
Owner

fangfufu commented Dec 6, 2024

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
Copy link
Owner

fangfufu commented Dec 6, 2024

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
Copy link
Owner

fangfufu commented Dec 6, 2024

Okay, please try this: 36b5b44

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.

@trixprod
Copy link
Author

trixprod commented Dec 6, 2024 •
edited
Loading

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]

@fangfufu
Copy link
Owner

fangfufu commented Dec 7, 2024

The first error is related to #175, I agree it should really be fixed.

@fangfufu fangfufu mentioned this issue Dec 7, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working help wanted Extra attention is needed major Important issues
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@fangfufu @trixprod