speed-limit not working with hanging ftp connection

[manfredsc]

This is related to http://sourceforge.net/p/curl/bugs/856/ resp. the known bug 73.

When an ftp connection is not fully set up and is hanging (no high port number negotiated,
communication is still going on (or not) on port 21), curl nevertheless decides that
connection phase is finished and therefore not connect-timeout, but max-time applies.
So far so good. But speed-limit is not working, too.

As I have to transfer huge files, I have to set large values for max-time, so it would be great
to be able to catch hanging connections be setting --speed-limit, but this does not work.

[bagder]

So can you tell us exactly what the last thing curl did when it "hung" in such a state?

[manfredsc]

Not exactly, unfortunately.
Such hangs do happen only rarely for me, in case of an overloaded ftp server. If you can tell
me how exactly I should enable curl to catch such a case, I can try and wait for such an event.

I do downloads the following way:

# curl -q -4 --disable-epsv --connect-timeout 20 --fail -s -S --max-time 1200 \
    --speed-limit 150000 --speed-time 30 \
    -w 'Status-Code %{http_code}. Speed %{speed_download} bytes/s (%{size_download} bytes / %{time_namelookup} : %{time_connect} : %{time_pretransfer} : %{time_starttransfer} : %{time_total} seconds). Server %{remote_ip}:%{remote_port}\n' $URL

In case of a hanging session, I see the following in the logs (notice that the max. 1200s are mostly not reached, I get normally aborts after 600-800s):

Status-Code 000. Speed 0.000 bytes/s (0 bytes / 0.001 : 0.150 : 0.000 : 0.000 : 627.659 seconds). Server xxx.xxx.xxx.xxx:21

whereas in the working case I get:

Status-Code 226. Speed 1523487.000 bytes/s (217660721 bytes / 0.001 : 0.097 : 1.188 : 1.188 : 142.870 seconds). Server xxx.xxx.xxx.xxx:18056

Hope this helps a bit, thanks,
Manfred

[manfredsc]

If you want me to instrument curl in some way, you have to tell me what to do.
The affected ftp server will be put out of order somewhen in August, so I will not be
able to reproduce these issues after this date.

FWIW, I do see cases where the connect timeout is effective, but only in a minority of cases.
The status code is varying though:

Status-Code 000. Speed 0.000 bytes/s (0 bytes / 0.001 : 5.056 : 0.000 : 0.000 : 19.070 seconds). Server xxx.xxx.xxx.xxx:21
Status-Code 227. Speed 0.000 bytes/s (0 bytes / 0.001 : 0.290 : 0.000 : 0.000 : 19.287 seconds). Server xxx.xxx.xxx.xxx:21
Status-Code 331. Speed 0.000 bytes/s (0 bytes / 0.001 : 0.271 : 0.000 : 0.000 : 19.082 seconds). Server xxx.xxx.xxx.xxx:21

I even got a case where the high port number was negotiated and max-time was effective:

Status-Code 000. Speed 0.000 bytes/s (0 bytes / 0.001 : 0.097 : 0.000 : 0.000 : 1182.468 seconds). Server xxx.xxx.xxx.xxx:31410

So the whole behavior seems not to be really deterministic.

Oh, and I determined the server software, using the "rstatus" command:
It's "vsFTPd 2.2.2"

[manfredsc]

I eventually caught 2 other cases, having enabled "-v" in curl. One has a "regular" connection
timeout (exit code 28), but only after 105 seconds instead of 20, and the other exits with
status 56 after 554 seconds.

*   Trying xxx.xxx.xxx.xxx...
* Connected to yyy.yyy.yyy.yyy (xxx.xxx.xxx.xxx) port 21 (#0)
< 220
> USER anonymous
< 331 Please specify the password.
> PASS myname@mydomain
< 230 Login successful.
> PWD
< 257 "/"
* Entry path is '/'
> PASV
* Connect data stream passively
* ftp_perform ends with SECONDARY: 0
< 227 Entering Passive Mode (xxx,xxx,xxx,xxx,43,79).
* Connection time-out
* Closing connection 0
curl: (28) Connection time-out
Status-Code 227. Speed 0.000 bytes/s (0 bytes / 0.001 : 3.292 : 0.000 : 0.000 : 105.090 seconds). Server xxx.xxx.xxx.xxx:21



*   Trying xxx.xxx.xxx.xxx...
* Connected to yyy.yyy.yyy.yyy (xxx.xxx.xxx.xxx) port 21 (#0)
< 220
> USER anonymous
< 331 Please specify the password.
> PASS myname@mydomain
< 230 Login successful.
> PWD
< 257 "/"
* Entry path is '/'
> PASV
* Connect data stream passively
* ftp_perform ends with SECONDARY: 0
* Recv failure: Connection timed out
* Closing connection 0
curl: (56) Recv failure: Connection timed out
Status-Code 000. Speed 0.000 bytes/s (0 bytes / 0.001 : 1.284 : 0.000 : 0.000 : 554.577 seconds). Server xxx.xxx.xxx.xxx:21

[bagder]

The speed check isn't actually done until the transfer starts so until it reaches the transfer state, that won't trigger. And if it is passed the "connection phase", max-time is what sets the maximum time to spend.

There are some additional timeouts by the system and elsewhere that can make it give up earlier than so.

[manfredsc]

I very much suspected this being the case. But you asked for more information...

[manfredsc]

Contrary to the initial announcement, the affected server will not be decommissioned. I still can
reproduce this issue occasionally and would be glad for a solution therefore.
"The speed check isn't actually done until the transfer starts" : Couldn't this be changed to
arm the timer at the moment of successful connection?

[bagder]

The speed limit feature is meant to make sure the data transfer maintains a certain speed, so it would change behavior and be counter-intuitive (IMO) to start the timer even before the transfer has started as then it doesn't measure the data transfer at all, it is just another way to add a timeout for the pre-transfer operations.