curl-library
Race condition in test 564 after 4a42e5cdaa344755?
Date: Wed, 17 Aug 2011 01:06:06 +0200
I'm currently experimenting with the tests again, and one of the
issues I ran into (using 4ed7abb5370a9416) is that test 564 seems
to fail most of the time, but not always.
When it fails, I get:
fk_at_r500 ~/git/curl/tests $./runtests.pl -n 564
Use of uninitialized value $p in string eq at /usr/local/lib/perl5/5.14.1/BSDPAN/BSDPAN.pm line 36.
********* System characteristics ********
* curl 7.22.0-DEV (amd64-unknown-freebsd9.0)
* libcurl/7.22.0-DEV OpenSSL/0.9.8q zlib/1.2.5
* Features: Debug TrackMemory IPv6 Largefile NTLM NTLM_SSO SSL libz
* Host: r500.local
* System: FreeBSD r500.local 9.0-BETA1 FreeBSD 9.0-BETA1 #344 r+ea7f16f: Tue Aug 16 19:09:41 CEST 2011 fk_at_r500.local:/usr/obj/usr/src/sys/ZOEY amd64
* Server SSL: OFF 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
* 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
*****************************************
Use of uninitialized value $p in string eq at /usr/local/lib/perl5/5.14.1/BSDPAN/BSDPAN.pm line 36.
test 564...[FTP RETR a file over a SOCKS proxy using the multi interface]
stdout FAILED:
--- log/check-expected 2011-08-17 00:05:29.722035830 +0200
+++ log/check-generated 2011-08-17 00:05:29.721032141 +0200
@@ -1,6 +0,0 @@
-data
- to
- see
-that FTP
-works
- so does it?
- abort tests
TESTDONE: 0 tests out of 1 reported OK: 0%
TESTFAIL: These test cases failed: 564
TESTDONE: 1 tests were considered during 34 seconds.
---------
=== Start of file stderr564
URL: ftp://127.0.0.1:8992/path/564
Start at URL 0
* About to connect() to proxy 127.0.0.1 port 9000 (#0)
* Trying 127.0.0.1... * 0x80183e008 is at send pipe head
* STATE: CONNECT => WAITCONNECT handle 0x8018c4088; (connection #0)
* SOCKS4 request granted.
* Connected to 127.0.0.1 (127.0.0.1) port 9000 (#0)
* FTP 0x8019578f8 state change from STOP to WAIT220
* STATE: WAITCONNECT => PROTOCONNECT handle 0x8018c4088; (connection #0)
< 220- _ _ ____ _
< 220- ___| | | | _ \| |
< 220- / __| | | | |_) | |
< 220- | (__| |_| | _ <| |___
< 220 \___|\___/|_| \_\_____|
> USER anonymous
* FTP 0x8019578f8 state change from WAIT220 to USER
< 331 We are happy you popped in
> PASS ftp_at_example.com
* FTP 0x8019578f8 state change from USER to PASS
< 230 Welcome you silly person
> PWD
* FTP 0x8019578f8 state change from PASS to PWD
< 257 "/" is current directory
* Entry path is '/'
* FTP 0x8019578f8 state change from PWD to STOP
* protocol connect phase DONE
* STATE: PROTOCONNECT => DO handle 0x8018c4088; (connection #0)
* DO phase starts
> CWD path
* FTP 0x8019578f8 state change from STOP to CWD
* STATE: DO => DOING handle 0x8018c4088; (connection #0)
< 250 CWD command successful.
> EPSV
* FTP 0x8019578f8 state change from CWD to PASV
* Connect data stream passively
< 229 Entering Passive Mode (|||53212|)
* Trying 127.0.0.1... * Connecting to 127.0.0.1 (127.0.0.1) port 9000
* SOCKS4 request granted.
* FTP 0x8019578f8 state change from PASV to STOP
* DO phase is complete
* STATE: DOING => DO_MORE handle 0x8018c4088; (connection #0)
* SOCKS4 reply has wrong version, version should be 4.: 500 '#
* STATE: DO_MORE => COMPLETED handle 0x8018c4088; (connection #-5000)
* STATE: COMPLETED => MSGSENT handle 0x8018c4088; (connection #-5000)
* Closing connection #0
=== End of file stderr564
I locally modified socks.c like this, to dump the offending response:
diff --git a/lib/socks.c b/lib/socks.c
index ac13ed8..a351ddf 100644
--- a/lib/socks.c
+++ b/lib/socks.c
@@ -277,7 +277,10 @@ CURLcode Curl_SOCKS4(const char *proxy_name,
/* wrong version ? */
if(socksreq[0] != 0) {
failf(data,
- "SOCKS4 reply has wrong version, version should be 4.");
+ "SOCKS4 reply has wrong version, version should be 4.:"
+ " %c%c%c%c%c%c%c%c",
+ socksreq[0], socksreq[1], socksreq[2], socksreq[3],
+ socksreq[4], socksreq[5], socksreq[6], socksreq[7]);
return CURLE_COULDNT_CONNECT;
}
It always seems to complain about the same byte sequence.
For one reason or another, curl seems to be interpreting an
ftp message as socks reply:
fk_at_r500 ~/git/curl/tests $grep -n "500 '" ./ftpserver.pl
1522: sendcontrol "500 '$_': command not understood.\r\n";
I confirmed this by modifying the error code.
Whether it fails or not, the test run seems to take about
34 seconds.
After reverting the lib/connect.c and lib/multi.c modifications
from 4a42e5cdaa344755c, while keeping the other modifications,
the test worked five times in a row.
Otherwise the success rate seems to be about 20% so even getting
two successes in a row is unlikely.
The patch is attached to make it more clear what I'm talking
about, I'm not suggesting that this is the solution.
Fabian
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
- text/x-patch attachment: 0001-Revert-the-lib-connect.c-and-lib-multi.c-modificatio.patch
- application/pgp-signature attachment: signature.asc