Starting with 02fbc26d5 (connect: Add connection delay to Happy Eyeballs)
the tests 19 and 704 have become unreliable on my FreeBSD system.

fk_at_r500 ~/git/curl/tests $./runtests.pl -a -n -p 19 19
********* System characteristics ********
* curl 7.34.0-DEV (amd64-unknown-freebsd11.0)
* libcurl/7.34.0-DEV OpenSSL/1.0.1e zlib/1.2.8 libidn/1.28
* Features: Debug TrackMemory IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP
* Host: r500.local
* System: FreeBSD r500.local 11.0-CURRENT FreeBSD 11.0-CURRENT #611 r258147+201c056(fk): Thu Nov 14 23:18:52 CET 2013 fk_at_r500.local:/usr/obj/usr/src/sys/ZOEY amd64
* Server SSL: ON libcurl SSL: ON
* debug build: ON track memory: ON
* valgrind: OFF HTTP IPv6 ON
* FTP IPv6 ON Libtool lib: OFF
* Shared build: no
* SSL library: OpenSSL
* Ports:
* HTTP/8990 FTP/8992 FTP2/8995 RTSP/9007 FTPS/8993 HTTPS/8991
* TFTP/8997 HTTP-IPv6/8994 RTSP-IPv6/9008 FTP-IPv6/8996
* GOPHER/9009 GOPHER-IPv6/9009
* SSH/8999 SOCKS/9000 POP3/9001 IMAP/9003 SMTP/9005
* POP3-IPv6/9002 IMAP-IPv6/9004 SMTP-IPv6/9006
* HTTPTLS/9011 HTTPTLS-IPv6/9012
* HTTP-PIPE/9014
*****************************************
test 019...[attempt connect to non-listening socket]

curl returned 28, when expecting 7
 exit FAILED
== Contents of files in the log/ dir after test 19
=== Start of file curl.log
 ../src/curl --output log/curl19.out --include --trace-ascii log/trace19 --trace-time 127.0.0.1:60000 >log/stdout19 2>log/stderr19
=== End of file curl.log
=== Start of file curlverout.log
 curl 7.34.0-DEV (amd64-unknown-freebsd11.0) libcurl/7.34.0-DEV OpenSSL/1.0.1e zlib/1.2.8 libidn/1.28
 Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smtp smtps telnet tftp
 Features: Debug TrackMemory IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP
=== End of file curlverout.log
=== Start of file stderr19
   % Total % Received % Xferd Average Speed Time Time Time Current
                                  Dload Upload Total Spent Left Speed
 
   0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
   0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
   0 0 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0
[...]
   0 0 0 0 0 0 0 0 --:--:-- 0:04:59 --:--:-- 0
   0 0 0 0 0 0 0 0 --:--:-- 0:05:00 --:--:-- 0
 curl: (28) Connection timed out after 300000 milliseconds
=== End of file stderr19
=== Start of file trace19
 18:14:15.099200 == Info: STATE: INIT => CONNECT handle 0x801c3f008; line 1010 (connection #-5000)
 18:14:15.100624 == Info: Rebuilt URL to: 127.0.0.1:60000/
 18:14:15.101177 == Info: Trying 127.0.0.1...
 18:14:15.101460 == Info: Immediate connect fail for 127.0.0.1: Connection refused
 18:14:15.101486 == Info: Adding handle: conn: 0x801ccc608
 18:14:15.101502 == Info: Adding handle: send: 0
 18:14:15.101517 == Info: Adding handle: recv: 0
 18:14:15.101547 == Info: Curl_addHandleToPipeline: length: 1
 18:14:15.101564 == Info: 0x801c3f008 is at send pipe head
 18:14:15.101605 == Info: - Conn 0 (0x801ccc608) send_pipe: 1, recv_pipe: 0
 18:14:15.101628 == Info: STATE: CONNECT => WAITCONNECT handle 0x801c3f008; line 1057 (connection #0)
 18:19:15.099326 == Info: Connection timed out after 300000 milliseconds
 18:19:15.100603 == Info: Closing connection 0
 18:19:15.100664 == Info: The cache now contains 0 members
=== End of file trace19
test 019...[attempt connect to non-listening socket]
------em-- OK (2 out of 2 , remaining: 00:00)
TESTDONE: 1 tests out of 2 reported OK: 50%
TESTFAIL: These test cases failed: 19
TESTDONE: 2 tests were considered during 300 seconds.

When the problem occurs, curl keeps spinning and truss shows:
[...]
getsockopt(0x6,0xffff,0x1007,0x7fffffffcb08,0x7fffffffcb04,0x801c01bc0) = 0 (0x0)
clock_gettime(4,{14439.927295421 }) = 0 (0x0)
clock_gettime(4,{14439.927346545 }) = 0 (0x0)
clock_gettime(4,{14439.927403186 }) = 0 (0x0)
poll({6/POLLOUT},1,1000) = 1 (0x1)
clock_gettime(4,{14439.927520171 }) = 0 (0x0)
clock_gettime(4,{14439.927581212 }) = 0 (0x0)
poll({6/POLLOUT},1,0) = 1 (0x1)
getsockopt(0x6,0xffff,0x1007,0x7fffffffcb08,0x7fffffffcb04,0x801c01bc0) = 0 (0x0)
clock_gettime(4,{14439.927749459 }) = 0 (0x0)
clock_gettime(4,{14439.927800234 }) = 0 (0x0)
clock_gettime(4,{14439.927856526 }) = 0 (0x0)
poll({6/POLLOUT},1,1000) = 1 (0x1)
clock_gettime(4,{14439.927972812 }) = 0 (0x0)
clock_gettime(4,{14439.928022958 }) = 0 (0x0)
poll({6/POLLOUT},1,0) = 1 (0x1)
getsockopt(0x6,0xffff,0x1007,0x7fffffffcb08,0x7fffffffcb04,0x801c01bc0) = 0 (0x0)
clock_gettime(4,{14439.928188202 }) = 0 (0x0)
clock_gettime(4,{14439.928238488 }) = 0 (0x0)
clock_gettime(4,{14439.928294152 }) = 0 (0x0)
poll({6/POLLOUT},1,1000) = 1 (0x1)
clock_gettime(4,{14439.928410228 }) = 0 (0x0)
clock_gettime(4,{14439.928502348 }) = 0 (0x0)
poll({6/POLLOUT},1,0) = 1 (0x1)
[...]

gdb shows that poll() is returning immediately with POLLHUP set,
but curl keeps poll()ing the fd anyway:

Breakpoint 1, Curl_poll (ufds=0x801c341e8, nfds=1, timeout_ms=1000) at select.c:398
398 if(r != -1)
(gdb) n
410 if(r < 0)
(gdb)
412 if(r == 0)
(gdb)
415 for(i = 0; i < nfds; i++) {
(gdb)
416 if(ufds[i].fd == CURL_SOCKET_BAD)
(gdb)
418 if(ufds[i].revents & POLLHUP)
(gdb)
419 ufds[i].revents |= POLLIN;
(gdb)
420 if(ufds[i].revents & POLLERR)
(gdb)
415 for(i = 0; i < nfds; i++) {
(gdb)
495 return r;
(gdb)
496 }

The attached patch gets the tests working reliably again.

Maybe poll() setting POLLHUP should still be handled differently, though?

Fabian

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html