Test 1801 failed on OS X

[Jactry]

Hi all,

I created an OS X testbot on Travis CI. Most of the tests passed on it but 1801.
Here are the logs:
clang: https://travis-ci.org/wine-zh/curl/jobs/75475792#L9795
gcc: https://travis-ci.org/wine-zh/curl/jobs/75475795#L9798
I'm not sure is it a bug of curl or due to the system.

I'm newbie here, any help or advice is great appreciated!
Thank you! :-)

[Jactry]

Update:
This test also failed on my local OS X system.
Here are some information may help, and I'm glad to provide more information if necessary. :-)

---snip---
test 1801...[HTTP/2 upgrade with lying server]

 1801: data FAILED:
--- log/check-expected  2015-08-14 14:18:25.000000000 +0800
+++ log/check-generated 2015-08-14 14:18:25.000000000 +0800
@@ -1 +1,2 @@
 HTTP/1.1 101 Switching![LF]
+[LF]
== Contents of files in the log/ dir after test 1801
=== Start of file check-expected
 HTTP/1.1 101 Switching![LF]
=== End of file check-expected
=== Start of file check-generated
 HTTP/1.1 101 Switching![LF]
 [LF]
=== End of file check-generated
=== Start of file curl1801.out
 HTTP/1.1 101 Switching
=== End of file curl1801.out
=== Start of file http_server.log
 14:18:25.169594 ====> Client connect
 14:18:25.169827 accept_connection 3 returned 4
 14:18:25.170043 accept_connection 3 returned 0
 14:18:25.170750 Read 171 bytes
 14:18:25.170898 Process 171 bytes request
 14:18:25.171069 Got request: GET /1801 HTTP/1.1
 14:18:25.171242 Requested test number 1801 part 0
 14:18:25.171479 enabled upgrade to http2
 14:18:25.171579 - request found to be complete
 14:18:25.171750 Found Upgrade: in request and allows it
 14:18:25.171982 Wrote request (171 bytes) input to log/server.input
 14:18:25.172065 Send response test1801 section <data>
 14:18:25.172262 Sent off 196 bytes
 14:18:25.172458 Response sent (196 bytes) and written to log/server.response
 14:18:25.172619 switched to http2
 14:18:25.172803 ====> Client disconnect 0
