Test 584 has recently become unreliable on FreeBSD: fk@r500 ~/git/curl/tests $./runtests.pl -a -p -n 584 584 584 584 584 584 ********* System characteristics ******** * curl 7.34.1-DEV (amd64-unknown-freebsd11.0) * libcurl/7.34.1-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 #627 r260861+5e50329(fk): Sat Jan 18 23:03:55 CET 2014 fk@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 Resolver: stock * 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 584...[HTTP GET using pipelining (nonzero length after zero length)] s--p--em-- OK (1 out of 6 , remaining: 00:12) test 584...[HTTP GET using pipelining (nonzero length after zero length)] s--p--em-- OK (2 out of 6 , remaining: 00:05) test 584...[HTTP GET using pipelining (nonzero length after zero length)] s--p--em-- OK (3 out of 6 , remaining: 00:02) test 584...[HTTP GET using pipelining (nonzero length after zero length)] s--p--em-- OK (4 out of 6 , remaining: 00:01) test 584...[HTTP GET using pipelining (nonzero length after zero length)] s--p--em-- OK (5 out of 6 , remaining: 00:00) test 584...[HTTP GET using pipelining (nonzero length after zero length)]
lib530 returned 125, when expecting 0 exit FAILED == Contents of files in the log/ dir after test 584 === Start of file http_server.log 14:14:18.614556 ====> Client connect 14:14:18.614691 TCP_NODELAY set 14:14:18.614750 accept_connection 3 returned 4 14:14:18.614798 accept_connection 3 returned 0 14:14:18.614954 Read 65 bytes 14:14:18.615058 Process 65 bytes request 14:14:18.615159 Got request: GET /path/5840001 HTTP/1.1 14:14:18.615245 Requested test number 584 part 1 14:14:18.615469 - request found to be complete 14:14:18.615618 Wrote request (65 bytes) input to log/server.input 14:14:18.615706 Send response test584 section <data1> 14:14:18.615928 Sent off 64 bytes 14:14:18.616026 Response sent (64 bytes) and written to log/server.response 14:14:18.616073 => persistant connection request ended, awaits new request 14:14:18.616129 ====> Client connect 14:14:18.616173 TCP_NODELAY set 14:14:18.616214 accept_connection 3 returned 6 14:14:18.616257 accept_connection 3 returned 0 14:14:18.616305 Read 65 bytes 14:14:18.616348 Process 65 bytes request 14:14:18.616395 Got request: GET /path/5840002 HTTP/1.1 14:14:18.616440 Requested test number 584 part 2 14:14:18.616552 - request found to be complete 14:14:18.616623 Wrote request (65 bytes) input to log/server.input 14:14:18.616691 Send response test584 section <data2> 14:14:18.616868 Sent off 16 bytes 14:14:18.616939 Response sent (16 bytes) and written to log/server.response 14:14:18.616985 => persistant connection request ended, awaits new request 14:14:18.617278 ====> Client connect 14:14:18.617377 TCP_NODELAY set 14:14:18.617460 accept_connection 3 returned 7 14:14:18.617543 accept_connection 3 returned 0 14:14:18.617664 Read 65 bytes 14:14:18.617749 Process 65 bytes request 14:14:18.617840 Got request: GET /path/5840003 HTTP/1.1 14:14:18.617925 Requested test number 584 part 3 14:14:18.618130 - request found to be complete 14:14:18.618196 Wrote request (65 bytes) input to log/server.input 14:14:18.618265 Send response test584 section <data3> 14:14:18.618439 Sent off 25 bytes 14:14:18.618510 Response sent (25 bytes) and written to log/server.response 14:14:18.618556 => persistant connection request ended, awaits new request 14:14:18.618621 ====> Client connect 14:14:18.618667 TCP_NODELAY set 14:14:18.618707 accept_connection 3 returned 8 14:14:18.618751 accept_connection 3 returned 0 14:14:18.618801 Read 65 bytes 14:14:18.618843 Process 65 bytes request 14:14:18.618892 Got request: GET /path/5840004 HTTP/1.1 14:14:18.618936 Requested test number 584 part 4 14:14:18.619040 - request found to be complete 14:14:18.619098 Wrote request (65 bytes) input to log/server.input 14:14:18.619164 Send response test584 section <data4> 14:14:18.619344 Sent off 148 bytes 14:14:18.619421 Response sent (148 bytes) and written to log/server.response 14:14:18.619470 => persistant connection request ended, awaits new request 14:15:18.937076 Connection closed by client 14:15:18.937577 ====> Client disconnect 0 14:15:18.937850 Connection closed by client 14:15:18.937975 ====> Client disconnect 0 14:15:18.938616 Connection closed by client 14:15:18.938739 ====> Client disconnect 0 14:15:18.939187 Connection closed by client 14:15:18.939335 ====> Client disconnect 0 === End of file http_server.log === Start of file server.input GET /path/5840001 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* GET /path/5840002 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* GET /path/5840003 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* GET /path/5840004 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* === End of file server.input === Start of file server.response HTTP/1.1 200 OK Server: test-server/fake Content-Length: 4 584 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 0 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 5 585 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 4 586 === End of file server.response === Start of file stderr584 URL: http://127.0.0.1:8990/path/584 Start at URL 0 * STATE: INIT => CONNECT handle 0x801cf0008; line 1020 (connection #-5000) * Hostname was NOT found in DNS cache * Trying 127.0.0.1... * STATE: CONNECT => WAITCONNECT handle 0x801cf0008; line 1067 (connection #0) * Connected to 127.0.0.1 (127.0.0.1) port 8990 (#0) * STATE: WAITCONNECT => WAITDO handle 0x801cf0008; line 1186 (connection #0) * WAITDO: Conn 0 send pipe 1 inuse FALSE athead TRUE * STATE: WAITDO => DO handle 0x801cf0008; line 1225 (connection #0) > GET /path/5840001 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* * STATE: DO => DO_DONE handle 0x801cf0008; line 1272 (connection #0) * STATE: DO_DONE => WAITPERFORM handle 0x801cf0008; line 1398 (connection #0) * STATE: WAITPERFORM => PERFORM handle 0x801cf0008; line 1411 (connection #0) * STATE: INIT => CONNECT handle 0x801cfc008; line 1020 (connection #-5000) * Found bundle for host 127.0.0.1: 0x801cbd288 * Server doesn't support pipelining * Hostname was found in DNS cache * Trying 127.0.0.1... * STATE: CONNECT => WAITCONNECT handle 0x801cfc008; line 1067 (connection #1) * Connected to 127.0.0.1 (127.0.0.1) port 8990 (#1) * STATE: WAITCONNECT => WAITDO handle 0x801cfc008; line 1186 (connection #1) * WAITDO: Conn 1 send pipe 1 inuse FALSE athead TRUE * STATE: WAITDO => DO handle 0x801cfc008; line 1225 (connection #1) > GET /path/5840002 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* * STATE: DO => DO_DONE handle 0x801cfc008; line 1272 (connection #1) * STATE: DO_DONE => WAITPERFORM handle 0x801cfc008; line 1398 (connection #1) * STATE: WAITPERFORM => PERFORM handle 0x801cfc008; line 1411 (connection #1) * STATE: INIT => CONNECT handle 0x801d08008; line 1020 (connection #-5000) * Found bundle for host 127.0.0.1: 0x801cbd288 * Server doesn't support pipelining * Hostname was found in DNS cache * Trying 127.0.0.1... * STATE: CONNECT => WAITCONNECT handle 0x801d08008; line 1067 (connection #2) * Connected to 127.0.0.1 (127.0.0.1) port 8990 (#2) * STATE: WAITCONNECT => WAITDO handle 0x801d08008; line 1186 (connection #2) * WAITDO: Conn 2 send pipe 1 inuse FALSE athead TRUE * STATE: WAITDO => DO handle 0x801d08008; line 1225 (connection #2) > GET /path/5840003 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* * STATE: DO => DO_DONE handle 0x801d08008; line 1272 (connection #2) * STATE: DO_DONE => WAITPERFORM handle 0x801d08008; line 1398 (connection #2) * STATE: WAITPERFORM => PERFORM handle 0x801d08008; line 1411 (connection #2) * STATE: INIT => CONNECT handle 0x801d14008; line 1020 (connection #-5000) * Found bundle for host 127.0.0.1: 0x801cbd288 * Server doesn't support pipelining * Hostname was found in DNS cache * Trying 127.0.0.1... * STATE: CONNECT => WAITCONNECT handle 0x801d14008; line 1067 (connection #3) * Connected to 127.0.0.1 (127.0.0.1) port 8990 (#3) * STATE: WAITCONNECT => WAITDO handle 0x801d14008; line 1186 (connection #3) * WAITDO: Conn 3 send pipe 1 inuse FALSE athead TRUE * STATE: WAITDO => DO handle 0x801d14008; line 1225 (connection #3) > GET /path/5840004 HTTP/1.1 Host: 127.0.0.1:8990 Accept: */* * STATE: DO => DO_DONE handle 0x801d14008; line 1272 (connection #3) * STATE: DO_DONE => WAITPERFORM handle 0x801d14008; line 1398 (connection #3) * STATE: WAITPERFORM => PERFORM handle 0x801d14008; line 1411 (connection #3) * HTTP 1.1 or later with persistent connection, pipelining supported < HTTP/1.1 200 OK * Server test-server/fake is not blacklisted < Server: test-server/fake < Content-Length: 4 < * STATE: PERFORM => DONE handle 0x801cf0008; line 1581 (connection #0) * Connection #0 to host 127.0.0.1 left intact * HTTP 1.1 or later with persistent connection, pipelining supported < HTTP/1.1 200 OK * Increasing bytecount by 25 from hbuflen * Increasing bytecount by 18 from hbuflen lib530.c:104 ABORTING TEST, since it seems that it would have run forever. * Closing connection 1 * The cache now contains 3 members * Closing connection 2 * The cache now contains 2 members * Closing connection 3 * The cache now contains 1 members === End of file stderr584 === Start of file stdout584 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 4 584 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 0 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 5 585 HTTP/1.1 200 OK Server: test-server/fake Content-Length: 4 586 === End of file stdout584 TESTDONE: 5 tests out of 6 reported OK: 83% TESTFAIL: These test cases failed: 584 TESTDONE: 6 tests were considered during 64 seconds. Bisecting lead to 5b2342d3772. The attached work-around brings back one of the removed infof() lines and gets the test working reliably again. I assume that's because the info() call has the side effect of slightly delaying Curl_addHandleToPipeline(), but I haven't confirmed that. Hopefully someone more familiar with the pipelining internals can come up with a proper fix. Fabian
From 23e13dd414e49e284605de417245b9b15cefb136 Mon Sep 17 00:00:00 2001
From: Fabian Keil <f...@fabiankeil.de>
Date: Wed, 22 Jan 2014 14:33:14 +0100
Subject: [PATCH] Bring back debug output for Curl_addHandleToPipeline()
This reverts a part of 5b2342d3772 and is a work-around to
get test 584 working reliably on FreeBSD 11-CURRENT again.
---
lib/url.c | 1 +
1 file changed, 1 insertion(+)
diff --git a/lib/url.c b/lib/url.c
index 665133f..3f85502 100644
--- a/lib/url.c
+++ b/lib/url.c
@@ -2683,6 +2683,7 @@ CURLcode Curl_addHandleToPipeline(struct SessionHandle *data,
{
if(!Curl_llist_insert_next(pipeline, pipeline->tail, data))
return CURLE_OUT_OF_MEMORY;
+ infof(data, "Curl_addHandleToPipeline: length: %d\n", pipeline->size);
return CURLE_OK;
}
--
1.8.5.2
signature.asc
Description: PGP signature
------------------------------------------------------------------- List admin: http://cool.haxx.se/list/listinfo/curl-library Etiquette: http://curl.haxx.se/mail/etiquette.html
