curl and libcurl

Ok, I'm now closing this entry as fixed.

The next release is planned for January 2010, but it might slip a bit
since we have a rather large set of stuff to work on for that release but
we'll have to see how everything goes. For further questions or so around
that, please use the curl-library mailing list!

awesome. when is the next release likely?

Thanks a lot. I tracked it down, fixed it, added a new test case for this
(1106) and committed the lot just now to CVS (with credit to you for the
discovery and report). Case closed!

Whoa, very nice catch. I believe that may also be why the test cases never
glitched since they all just use -x/--proxy and not the environment
variable approach.

Ok, so I'll just have to figure out how this happens...

I think we have a winner.
I tried the following, after *unsetting* *all* proxy environment
variables:

curl -x 192.168.1.1:3128 ftp://ftp.suse.com/

and it worked

So did the following variations:

curl -x http://192.168.1.1:3128 ftp://ftp.suse.com/
curl -x http://192.168.1.1:3128/ ftp://ftp.suse.com/

but this did not:

env ftp_proxy=http://192.168.1.1:3128/ curl ftp://ftp.suse.com/
and neither did this:
env ftp_proxy=192.168.1.1:3128 curl ftp://ftp.suse.com/

So it would seem as though the proxy stuff as it comes from the
environment is busted.

I'm using Apache with its proxy_ftp enabled, eglibc 2.10.2, Linux 2.6.31 on
i686 32bit

I invoke curl with

curl -x localhost:80 ftp://ftp.sunet.se/

As long as it picks up the proxy, it really doesn't matter if it's done
with -x or an environment variable.

What proxy did you go through? I am using squid.

The recv/recvfrom is expected - this is going to vary a bit depending on
what kernel and glibc one is using (if one is using Linux). I am on glibc
2.10.1, kernel 2.6.31.5, x86_64. The working version I have (7.19.4) shows
recvfrom and sendto.

How did you invoke it, exactly? What was the exact commandline and what
proxy environment variables were present? (env | grep -i proxy)

Also, my strace outputs show NO calls to recvfrom() at all. TCP data is
clearly received with recv(). The particular piece from connect() to the
first write() looks like this:

connect(3, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in
progress)
clock_gettime(CLOCK_MONOTONIC, {434720, 492568076}) = 0
poll([{fd=3, events=POLLOUT}], 1, 299997) = 1 ([{fd=3, revents=POLLOUT}])
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
clock_gettime(CLOCK_MONOTONIC, {434720, 492678711}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "connected\n", 10connected
) = 10
clock_gettime(CLOCK_MONOTONIC, {434720, 492808025}) = 0
clock_gettime(CLOCK_MONOTONIC, {434720, 492840544}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "*", 1*) = 1
write(2, " ", 1 ) = 1
write(2, "Connected to localhost (127.0.0."..., 48Connected to localhost
(127.0.0.1) port 80 (#0)
) = 48
clock_gettime(CLOCK_MONOTONIC, {434720, 493056415}) = 0
clock_gettime(CLOCK_MONOTONIC, {434720, 493086293}) = 0
clock_gettime(CLOCK_MONOTONIC, {434720, 493115332}) = 0
send(3, "GET ftp://ftp.sunet.se HTTP/1.1\r"..., 215, MSG_NOSIGNAL) = 215
clock_gettime(CLOCK_MONOTONIC, {434720, 493816701}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, ">", 1>) = 1
write(2, " ", 1 ) = 1
write(2, "GET ftp://ftp.sunet.se HTTP/1.1\r"..., 33GET ftp://ftp.sunet.se
HTTP/1.1
) = 33

Just FYI, I can do ftp over proxy just fine. I just tested 7.19.7 and my
dev 7.20.0 version over a locally installed proxy. It's clearly not as
simple as working vs not working. This also explains why all test cases
still run fine: there's a subtle difference somewhere...

I tried 7.19.5 and 7.19.4.
7.19.5 did *not* work, 7.19.4, however, works fine.
Somewhere between 7.19.4 and 7.19.5....

7.19.7 does not fix for me.
I'll work backwards in versions.

Any chance you can just run a quick test with 7.19.7 too, just to make sure
it still shows the same badness?

In my end I'll work on getting some actual proxy up that proxies ftp like
this so I can make some tests.

One thing to note: I tried an older version (curl 7.19.0) on openSUSE 11.1
and it works just fine in exactly the same scenario.

The strace looks fine, too:

connect followed by poll, getsockopt, sendto (this part is missing above),
a few more polls and then it begins receiving the data.

recv frequently gets turned into recvfrom by the C library.

Look at the timestamps. The recv[from] returning 0 is perfectly
reasonable: the proxy accepted a request, waited 30 seconds, never got a
request, and closed the connection.

The core of the problem is still this: curl isn't ever asking the proxy
for anything. it connects, and then waits for a response. it won't get one.
ever. it's not asked for anything.

I'm invoking curl like this:

curl --trace-ascii - --trace-time
ftp://ftp.suse.com/pub/projects/kernel/kotd/openSUSE-11.2/x86_64/kernel-desktop-base-2.6.31.7-0.0.0.8.a22d080.x86_64.rpm

the environment looks like this:

frank:~ # env | grep -i prox
http_proxy=http://192.168.1.1:3128/
ftp_proxy=http://192.168.1.1:3128/
https_proxy=http://192.168.1.1:3128/
frank:~ #


remember: wget works perfectly in the same environment. so does aria2.

wget is doing what one would expect:
connect to the proxy
write a request.
read response

Here is the wget strace:

socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(3128),
sin_addr=inet_addr("192.168.1.1")}, 16) = 0
write(2, "connected.\n", 11) = 11
select(4, NULL, [3], NULL, {900, 0}) = 1 (out [3], left {899, 999996})
write(3, "GET ftp://ftp.suse.com/pub/proje"..., 195) = 195
write(2, "Proxy request sent, awaiting res"..., 41) = 41
....

