[libcurl] Returning from a write callback with error does not immediately return from curl_easy_perform

[Bylon2]

The bug does NOT occur on x86/amd64 version, but is visible on armV7 (Raspbian Buster 32 bits on Raspberry Pi 4)

I have a fuse driver using libcurl underneath : https://gitlab.com/BylonAkila/astreamfs/blob/master/1fichierfs.c

What it does is read chunks of file as instructed in background process (read-ahead stream optimised). When no read request arrives, the background processes are just sleeping inside the curl callback.
In the case a request arrives out of the currently opened streams, we pick a sleeping process, terminate the current curl operation (sending CURLE_WRITE_ERROR from the callback) and start a new curl_easy_perform with the new range.

What is expected:

So what can happen in the background:

• curl_easy_perform (range offset-end_of_file)
  -- callback read bytes and return them, when no more bytes are needed we sit in the callback
  -- wait for some time
  -- A new request arrives and we need to reuse that thread, so we send the new range to it (with semaphores), the callback then returns CURLE_WRITE_ERROR to terminate the current stream-read
• on x86, curl_easy_perform IMMEDIATELY terminates (with error 23 as expected) and returns to the caller. The caller will then start a new curl_easy_perform with the new range.

What happens instead

And that is specific to armhf 32 bits apparently, is that in spite of the callback returning CURLE_WRITE_ERROR, curl_easy_perform does not return immediately to its caller. The return delay to the caller, after curl_easy_perform receives the error code from the callback can be anything from zero to 3 minutes!

Versions

$ uname -a
Linux raspberrypi 4.19.75-v7l+ #1270 SMP Tue Sep 24 18:51:41 BST 2019 armv7l GNU/Linux

$ lsb_release -a
No LSB modules are available.
Distributor ID:	Raspbian
Description:	Raspbian GNU/Linux 10 (buster)
Release:	10
Codename:	buster

$ 1fichierfs -V
1fichierfs: version 1.5.0
libcurl/7.64.0 (arm-unknown-linux-gnueabihf) GnuTLS/3.6.7
FUSE library version: 2.9.9
fusermount version: 2.9.9
using FUSE kernel interface version 7.19

So the libcurl version is 7.64.0 with GnutTLS/3.6.7
(I need reentrance since it is mutlithreaded use)

TODO

I'll try to build a smaller program to demonstrate the bug, since it is impractical with this driver because you need a 1fichier.com subscription to use it.

In the mean time... if you have an idea where that comes from...

[bagder]

Before you manage to reproduce with an example, you can just put a break-point here:

curl/lib/sendf.c

Line 614 in a626fa1

failf(data, "Failed writing body (%zu != %zu)", wrote, chunklen);

And then A) issue a back trace and show that to us and B) single-step forward a bit to a pointer where you see it "forgetting" about the error code the callback returned.

[Bylon2]

Thanks for the tip, I'll try that... which means I'll have first to get the source (easy with apt) and find how to replace the library with the locally compiled and modified stuff!

Another test I'll do, is try the same thing without tls, in case the delay might be caused by curl trying to clean things with GnuTLS, and that cleaning taking some random time.

[jay]

#define STREAM_ERROR ((CURLcode)99) /* CURL errors stop at 90 */

at 94 now and will increase as more are added.

[Bylon2]

Thanks, I'll change that... is there a

#define CURLE_MAX_ERROR_CODE 94

... or the like, so that I set my own internal errors to a value not already used by curl?

[bagder]

CURL_LAST (weirdly enough it isn't CURLE_LAST which would've been logical) is the number above the highest used number in the header file you build with. It doesn't really say what the highest error code might be from your installed library though!

[jay]

I wouldn't mess with that it's a similar predicament. We could add a CURLE_USER_MASK 0x80000000 but personally I think that's just masking the smell (pun). Better to use your own error type.

[Bylon2]

Back to the bug at hand!..

More tests give me that:

• The "alleged bug" does NOT happen in plain http (no TLS)
• The "alleged bug" does NOT happen when linking my program with OpenSSL instead of GnuTLS

So I am assuming this is either:

• A bug with the current version of GnuTLS (3.6.7)
• libcurl not using correctly this version of GnuTLS

I used to link with GnuTLS library since I'm still running Ubuntu 16.04 on my desktop and laptop, and this version does not have the minimum OpenSSL 1.1 to be thread-safe. So OpenSSL was not an option with my heavily threaded(*) use case under Ubuntu 16.04

On the other hand, Raspbian Buster is more up to date and sports a 1.1.1d version of OpenSSL as shown:

$ ./1fichierfs -V
1fichierfs: version 1.5.0
libcurl/7.64.0 (arm-unknown-linux-gnueabihf) OpenSSL/1.1.1d
FUSE library version: 2.9.9
fusermount version: 2.9.9
using FUSE kernel interface version 7.19