=== End of file http_server.log
=== Start of file server.input
 GET /1801 HTTP/1.1
 Host: 127.0.0.1:8990
 User-Agent: curl/7.45.0-DEV
 Accept: */*
 Connection: Upgrade, HTTP2-Settings
 Upgrade: h2c
 HTTP2-Settings: AAMAAABkAAQAAP__
=== End of file server.input
=== Start of file server.response
 HTTP/1.1 101 Switching
 HTTP/1.1 200 OK
 Date: Thu, 09 Nov 2010 14:49:00 GMT
 Server: test-server/fake
 Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
 Content-Length: 6
 Content-Type: text/html
 lies
=== End of file server.response
=== Start of file stderr1801
   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                  Dload  Upload   Total   Spent    Left  Speed

   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (56) Unexpected EOF
=== End of file stderr1801
=== Start of file trace1801
 14:18:25.167498 == Info: STATE: INIT => CONNECT handle 0x7ffa0300aa08; line 1090 (connection #-5000)
 14:18:25.168672 == Info: Added connection 0. The cache now contains 1 members
 14:18:25.169237 == Info:   Trying 127.0.0.1...
 14:18:25.169329 == Info: STATE: CONNECT => WAITCONNECT handle 0x7ffa0300aa08; line 1143 (connection #0)
 14:18:25.170087 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8990 (#0)
 14:18:25.170099 == Info: STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x7ffa0300aa08; line 1240 (connection #0)
 14:18:25.170116 == Info: Marked for [keep alive]: HTTP default
 14:18:25.170125 == Info: STATE: SENDPROTOCONNECT => DO handle 0x7ffa0300aa08; line 1258 (connection #0)
 14:18:25.170240 => Send header, 171 bytes (0xab)
 0000: GET /1801 HTTP/1.1
 0014: Host: 127.0.0.1:8990
 002a: User-Agent: curl/7.45.0-DEV
 0047: Accept: */*
 0054: Connection: Upgrade, HTTP2-Settings
 0079: Upgrade: h2c
 0087: HTTP2-Settings: AAMAAABkAAQAAP__
 00a9:
 14:18:25.170307 == Info: STATE: DO => DO_DONE handle 0x7ffa0300aa08; line 1337 (connection #0)
 14:18:25.170319 == Info: STATE: DO_DONE => WAITPERFORM handle 0x7ffa0300aa08; line 1464 (connection #0)
 14:18:25.170329 == Info: STATE: WAITPERFORM => PERFORM handle 0x7ffa0300aa08; line 1474 (connection #0)
 14:18:25.172322 == Info: HTTP/2 found, allow multiplexing
 14:18:25.172332 <= Recv header, 24 bytes (0x18)
 0000: HTTP/1.1 101 Switching!.
 14:18:25.172465 == Info: Received 101
 14:18:25.172528 == Info: Using HTTP2, server supports multi-use
 14:18:25.172536 == Info: Connection state changed (HTTP/2 confirmed)
 14:18:25.172561 == Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=171
 14:18:25.184306 == Info: nghttp2_session_mem_recv() returns 171
 14:18:25.184471 == Info: http2_recv: 16384 bytes buffer at 0x7ffa0300b330 (stream 1)
 14:18:25.184522 == Info: multi changed, check CONNECT_PEND queue
 14:18:25.189662 == Info: http2_recv: 16384 bytes buffer at 0x7ffa0300b330 (stream 1)
 14:18:25.189686 == Info: Unexpected EOF
 14:18:25.189694 == Info: Marked for [closure]: Transfer returned error
 14:18:25.189702 == Info: Curl_done
 14:18:25.189739 == Info: free header_recvbuf!
 14:18:25.189769 == Info: HTTP/2 DISCONNECT starts now
 14:18:25.189798 == Info: HTTP/2 DISCONNECT done
 14:18:25.189805 == Info: Closing connection 0
 14:18:25.189827 == Info: The cache now contains 0 members
 14:18:25.189993 == Info: Expire cleared
=== End of file trace1801
---snip---
TESTDONE: 925 tests out of 926 reported OK: 99%
TESTFAIL: These test cases failed: 1801
TESTDONE: 992 tests were considered during 357 seconds.
TESTINFO: 66 tests were skipped due to these restraints:
TESTINFO: "curl lacks Metalink support" 18 times (2005, 2006, 2007, 2008, 2009, 2010, 2011, 2012, 2013 and 9 more)
TESTINFO: "Resolving IPv6 'ip6-localhost' didn't work" 2 times (241, 1083)
TESTINFO: "curl lacks TLS-SRP support" 5 times (320, 321, 322, 323, 324)
TESTINFO: "configured as DISABLED" 8 times (594, 836, 882, 938, 1209, 1211, 1316, 1512)
TESTINFO: "no stunnel" 32 times (300, 301, 302, 303, 304, 305, 306, 307, 308 and 23 more)
TESTINFO: "curl lacks WinSSL support" 1 times (2043)
make[1]: *** [full-test] Error 1
make: *** [test-full] Error 2

OS X version:
10.10.4
kernel version:
uname -a
Darwin MacBookPro.local 14.4.0 Darwin Kernel Version 14.4.0: Thu May 28 11:35:04 PDT 2015; root:xnu-2782.30.5~1/RELEASE_X86_64 x86_64
configure information:

 curl version:     7.45.0-DEV
  Host setup:       x86_64-apple-darwin14.4.0
  Install prefix:   /usr/local
  Compiler:         gcc
  SSL support:      enabled (OpenSSL)
  SSH support:      enabled (libSSH2)
  zlib support:     enabled
  GSS-API support:  no      (--with-gssapi)
  TLS-SRP support:  no      (--enable-tls-srp)
  resolver:         default (--enable-ares / --enable-threaded-resolver)
  IPv6 support:     enabled
  Unix sockets support: enabled
  IDN support:      enabled
  Build libcurl:    Shared=yes, Static=yes
  Built-in manual:  enabled
  --libcurl option: enabled (--disable-libcurl-option)
  Verbose errors:   enabled (--disable-verbose)
  SSPI support:     no      (--enable-sspi)
  ca cert bundle:   no
  ca cert path:     no
  LDAP support:     enabled (OpenLDAP)
  LDAPS support:    enabled
  RTSP support:     enabled
  RTMP support:     enabled (librtmp)
  metalink support: no      (--with-libmetalink)
  HTTP2 support:    enabled (nghttp2)
  Protocols:        DICT FILE FTP FTPS GOPHER HTTP HTTPS IMAP IMAPS LDAP LDAPS POP3 POP3S RTMP RTSP SCP SFTP SMB SMBS SMTP SMTPS TELNET TFTP

[kdudka]

We are disabling test1801 in Fedora builds of curl. In my opinion, the test is broken by design:

21e82bd#commitcomment-12226582

[bagder]

Looks like a flaky test case, but it works reliably for me... :-(

[Jactry]

Hi @bagder ,

Perfect!
Thanks for your work!