I disagree with your conclusion.

First, I assume that libcurl's use of recv() somehow gets translated into
a recvfrom() (which in my book is strange in itself but lets ignore that
for now). But if that recvfrom() returns 0 after having poll() told the
socket is readable, that's an end of the connection. Let me quote the man
page: "The return value will be 0 when the peer has performed an orderly
shutdown.". So the question is then why the other end end closes down the
connection that fast.

Second, what makes me very curious is the comment "FTP response reading
failed" (a "normal" ftp over HTTP proxy does no such thing as it no longer
does FTP then but is doing HTTP and then it never waits for FTP responses).
Are you by any chance doing "tunneling" through the proxy? Can you show us
a full command line that you use when you experience these problems.

The recvfrom:
10137 16:04:22.287387 recvfrom(3, "", 16384, 0, NULL, NULL) = 0 <0.000028>

is receiving from file descriptor no 3. fd 3 was created here:

10137 16:03:52.937144 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
<0.000020>

(clearly a TCP socket) and the subsequent statements clearly show it to be
the socket which curl is using to communicate with the proxy:

10137 16:03:52.937394 connect(3, {sa_family=AF_INET,
sin_port=htons(3128),
sin_addr=inet_addr("192.168.1.1")}, 16) = -1 EINPROGRESS (Operation now
in
progress) <0.000057>

--trace-ascii and --trace-time added:



18:21:57.436169 == Info: About to connect() to proxy 192.168.1.1 port 3128
(#0)
18:21:57.437620 == Info: Trying 192.168.1.1... 18:21:57.439207 == Info:
connected
18:21:57.439770 == Info: Connected to 192.168.1.1 (192.168.1.1) port 3128
(#0)

18:22:26.845603 == Info: FTP response reading failed
18:22:26.845939 == Info: Closing connection #0
curl: (56) FTP response reading failed


The strace is pretty clear to me that curl (or libcurl) is simply waiting
for a response that will never come. The response will never come because
it never asks for anything!

recvfrom() ?? Is that from the DNS resolve? It doesnät make sense to me.

Can you run curl with --trace-ascii and get a dump of that to show us?

We run ftp over http proxy in our test suite (in several test cases even),
which runs fine on every release before we ship it and it still runs fine
in our current dev version.