Simple request always fails on Mac OS X

[wezm]

Given this small sample program basically copied from the README:

extern crate hyper;

use std::io::Read;

use hyper::Client;
use hyper::header::Connection;
use hyper::header::ConnectionOption;

fn main() {
    // Create a client.
    let mut client = Client::new();

    // Creating an outgoing request.
    let mut res = client.get("http://files.wezm.net/testpodcast.xml")
        // set a header
        .header(Connection(vec![ConnectionOption::Close]))
        // let 'er go!
        .send().unwrap();

    // Read the Response.
    let mut body = String::new();
    res.read_to_string(&mut body).unwrap();

    println!("Response: {}", body);
}

The request always fails with a HttpIoError (NotConnected):

cargo run --verbose                                                                                                                                      Fresh typeable v0.1.1
       Fresh libc v0.1.6
       Fresh bitflags v0.1.1
       Fresh unicase v0.1.0
       Fresh traitobject v0.0.1
       Fresh lazy_static v0.1.10
       Fresh pkg-config v0.3.4
       Fresh gcc v0.3.5
       Fresh httparse v0.1.1
       Fresh rustc-serialize v0.3.14
       Fresh matches v0.1.2
       Fresh log v0.3.1
       Fresh num_cpus v0.2.4
       Fresh url v0.2.33
       Fresh mime v0.0.11
       Fresh openssl-sys v0.6.2
       Fresh time v0.1.25
       Fresh openssl v0.6.2
       Fresh cookie v0.1.20
       Fresh hyper v0.3.16
       Fresh request v0.1.0 (file:///Users/wmoore/Projects/Musicast/crawler/request)
     Running `target/debug/request`
thread '<main>' panicked at 'called `Result::unwrap()` on an `Err` value: HttpIoError(Error { repr: Os(57) })', /Users/rustbuild/src/rust-buildbot/slave/beta-dist-rustc-mac/build/src/libcore/result.rs:729
Process didn't exit successfully: `target/debug/request` (exit code: 101)

This is with OS X 10.10.3 (14D136) and rustc 1.0.0-beta.4 (850151a75 2015-04-30) (built 2015-04-30). The same program works when run on a Ubuntu 14.04 VM with the same version of rust.

It seems somewhat dependent on the URL, although more fail than don't. E.g. these work:

• http://www.itmedia.co.jp (albeit it fails later because the character set is Shift-JIS)
• http://bellroy.com/

These do not:

• http://google.com/
• http://feeds.feedburner.com/oneminutefrench
• http://files.wezm.net/testpodcast.xml
• http://www.marksherry.net/outburst_radio/outburst_radioshow_podcast.xml
• http://drclaw.net/feed/atom/

[reem]

Can you re-run with RUST_BACKTRACE=1, so we can get a backtrace for that panic?

[wezm]

Sure, doesn't look all that helpful though. I can tell you that it's the unwrap on send .send().unwrap(); that is panicking though:

stack backtrace:
   1:        0x1050720df - sys::backtrace::write::h0f2fc53eb11eb814gWr
   2:        0x105075464 - panicking::on_panic::hd617a4042e8486fciUv
   3:        0x10506b245 - rt::unwind::begin_unwind_inner::hd84dfec22ac3667d1Bv
   4:        0x10506bad6 - rt::unwind::begin_unwind_fmt::h5bb6fa95bd57b24bFAv
   5:        0x105074d3c - rust_begin_unwind
   6:        0x1050949d5 - panicking::panic_fmt::hea516303ab7688d0lwy
   7:        0x104fad606 - result::Result<T, E>::unwrap::h5683422046223242116
   8:        0x104fad22c - main::ha0a39c096ced901bjaa
   9:        0x105076f88 - rust_try_inner
  10:        0x105076f75 - rust_try
  11:        0x105075c68 - rt::lang_start::h04063553a12d35edNOv
  12:        0x104fd7b1e - main

[seanmonstar]

Would you mind added env_logger (or similar) and collecting logs from
hyper? (with env_logger, you'd set RUST_LOG=hyper).

On Tue, May 5, 2015, 10:25 PM Wesley Moore notifications@github.com wrote:

Sure, doesn't look all that helpful though. I can tell you that it's the
unwrap on send .send().unwrap(); that is panicking though:

stack backtrace:
1: 0x1050720df - sys::backtrace::write::h0f2fc53eb11eb814gWr
2: 0x105075464 - panicking::on_panic::hd617a4042e8486fciUv
3: 0x10506b245 - rt::unwind::begin_unwind_inner::hd84dfec22ac3667d1Bv
4: 0x10506bad6 - rt::unwind::begin_unwind_fmt::h5bb6fa95bd57b24bFAv
5: 0x105074d3c - rust_begin_unwind
6: 0x1050949d5 - panicking::panic_fmt::hea516303ab7688d0lwy
7: 0x104fad606 - result::Result<T, E>::unwrap::h5683422046223242116
8: 0x104fad22c - main::ha0a39c096ced901bjaa
9: 0x105076f88 - rust_try_inner
10: 0x105076f75 - rust_try
11: 0x105075c68 - rt::lang_start::h04063553a12d35edNOv
12: 0x104fd7b1e - main

—
Reply to this email directly or view it on GitHub
#508 (comment).

[wezm]

Sure, happy to help any way I can:

     Running `target/debug/request`
TRACE:hyper::client: send Get Url { scheme: "http", scheme_data: Relative(RelativeSchemeData { username: "", password: None, host: Domain("files.wezm.net"), port: None, default_port: Some(80), path: ["testpodcast.xml"] }), query: None, fragment: None }
TRACE:hyper::client: host="files.wezm.net"
TRACE:hyper::client: port=80
DEBUG:hyper::net: http scheme
DEBUG:hyper::client::request: request line: Get "/testpodcast.xml" Http11
DEBUG:hyper::client::request: headers=Headers { Connection: close, Host: files.wezm.net, }
TRACE:hyper::buffer: slicing (0, 1408, 4096)
TRACE:hyper::header: raw header: "Server"=[110, 103, 105, 110, 120, 47, 49, 46, 54, 46, 51]
TRACE:hyper::header: raw header: "Date"=[87, 101, 100, 44, 32, 48, 54, 32, 77, 97, 121, 32, 50, 48, 49, 53, 32, 48, 53, 58, 53, 48, 58, 51, 52, 32, 71, 77, 84]
TRACE:hyper::header: raw header: "Content-Type"=[116, 101, 120, 116, 47, 120, 109, 108]
TRACE:hyper::header: raw header: "Last-Modified"=[77, 111, 110, 44, 32, 49, 54, 32, 70, 101, 98, 32, 50, 48, 49, 53, 32, 48, 52, 58, 52, 51, 58, 48, 57, 32, 71, 77, 84]
TRACE:hyper::header: raw header: "X-Varnish"=[50, 57, 56, 52, 57, 51, 32, 50, 57, 56, 52, 57, 49]
TRACE:hyper::header: raw header: "Age"=[52, 51]
TRACE:hyper::header: raw header: "Via"=[49, 46, 49, 32, 118, 97, 114, 110, 105, 115, 104, 45, 118, 52]
TRACE:hyper::header: raw header: "Transfer-Encoding"=[99, 104, 117, 110, 107, 101, 100]
TRACE:hyper::header: raw header: "Connection"=[99, 108, 111, 115, 101]
TRACE:hyper::header: raw header: "Accept-Ranges"=[98, 121, 116, 101, 115]
DEBUG:hyper::client::response: version=Http11, status=Ok
DEBUG:hyper::client::response: headers=Headers { Transfer-Encoding: chunked, Via: 1.1 varnish-v4, Accept-Ranges: bytes, Date: Wed, 06 May 2015 05:50:34 GMT, Server: nginx/1.6.3, X-Varnish: 298493 298491, Age: 43, Content-Type: text/xml, Connection: close, Last-Modified: Mon, 16 Feb 2015 04:43:09 GMT, }
TRACE:hyper::client::pool: PooledStream.drop, is_closed=true, is_drained=false
thread '<main>' panicked at 'called `Result::unwrap()` on an `Err` value: HttpIoError(Error { repr: Os(57) })', /Users/rustbuild/src/rust-buildbot/slave/beta-dist-rustc-mac/build/src/libcore/result.rs:729
An unknown error occurred

To learn more, run the command again with --verbose.

[seanmonstar]

Hmm. Hyper is now calling shutdown because of the Connection: Close header.
After writing the end, it calls shutdown(Write). I wonder if there's a
difference in the way Mac and Linux handle libc::shutdown.

On Tue, May 5, 2015, 10:52 PM Wesley Moore notifications@github.com wrote:

Sure, happy to help any way I can:

 Running `target/debug/request`

TRACE:hyper::client: send Get Url { scheme: "http", scheme_data: Relative(RelativeSchemeData { username: "", password: None, host: Domain("files.wezm.net"), port: None, default_port: Some(80), path: ["testpodcast.xml"] }), query: None, fragment: None }
TRACE:hyper::client: host="files.wezm.net"
TRACE:hyper::client: port=80
DEBUG:hyper::net: http scheme
DEBUG:hyper::client::request: request line: Get "/testpodcast.xml" Http11
DEBUG:hyper::client::request: headers=Headers { Connection: close, Host: files.wezm.net, }
TRACE:hyper::buffer: slicing (0, 1408, 4096)
TRACE:hyper::header: raw header: "Server"=[110, 103, 105, 110, 120, 47, 49, 46, 54, 46, 51]
TRACE:hyper::header: raw header: "Date"=[87, 101, 100, 44, 32, 48, 54, 32, 77, 97, 121, 32, 50, 48, 49, 53, 32, 48, 53, 58, 53, 48, 58, 51, 52, 32, 71, 77, 84]
TRACE:hyper::header: raw header: "Content-Type"=[116, 101, 120, 116, 47, 120, 109, 108]
TRACE:hyper::header: raw header: "Last-Modified"=[77, 111, 110, 44, 32, 49, 54, 32, 70, 101, 98, 32, 50, 48, 49, 53, 32, 48, 52, 58, 52, 51, 58, 48, 57, 32, 71, 77, 84]
TRACE:hyper::header: raw header: "X-Varnish"=[50, 57, 56, 52, 57, 51, 32, 50, 57, 56, 52, 57, 49]
TRACE:hyper::header: raw header: "Age"=[52, 51]
TRACE:hyper::header: raw header: "Via"=[49, 46, 49, 32, 118, 97, 114, 110, 105, 115, 104, 45, 118, 52]
TRACE:hyper::header: raw header: "Transfer-Encoding"=[99, 104, 117, 110, 107, 101, 100]
TRACE:hyper::header: raw header: "Connection"=[99, 108, 111, 115, 101]
TRACE:hyper::header: raw header: "Accept-Ranges"=[98, 121, 116, 101, 115]
DEBUG:hyper::client::response: version=Http11, status=Ok
DEBUG:hyper::client::response: headers=Headers { Transfer-Encoding: chunked, Via: 1.1 varnish-v4, Accept-Ranges: bytes, Date: Wed, 06 May 2015 05:50:34 GMT, Server: nginx/1.6.3, X-Varnish: 298493 298491, Age: 43, Content-Type: text/xml, Connection: close, Last-Modified: Mon, 16 Feb 2015 04:43:09 GMT, }
TRACE:hyper::client::pool: PooledStream.drop, is_closed=true, is_drained=false
thread '

' panicked at 'called Result::unwrap() on an Err value: HttpIoError(Error { repr: Os(57) })', /Users/rustbuild/src/rust-buildbot/slave/beta-dist-rustc-mac/build/src/libcore/result.rs:729
An unknown error occurred

To learn more, run the command again with --verbose.

—
Reply to this email directly or view it on GitHub
#508 (comment).

[seanmonstar]

@wezm If it's related to shutdown, this is the smallest case that would test it (I think...):

use std::io::{Read, Write};
use std::net;


fn main() {
    let mut stream = net::TcpStream::connect("rust-lang.org:80").unwrap();
    stream.write_all(b"GET / HTTP/1.1\r\nHost: rust-lang.org\r\n\r\n").unwrap();
    stream.shutdown(net::Shutdown::Write).unwrap();

    let mut s = String::new();
    stream.read_to_string(&mut s).unwrap();
    println!("{}", s);
}

[wezm]

The test case above works fine (does not panic) as posted. I tried adding a Connection: close header and it still works fine. 😕

[seanmonstar]

@wezm what if you comment out the Connection: close header from the hyper example? If it still fails, we can look elsewhere.

[seanmonstar]

@wezm if it works without the Connection close, try the tcp example with your own url (don't forget to edit the Host: part of the byte string.

[wezm]

Just read the man page for shutdown on Linux and OS X. From that point of view they should operate identically (of course the actual implementation may differ).

[wezm]

The hyper test case works when Connection close is removed. The TCP example when edited as follows also works, with and without the Connection close header.

    let mut stream = net::TcpStream::connect("files.wezm.net:80").unwrap();
    stream.write_all(b"GET /testpodcast.xml HTTP/1.1\r\nHost: files.wezm.net\r\n\r\n").unwrap();

[seanmonstar]

Hm, what if you change the tcp example to call shutdown twice?

// ...
stream.shutdown(net::Shutdown::Write).unwrap();
stream.shutdown(net::Shutdown::Write).unwrap();
// ...

[wezm]

Yup, panics with the same error as the original test case.

On 7 May 2015, at 10:34 am, Sean McArthur notifications@github.com wrote:

Hm, what if you change the tcp example to call shutdown twice?

// ...
stream.shutdown(net::Shutdown::Write).unwrap();
stream.shutdown(net::Shutdown::Write).unwrap();
// ...
—
Reply to this email directly or view it on GitHub #508 (comment).