So as far as this "alleged bug"(**) is concerned, since I have a perfectly fine workaround (using OpenSSL!), you can mark it as "low priority".

Unless it concerns others that really need GnuTLS on arm, this will have lesser priority in my /TODO list of things I still have to work on to properly finish configuring my Raspberry Pi 4!
For those using GnuTLS for the same reason I did, I hope this can help to "workaround" the issue!

==> Please can you mark as "Low Priority"

(*) "heavily threaded" (program at rest)

$ ps huH p 4225
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 
pi        4225  0.2  0.1  97776  5964 ?        Ssl  18:43   0:04 dev/astreamfs/1fichierfs 
pi        4225  0.3  0.1  97776  5964 ?        Ssl  18:43   0:05 dev/astreamfs/1fichierfs 
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 
pi        4225  0.0  0.1  97776  5964 ?        Ssl  18:43   0:00 dev/astreamfs/1fichierfs 

(**) "alleged" but it can be very easily reproduced with my program... if you have a 1fichier.com subscription!

Many thanks for your reactivity and quick responses!

[Bylon2]

Before you manage to reproduce with an example, you can just put a break-point here:

curl/lib/sendf.c

Line 614 in a626fa1

failf(data, "Failed writing body (%zu != %zu)", wrote, chunklen);

And then A) issue a back trace and show that to us and B) single-step forward a bit to a pointer where you see it "forgetting" about the error code the callback returned.

By the way, "putting a breakpoint" is somehow impractical in an heavily threaded program with several curl_easy_perform happening in the background. So what I would have to do in this case is to add some traces (printf like). A little more effort than a simple "break-point + trace" unfortunately.

For instance, wonderful tools such as nemiver are of no use at all, unless debugging the initialisation phase. Even if you make it work with a daemon (not sure it is possible!) that would so much disrupt the inter-thread timings that you could very well not observe some bugs.

[bagder]

If the problem is in curl, then a break-point would still be valuable no matter how many other threads run because they're not the ones we care about.

If the issue is indeed within GnuTLS, then a break-point won't help much. Then the question I have what is curl/GnuTLS doing all those minutes from the error is returned from the callback until you get the libcurl functions error code returned? Is it stuck in a function call? If so, which and why? If not, then I don't think it is GnuTLS' fault and where back on the first paragraph again...

[Bylon2]

@badger, in fact the program has (by default) 4 readers. When the bug occurs, all four readers have been used at least once (round robin), and we try to use an "idle" reader: more than 45 seconds with no requests, but the curl-callback is still active. The break-point would then be common for all readers and break each time a curl finishes on any reader. That is because of course the code is not duplicated for each thread. ;-)

It might help, but it will most probably disrupt the whole scheduling of threads and possibly make the bug vanish, because each time it breaks you would have to step-by-step in case it is "the bug"... which gives time for the faulty GnuTLS to finish his background stuff.

Another bigger issue (for me) is that I am not so comfortable with gdb... especially on a multi-thread daemon. Most probably also, to be able to break at breakpoints, gdb has to set its own locking that could disrupt many things! And it's easier counterpart (Nemiver) does probably not work in this case.

So the most realistic to debug is indeed adding some kind of "printf". That what I did actually on the current program: a "printf" just before returning from the callback, and another one just after the exit of curl_easy_perform. On my trace, I see that those "printf" are several second (up to several minutes) apart when the bug occurs.

A working case (when there is no bug) looks like that

[1fichierfs  6836.325] DEBUG: >> unfichier_read: 0x7f3e3c01ed30 (953487360,102400) rq[521]--------
[1fichierfs  6836.325] DEBUG: dump: readers[521*0] fs=0x7f3e3c01ed30 7110656:7127040 (idle=0) (n_rq=0)
[1fichierfs  6836.325] DEBUG: dump: readers[521|1] fs=0x7f3e3c01ed30 758022144:758038528 (idle=0) (n_rq=0)
[1fichierfs  6836.325] DEBUG: dump: readers[521|2] fs=0x7f3e3c01ed30 1750368256:1750384640 (idle=0) (n_rq=0)
[1fichierfs  6836.325] DEBUG: dump: readers[521|3] fs=0x7f3e3c01ed30 2663206912:2663223296 (idle=0) (n_rq=0)
[1fichierfs  6836.325] DEBUG: write_data[0] Dump: 0x7f3e417fa6b8->(nil)  953487360:0-102400
[1fichierfs  6836.337] DEBUG: curl_easy_perform exited with 23
[1fichierfs  6836.337] DEBUG: async_reader[0] range is 953356288-
[1fichierfs  6836.337] INFO: curling https://a-2.1fichier.com/p445931726 (URL=https://1fichier.com/?7b5qwm8bw5mhsj6eqr3t)

