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

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

I'm still getting problems with the latest code (commit fe2b2a3b9dbe18883cf7c9789cd958915978dc3a).

The project showing the problem is open source, Xcode based, with a SenTest style unit test illustrating the problem. I'm happy to share it if you want (let me know).

I'm not sure how feasible it would be to massage this into your standard test format since there's a fair bit of Objective-c wrapping around the libcurl code (which is the whole point).

The two problems I'm seeing are…

1)

I'm getting the crash that I described previously, where an incorrect nmemb value is coming through to the callback from Curl_pp_readresp:

#4 0x00000001007c9d0e in -[CURLHandle curlReceiveDataFrom:size:number:isHeader:] at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/CURLHandle.m:677
#5 0x00000001007c91c0 in curlHeaderFunction at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/CURLHandle.m:1074
#6 0x0000000102c0b228 in Curl_client_write at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/sendf.c:476
#7 0x0000000102c35d9f in Curl_pp_readresp at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/pingpong.c:393
#8 0x0000000102c0caee in ftp_readresp at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/ftp.c:627
#9 0x0000000102c0ca56 in Curl_GetFTPResponse at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/ftp.c:759
#10 0x0000000102c0c2b0 in ftp_sendquote [inlined] at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/ftp.c:3530
#11 0x0000000102c0c25a in ftp_done at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/ftp.c:3485
#12 0x0000000102c1731a in Curl_done at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/url.c:5234
#13 0x0000000102c24a39 in multi_runsingle at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/multi.c:1563
#14 0x0000000102c25a00 in multi_socket at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/multi.c:2178
#15 0x0000000102c25a92 in curl_multi_socket_action at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/build/curl-x86_64/lib/multi.c:2258
#16 0x00000001007cd70f in -[CURLMulti multiProcessAction:forSocket:] at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/CURLMulti.m:284
#17 0x00000001007ce64b in __24-[CURLMulti createTimer]_block_invoke at /Volumes/titan/Users/sam/Work/clients/karelia/ConnectionKit/CurlHandle/CURLHandleSource/CURLMulti.m:436

2)

The "stall" that I mentioned is also still happening.

It's not a deadlock situation as such, so there's no meaningful stack trace I can give you, but what seems to happen is that the timeout function that I set up to service the multi keeps ticking, but nothing actually happens to the easy handle. It's not clear to me why at this point.

The test performs a series of uploads of the same file, to the same server, one after another. For each upload the test sets it going, then loops on the current run loop until a flag is set. It relies on success/failure information coming through via the callbacks to set this flag.

The first upload succeeds, but the second one doesn't seem to complete - the flag isn't set, and so we end up stuck in the code that's pumping the run loop.

(apologies if some of this OS X terminology doesn't make any sense, but you can probably guess roughly what I'm referring to).

Here's some log, starting at the point where the first upload has succeeded. CURLHandle and CURLMulti are my objective C wrappers for easy and multi handles.

One thing that's a bit weird is that at the point that we get stuck, curl_multi_socket_action seems to return a running count of 1, then of 0, then of 1, and so on...

