On 7 Feb 2013, at 23:07, Nick Zitzmann <nick_at_chronosnet.com> wrote:

> If you get any more stalls with the latest code, could you share a stack trace sample when the stall occurs, or (even better) a sample project that reproduces the problem? I've only noticed one stall recently that wasn't caused by the connection to the server, and it was due to an IPv6-related bug that was fixed last week.

A bit more followup on this one, fwiw:

Looking at the debug output from curl, there are some differences between the upload that works, and the one that gets stuck.

Here's the working one:

14:30:06.191 DEBUG - Connected to 10.0.1.32 (10.0.1.32) port 21 (#0)
14:30:06.191 DEBUG - FTP 0x102019d18 (line 3246) state change from STOP to WAIT220
14:30:06.192 DEBUG - STATE: WAITCONNECT => PROTOCONNECT handle 0x100330150; line 1145 (connection #0)
14:30:06.215 HEADER_IN - 220 10.0.1.32 FTP server (tnftpd 20100324+GSSAPI) ready.
14:30:06.217 HEADER_OUT - USER ftptest
14:30:06.218 DEBUG - FTP 0x102019d18 (line 845) state change from WAIT220 to USER
14:30:06.234 HEADER_IN - 331 User ftptest accepted, provide password.
14:30:06.235 HEADER_OUT - PASS ftptest
14:30:06.236 DEBUG - FTP 0x102019d18 (line 2630) state change from USER to PASS
14:30:06.259 HEADER_IN - 230 User ftptest logged in.
14:30:06.260 HEADER_OUT - PWD
14:30:06.260 DEBUG - FTP 0x102019d18 (line 857) state change from PASS to PWD
14:30:06.289 HEADER_IN - 257 "/Users/ftptest" is the current directory.
14:30:06.290 DEBUG - Entry path is '/Users/ftptest'
14:30:06.291 DEBUG - FTP 0x102019d18 (line 2938) state change from PWD to STOP
14:30:06.292 DEBUG - protocol connect phase DONE
14:30:06.292 DEBUG - STATE: PROTOCONNECT => DO handle 0x100330150; line 1164 (connection #0)
14:30:06.293 DEBUG - DO phase starts
14:30:06.293 HEADER_OUT - CWD CURLHandleTests
14:30:06.294 DEBUG - FTP 0x102019d18 (line 942) state change from STOP to CWD
14:30:06.312 HEADER_IN - 250 CWD command successful.
14:30:06.318 HEADER_OUT - PASV
14:30:06.318 DEBUG - FTP 0x102019d18 (line 1365) state change from CWD to PASV
14:30:06.319 DEBUG - Connect data stream passively
14:30:06.319 DEBUG - STATE: DO => DOING handle 0x100330150; line 1223 (connection #0)
14:30:06.358 HEADER_IN - 227 Entering Passive Mode (10,0,1,32,218,29)
14:30:06.360 DEBUG - Trying 10.0.1.32...
14:30:06.360 DEBUG - Connecting to 10.0.1.32 (10.0.1.32) port 55837
14:30:06.361 DEBUG - FTP 0x102019d18 (line 2083) state change from PASV to STOP
14:30:06.361 DEBUG - DO phase is complete2
14:30:06.425 DEBUG - STATE: DOING => DO_MORE handle 0x100330150; line 1310
14:30:06.430 HEADER_OUT - TYPE I
14:30:06.431 DEBUG - FTP 0x102019d18 (line 3579) state change from STOP to STOR_TYPE
14:30:06.432 HEADER_IN - 200 Type set to I.
14:32:16.014 HEADER_OUT - STOR Upload.txt
14:32:16.015 DEBUG - FTP 0x102019d18 (line 1696) state change from STOR_TYPE to STOR
14:32:16.018 HEADER_IN - 150 Opening BINARY mode data connection for 'Upload.txt'.
14:32:16.019 DEBUG - FTP 0x102019d18 (line 533) state change from STOR to STOP
14:32:16.022 DEBUG - STATE: DO_MORE => DO_DONE handle 0x100330150; line 1332
14:32:16.027 DEBUG - STATE: DO_DONE => WAITPERFORM handle 0x100330150; line
14:32:16.057 DEBUG - STATE: WAITPERFORM => PERFORM handle 0x100330150; line
14:32:16.064 DATA_OUT - *|*|* Some test content. Blah blah... *|*|*
14:32:16.065 DEBUG - We are completely uploaded and fine
14:32:16.065 DEBUG - STATE: PERFORM => DONE handle 0x100330150; line 1533
14:32:16.066 DEBUG - Remembering we are in dir "CURLHandleTests/"
14:32:16.068 HEADER_IN - 226 Transfer complete.

Here's the one that's getting stuck:

14:32:16.143 DEBUG - Found bundle for host 10.0.1.32: 0x1003301b0
14:32:16.144 DEBUG - Re-using existing connection! (#0) with host 10.0.1.32
14:32:16.145 DEBUG - Connected to 10.0.1.32 (10.0.1.32) port 21 (#0)
14:32:16.146 DEBUG - 0x1020e2000 is at send pipe head!
14:32:16.147 DEBUG - STATE: CONNECT => DO handle 0x1001c8020; line 1025 (connection #0)
14:32:16.148 DEBUG - Request has same path as previous transfer
14:32:16.149 DEBUG - DO phase starts
14:32:16.150 HEADER_OUT - PASV
14:32:16.151 DEBUG - FTP 0x102019d18 (line 1365) state change from STOP to PASV
14:32:16.152 DEBUG - Connect data stream passively
14:32:16.153 HEADER_IN - 227 Entering Passive Mode (10,0,1,32,218,41)
14:32:16.155 DEBUG - Trying 10.0.1.32...
14:32:16.156 DEBUG - Connecting to 10.0.1.32 (10.0.1.32) port 55849
14:32:16.157 DEBUG - FTP 0x102019d18 (line 2083) state change from PASV to STOP
14:32:16.158 DEBUG - DO phase is complete1
14:32:16.159 DEBUG - FTP 0x102019d18 (line 3574) state change from STOP to STOR_TYPE
14:32:16.159 HEADER_OUT - STOR Upload.txt
14:32:16.161 DEBUG - FTP 0x102019d18 (line 1696) state change from STOR_TYPE to STOR
14:32:16.162 HEADER_IN - 150 Opening BINARY mode data connection for 'Upload.txt'.
14:32:16.164 DEBUG - FTP 0x102019d18 (line 533) state change from STOR to STOP
14:32:16.165 DEBUG - STATE: DO => DO_MORE handle 0x1001c8020; line 1231 (connection #0)
14:32:16.168 DEBUG - FTP 0x102019d18 (line 3574) state change from STOP to STOR_TYPE
14:32:16.168 HEADER_OUT - STOR Upload.txt
14:32:16.169 DEBUG - FTP 0x102019d18 (line 1696) state change from STOR_TYPE to STOR

The obvious differences with the second connection that I can see:

- it reuses the connection
- it skips USER, PASS, PWD, CWD
- after getting back the PASV response, it ends up in DO phase complete1, rather than complete2
- if skips TYPE
- nothing more happens after the final STOR_TYPE to STOR

Not sure if any of that suggests anything to anyone…

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2013-02-14