Cache_free: could not destroy w_lock!

[trixprod]

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]

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

[fangfufu]

Possibly related to:
#91
#126

This is going to a fun one...

[trixprod]

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]

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]

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]

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]

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]

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]

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!