Which means:

• read at position 953,487,360 received from fuse.
• all threads have been used, the read process selects reader 0 that is not idle but has no pending request (best choice in round robin algo).
• write_data (the callback ) receives this order, but since reader 0 is at position 7,110,656, it is way off range, the callback then returns with an error to end the current curl_easy_perform.
• curl_easy_perform ends with error 23 (as expected)... which here took 12 milliseconds at the precision of the coarse clock that is 4ms (I call that "immediate"!)
• then the async reader (0 since we are reader 0) now issues a new curl_easy_perform in range with what is requested.

For debugging purpose I added a "trace" just before the return from the callback. This is not shown here because this is the "packaged" driver, but the trace shown that we indeed returned from the callback and had to wait several second to see the corresponding 'curl_easy_perform exited with 23'.
One could argue that the thread might have been suspended between curl_easy_perform and the "printf" that is just the next instruction, or between the "printf" in the callback and the return... but I frankly don't believe that in normal conditions a thread could be suspended seconds, even less minutes for such a kind of straightforward part of the program with no locks/semaphores!

[Bylon2]

I confirm gdb completely breaks the program, probably due to the locking it adds. Nevertheless I could try to provide a trace, just attaching it at the moment when the bug is visible... but for now fail to see any curl symbol.

Here is what I have so far (working case)

(gdb) bt
#0  futex_abstimed_wait_cancelable (private=0, abstime=0xb4e997f8, expected=1, futex_word=0x30788 <readers+48>) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  do_futex_wait (sem=sem@entry=0x30788 <readers+48>, abstime=abstime@entry=0xb4e997f8) at sem_waitcommon.c:115
#2  0xb6e1e5c4 in __new_sem_wait_slow (sem=0x30788 <readers+48>, abstime=0xb4e997f8) at sem_waitcommon.c:282
#3  0x00011ba8 in get_work ()
#4  0x00011cd4 in write_data ()
#5  0xb6e4d604 in ?? () from /usr/lib/arm-linux-gnueabihf/libcurl.so.4
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

So we correctly my own symbols: write_data (the curl-callback), but the trace says it is called from "??" in libcurl!

Is there a method to display more useful debugging symbols from the libcurl stack?

[EDIT] after some searching on the web, it seems that unlike Debian, Raspbian provides only "striped" packages with no debug symbol. So the alternative method seems to be: rebuild the package with "nostrip" option, so that we get symbols. I'll try that later!

[Bylon2]

I managed to get a backtrace using the documentation at this page: https://wiki.debian.org/HowToGetABacktrace

Unfortunately, even after rebuilding curl (which tool forever x 2!) with nostrip option, I still get a trace with NO libcurl symbols, same as the previous post.

So if someone has a valid pointer on how to get those libcurl symbols, I'll try again, otherwise I guess the bug will stay, sorry!

[bagder]

If you don't get the symbols then it sounds like you're not using your newly built version?

[Bylon2]

Yes I did to the limit of my skills that go as far as, after rebuilding:

sudo apt purge libcurl4-openssl-dev

To remove the version installed from the repo.
Did a "make" to see that it didn't link (since no other libcurl4-xxx-dev is installed)

Then did:
sudo dpkg -i /path/to/build-area/libcurl4-gnutls-dev

Compiled successfully, reproduced the bug (it is not systematic but easy to reproduce), and failed to get a relevant trace!

I have another try to do, the debian wiki page I linked recommends to build with:
DEB_BUILD_OPTIONS="nostrip noopt" apt -b source libcurl4-gnutls-dev

I saw on another page the you can add the undocumented debug option to the packaging.

Also I am wondering, and you might have the answer to that as "curl specialists".

When I issued the build command above, it did not only build libcurl4-gnutls-dev, but built all flavors of lib4curl4-xxx-dev, and also built curl itself.

My question would be, indeed the "dev" versions of the libraries are needed when one does a program requiring libcurl. Those versions bring for example the C headers (curl.h and others), the curl-config utility, etc...

But once the program has been dynamically linked, I assume it is not using the "-dev" libraries when it runs, othewise anyone wanting to run such program would have to install the "-dev" package (sure we can put a "Depends" on the .deb). So maybe the error is there. Building the "-dev" didn't rebuild the runtime libraries that are used once the program have been compiled.

Any advise on that?
What other package need I rebuild on top of libcurl4-gnutls-dev (which build much more in fact)!
Or maybe the build is enough (since it builds all!) but I also need to "dpkg -i curl" (didn't check if it has some dynamic libraries in its -contents)

So in short, put up a little document about "how to backtrace curl/libcurl on Linux" would be nice. Obviously a documentation for Debian can be adapted to Ubuntu (or conversely), and the ones using Fedora would easily convert apt to dnf!