Hi,

I hope you don't mind if I throw in my own results with the modified
ftp-multi-upload.c

I got a curl 7.19.2 debug build anyway, as well as a vsftpd 2.0.6
connected via local gbit.

Daniel Stenberg wrote:
> Using this version I too could reproduce some kind of hang (roughly on
> one attempt out of five or so) but it doesn't seem to be identical to
> your case. I only get it after 58 transfers and after a 221 (transfer
> complete) is received.

In most cases it works here, randomly it does not quit, hangs after the
last file,

example:
WE USE URL(58) ftp://192.168.53.25/incoming/curl/file59
* STATE: INIT => CONNECT handle 0x748f8b0; (connection #-5000)
* Re-using existing connection! (#1) with host 192.168.53.25
* Connected to 192.168.53.25 (192.168.53.25) port 21 (#1)
* STATE: CONNECT => DO handle 0x748f8b0; (connection #1)
* Request has same path as previous transfer
* DO phase starts
> PASV
* FTP 0x7450ee8 state change from STOP to PASV
* Connect data stream passively
< 227 Entering Passive Mode (192,168,53,25,74,126)
* Trying 192.168.53.25... * Connecting to 192.168.53.25
(192.168.53.25) port 19070
* FTP 0x7450ee8 state change from PASV to STOP
* DO phase is complete
* STATE: DO => DO_MORE handle 0x748f8b0; (connection #1)
* DO-MORE phase starts
* FTP 0x7450ee8 state change from STOP to STOR_TYPE
> STOR file59
* FTP 0x7450ee8 state change from STOR_TYPE to STOR
< 150 Ok to send data.
* FTP 0x7450ee8 state change from STOR to STOP
* DO-MORE phase ends with 0
* STATE: DO_MORE => DO_DONE handle 0x748f8b0; (connection #1)
* STATE: DO_DONE => WAITPERFORM handle 0x748f8b0; (connection #1)
* Conn 1 recv pipe 1 inuse 0 athead 1
* STATE: WAITPERFORM => PERFORM handle 0x748f8b0; (connection #1)
* STATE: PERFORM => DONE handle 0x748f8b0; (connection #1)
* Expire cleared
* Remembering we are in dir "incoming/curl/"
< 226 File receive OK.
* Connection #1 to host 192.168.53.25 left intact
* STATE: DONE => COMPLETED handle 0x748f8b0; (connection #-5000)

gdb told me it hangs in

#0 0x00007f77fe9c4433 in select () from /lib/libc.so.6
#1 0x00000000004014cc in main ()

Wireshark shows:

session #1
-------------------
...
230 Login successful.
PWD
257 "/"
CWD incoming
250 Directory successfully changed.
CWD curl
250 Directory successfully changed.
PASV
227 Entering Passive Mode (192,168,53,25,44,147)
TYPE I
200 Switching to Binary mode.
STOR file01
150 Ok to send data.
CWD /
-------------------

session #2
-------------------
...
230 Login successful.
PWD
257 "/"
CWD incoming
250 Directory successfully changed.
CWD curl
250 Directory successfully changed.
PASV
227 Entering Passive Mode (192,168,53,25,236,23)
TYPE I
200 Switching to Binary mode.
STOR file02
150 Ok to send data.
226 File receive OK.
PASV
227 Entering Passive Mode (192,168,53,25,51,37)
STOR file04
150 Ok to send data.
226 File receive OK.
PASV
....
STOR file57
150 Ok to send data.
226 File receive OK.
PASV
227 Entering Passive Mode (192,168,53,25,205,147)
STOR file58
150 Ok to send data.
226 File receive OK.
PASV
227 Entering Passive Mode (192,168,53,25,30,169)
STOR file59
150 Ok to send data.
226 File receive OK.
-------------------

summary:
session #1 got stalled, file03 was never uploaded,
session #2 worked.

Looking at the curl debug, we can see uploading file03 never started.

WE USE URL(2) ftp://192.168.53.25/incoming/curl/file03
* STATE: INIT => CONNECT handle 0xd824c8; (connection #-5000)
* STATE: PERFORM => DONE handle 0xd79858; (connection #0)
* Re-using existing connection! (#0) with host 192.168.53.25
* Connected to 192.168.53.25 (192.168.53.25) port 21 (#0)
* STATE: CONNECT => DO handle 0xd824c8; (connection #0)
* Expire cleared
* STATE: DONE => COMPLETED handle 0xd79858; (connection #-5000)
* DO phase starts
> CWD /
* FTP 0xd82fb8 state change from STOP to CWD
* STATE: DO => DOING handle 0xd824c8; (connection #0)

connection #0 does not reach STATE: DONE after sending file01

* FTP 0xd82fb8 state change from STOR to STOP
* DO-MORE phase ends with 0
* STATE: DO_MORE => DO_DONE handle 0xd79858; (connection #0)
* STATE: DO_DONE => WAITPERFORM handle 0xd824c8; (connection #1)
* STATE: DO_DONE => WAITPERFORM handle 0xd79858; (connection #0)
* Conn 1 recv pipe 1 inuse 0 athead 1
* STATE: WAITPERFORM => PERFORM handle 0xd824c8; (connection #1)
* Conn 0 recv pipe 1 inuse 0 athead 1
* STATE: WAITPERFORM => PERFORM handle 0xd79858; (connection #0)
* STATE: PERFORM => DONE handle 0xd824c8; (connection #1)
* Expire cleared
* Remembering we are in dir "incoming/curl/"
< 226 File receive OK.
* Connection #1 to host 192.168.53.25 left intact
* STATE: DONE => COMPLETED handle 0xd824c8; (connection #-5000)
WE USE URL(2) ftp://192.168.53.25/incoming/curl/file03
... you already saw the following crap above above ....

For working sessions, the "Expire cleared" is right after the state
changes for the connection:

e.g.:

* STATE: WAITPERFORM => PERFORM handle 0xaa5858; (connection #1)
* STATE: PERFORM => DONE handle 0xaa5858; (connection #1)
* Expire cleared

Therefore I expect the late "Expire cleared" to be related, a timing
issue, making it unreliable to reproduce.

If it works, wireshark sessions look like like one expects them to look
like.

> I'll need to experiment some more with a remote server (I only tried
> with one on localhost so far) and see if I can get it with less number
> of files transferred.

If it fails, it fails *early* (in most cases) here.

Early means connection #0, file03 with the same characteristics as
mentioned above.

Common to all fails is the late "Expire cleared".

Digging in the code, I found "Expire cleared" in lib/multi.c
Curl_expire(), I came across the same function trying to debug my
'loosing timeouts' for http in hiperfifo.c.

2 different plattforms, 2 different protocols, same bug?

MfG
Markus
Received on 2008-11-16