Menu

#885 proxy and ftp - never issues request

closed-fixed
libcurl (356)
5
2014-08-18
2009-12-13
Jon Nelson
No

curl 7.19.6 on openSUSE 11.2, connecting via ftp through a squid proxy.

I noticed a problem attempting to fetch from an ftp resources that curl appeared to connect and then do nothing until it eventually timed out.
Suspecting some other problem, I tried aria2, wget, and firefox -- all of which worked just fine.

So I strace'd curl and this is what I get (the proxy is 192.168.1.1 port 3128):
...

10137 16:03:52.937144 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3 <0.000020>
10137 16:03:52.937229 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000015>
10137 16:03:52.937290 fcntl(3, F_GETFL) = 0x2 (flags O_RDWR) <0.000012>
10137 16:03:52.937340 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000011>
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>
10137 16:03:52.937516 poll([{fd=3, events=POLLOUT}], 1, 299999) = 1 ([{fd=3, revents=POLLOUT}]) <0.000879>
10137 16:03:52.938452 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 <0.000012>
10137 16:03:52.938516 poll([{fd=3, events=POLLIN|POLLPRI}], 1, 3600000) = 1 ([{fd=3, revents=POLLIN}]) <29.348688>
10137 16:04:22.287387 recvfrom(3, "", 16384, 0, NULL, NULL) = 0 <0.000028>
10137 16:04:22.287525 close(3) = 0 <0.000079>

followed by curl grumping (error 56).

What I don't understand is why, after the connect is successful, curl doesn't send the proxy anything.

Discussion

  • Daniel Stenberg

    Daniel Stenberg - 2009-12-13

    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.

     
  • Jon Nelson

    Jon Nelson - 2009-12-13

    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!

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-13

    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.

     
  • Jon Nelson

    Jon Nelson - 2009-12-13

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

     
  • Jon Nelson

    Jon Nelson - 2009-12-14

    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.

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14

    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.

     
  • Jon Nelson

    Jon Nelson - 2009-12-14

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

     
  • Jon Nelson

    Jon Nelson - 2009-12-14

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

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14

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

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14

    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

     
  • Jon Nelson

    Jon Nelson - 2009-12-14

    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)

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14

    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.

     
  • Jon Nelson

    Jon Nelson - 2009-12-14

    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.

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14

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

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14

    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!

     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-14
    • status: open --> pending-fixed
     
  • Jon Nelson

    Jon Nelson - 2009-12-15

    awesome. when is the next release likely?

     
  • Jon Nelson

    Jon Nelson - 2009-12-15
    • status: pending-fixed --> open-fixed
     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-15
    • status: open-fixed --> closed-fixed
     
  • Daniel Stenberg

    Daniel Stenberg - 2009-12-15

    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!