2013-02-13 15:14:08.362 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: DEBUG - We are completely uploaded and fine
2013-02-13 15:14:08.363 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: DEBUG - STATE: PERFORM => DONE handle 0x10030c750; line 1533 (connection #21)
2013-02-13 15:14:08.366 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: DEBUG - Remembering we are in dir "CURLHandleTests/"
2013-02-13 15:14:08.372 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: HEADER_IN - 226 Transfer complete.
2013-02-13 15:14:08.374 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: write 24 at 0x10087f490
2013-02-13 15:14:08.375 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: DEBUG - Connection #21 to host 10.0.1.32 left intact
2013-02-13 15:14:08.375 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: writer source removed for socket 13
2013-02-13 15:14:08.377 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: updated socket:<13>
2013-02-13 15:14:08.378 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: removed socket:<13>
2013-02-13 15:14:08.379 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: 0 handles reported as running
2013-02-13 15:14:08.381 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: got done msg result 0
2013-02-13 15:14:08.382 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: removed handle <CURLHandle 0x1001400b0 (easy 0x10087ec00)>
2013-02-13 15:14:08.383 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: DEBUG - Expire cleared
2013-02-13 15:14:08.383 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x1001400b0 (easy 0x10087ec00)>>: timeout changed to 1000ms
2013-02-13 15:14:08.385 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: completed with code 0
2013-02-13 15:14:08.387 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: finished
2013-02-13 15:14:08.388 otest[32724:1803] test: handle <CURLHandle 0x1001400b0 (easy 0x10087ec00)> finished
2013-02-13 15:14:08.389 otest[32724:1803] test: pause requested
2013-02-13 15:14:08.390 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x10087ec00)>: cleanup
2013-02-13 15:14:08.390 otest[32724:303] test: paused
2013-02-13 15:14:08.391 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x0)>: cleanup
2013-02-13 15:14:08.392 otest[32724:1803] <CURLHandle 0x1001400b0 (easy 0x0)>: dealloced
2013-02-13 15:14:08.393 otest[32724:1803] <CURLMulti 0x100127c40>: reader source cancel handler fired for socket 10
2013-02-13 15:14:08.394 otest[32724:1803] <CURLMulti 0x100127c40>: writer source cancel handler fired for socket 13
2013-02-13 15:14:08.395 otest[32724:1803] <CURLMulti 0x100127c40>: timer fired
2013-02-13 15:14:08.396 otest[32724:1803] <CURLMulti 0x100127c40>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:08.397 otest[32724:1803] <CURLMulti 0x100127c40>: 0 handles reported as running
2013-02-13 15:14:08.399 otest[32724:2d0b] <CURLMulti 0x100127c40>: timeout changed to 1ms
2013-02-13 15:14:08.399 otest[32724:2d0b] <CURLMulti 0x100127c40>: added handle <CURLHandle 0x101e32220 (easy 0x1010a0000)>
2013-02-13 15:14:08.400 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:08.401 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:08.403 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Found bundle for host 10.0.1.32: 0x104330140
2013-02-13 15:14:08.404 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Re-using existing connection! (#21) with host 10.0.1.32
2013-02-13 15:14:08.404 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Connected to 10.0.1.32 (10.0.1.32) port 21 (#21)
2013-02-13 15:14:08.405 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - 0x1010a0000 is at send pipe head!
2013-02-13 15:14:08.407 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - STATE: CONNECT => DO handle 0x10433f810; line 1025 (connection #21)
2013-02-13 15:14:08.408 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Request has same path as previous transfer
2013-02-13 15:14:08.409 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - DO phase starts
2013-02-13 15:14:08.410 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: HEADER_OUT - PASV
2013-02-13 15:14:08.412 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 1365) state change from STOP to PASV
2013-02-13 15:14:08.412 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Connect data stream passively
2013-02-13 15:14:08.413 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: HEADER_IN - 227 Entering Passive Mode (10,0,1,32,252,62)
2013-02-13 15:14:08.413 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: write 46 at 0x1010a0890
2013-02-13 15:14:08.414 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Trying 10.0.1.32...
2013-02-13 15:14:08.415 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - Connecting to 10.0.1.32 (10.0.1.32) port 64574
2013-02-13 15:14:08.415 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 2083) state change from PASV to STOP
2013-02-13 15:14:08.416 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - DO phase is complete1
2013-02-13 15:14:08.435 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 3574) state change from STOP to STOR_TYPE
2013-02-13 15:14:08.438 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: HEADER_OUT - STOR Upload.txt
2013-02-13 15:14:08.439 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 1696) state change from STOR_TYPE to STOR
2013-02-13 15:14:08.440 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: HEADER_IN - 150 Opening BINARY mode data connection for 'Upload.txt'.
2013-02-13 15:14:08.441 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: write 59 at 0x1010a0890
2013-02-13 15:14:08.442 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 533) state change from STOR to STOP
2013-02-13 15:14:08.443 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - STATE: DO => DO_MORE handle 0x10433f810; line 1231 (connection #21)
2013-02-13 15:14:08.444 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: new socket:<13>
2013-02-13 15:14:08.447 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: reader source added for socket 13
2013-02-13 15:14:08.448 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: updated socket:<13 reading>
2013-02-13 15:14:08.450 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 3574) state change from STOP to STOR_TYPE
2013-02-13 15:14:08.451 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: HEADER_OUT - STOR Upload.txt
2013-02-13 15:14:08.452 otest[32724:1803] <CURLHandle 0x101e32220 (easy 0x1010a0000)>: DEBUG - FTP 0x102803b18 (line 1696) state change from STOR_TYPE to STOR
2013-02-13 15:14:08.453 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: new socket:<10>
2013-02-13 15:14:08.453 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: reader source added for socket 10
2013-02-13 15:14:08.454 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: updated socket:<10 reading>
2013-02-13 15:14:08.457 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: reader source removed for socket 13
2013-02-13 15:14:08.457 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: updated socket:<13>
2013-02-13 15:14:08.459 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: removed socket:<13>
2013-02-13 15:14:08.459 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timeout changed to 1000ms
2013-02-13 15:14:08.461 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
2013-02-13 15:14:08.462 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: reader source cancel handler fired for socket 13
2013-02-13 15:14:08.464 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:08.464 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:08.465 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
2013-02-13 15:14:08.866 otest[32724:1803] <CURLMulti 0x100305260>: timer fired
2013-02-13 15:14:08.867 otest[32724:1803] <CURLMulti 0x100305260>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:08.867 otest[32724:1803] <CURLMulti 0x100305260>: 0 handles reported as running
2013-02-13 15:14:09.460 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:09.461 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:09.462 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
2013-02-13 15:14:09.865 otest[32724:1803] <CURLMulti 0x100305260>: timer fired
2013-02-13 15:14:09.866 otest[32724:1803] <CURLMulti 0x100305260>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:09.867 otest[32724:1803] <CURLMulti 0x100305260>: 0 handles reported as running
2013-02-13 15:14:10.460 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:10.461 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:10.462 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
2013-02-13 15:14:10.865 otest[32724:1803] <CURLMulti 0x100305260>: timer fired
2013-02-13 15:14:10.866 otest[32724:1803] <CURLMulti 0x100305260>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:10.867 otest[32724:1803] <CURLMulti 0x100305260>: 0 handles reported as running
2013-02-13 15:14:11.460 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:11.461 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:11.462 otest[32724:1803] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
2013-02-13 15:14:11.866 otest[32724:2d0b] <CURLMulti 0x100305260>: timer fired
2013-02-13 15:14:11.867 otest[32724:2d0b] <CURLMulti 0x100305260>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:11.867 otest[32724:2d0b] <CURLMulti 0x100305260>: 0 handles reported as running
2013-02-13 15:14:12.461 otest[32724:2d0b] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:12.462 otest[32724:2d0b] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:12.482 otest[32724:2d0b] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
2013-02-13 15:14:12.866 otest[32724:2d0b] <CURLMulti 0x100305260>: timer fired
2013-02-13 15:14:12.868 otest[32724:2d0b] <CURLMulti 0x100305260>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:12.868 otest[32724:2d0b] <CURLMulti 0x100305260>: 0 handles reported as running
2013-02-13 15:14:13.460 otest[32724:2d0b] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: timer fired
2013-02-13 15:14:13.461 otest[32724:2d0b] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: processing for socket 0 action CURL_SOCKET_TIMEOUT
2013-02-13 15:14:13.462 otest[32724:2d0b] <CURLMulti 0x100127c40 managing <CURLHandle 0x101e32220 (easy 0x1010a0000)>>: 1 handles reported as running
(lldb)

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