cURL / Mailing Lists / curl-library / Single Mail

curl-library

Test 584 failures on FreeBSD after 5b2342d3772

From: Fabian Keil <freebsd-listen_at_fabiankeil.de>
Date: Wed, 22 Jan 2014 14:51:49 +0100

Test 584 has recently become unreliable on FreeBSD:

fk_at_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_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 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

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

Received on 2014-01-22