Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Simple request always fails on Mac OS X #508

Closed
wezm opened this issue May 6, 2015 · 15 comments · Fixed by #512
Closed

Simple request always fails on Mac OS X #508

wezm opened this issue May 6, 2015 · 15 comments · Fixed by #512
Labels
A-client Area: client. C-bug Category: bug. Something is wrong. This is bad!

Comments

@wezm
Copy link

wezm commented May 6, 2015

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:

These do not:

@reem
Copy link
Contributor

reem commented May 6, 2015

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

@wezm
Copy link
Author

wezm commented May 6, 2015

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
Copy link
Member

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 [email protected] 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
Copy link
Author

wezm commented May 6, 2015

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
Copy link
Member

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 [email protected] 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
Copy link
Member

@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);
}

@seanmonstar seanmonstar added C-bug Category: bug. Something is wrong. This is bad! A-client Area: client. labels May 6, 2015
@wezm
Copy link
Author

wezm commented May 6, 2015

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

@seanmonstar
Copy link
Member

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

@seanmonstar
Copy link
Member

@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
Copy link
Author

wezm commented May 6, 2015

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
Copy link
Author

wezm commented May 7, 2015

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
Copy link
Member

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
Copy link
Author

wezm commented May 7, 2015

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

On 7 May 2015, at 10:34 am, Sean McArthur [email protected] 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).

@seanmonstar
Copy link
Member

Aha! So, seems Linux has no problem with that, but Mac does.

Hyper calls shutdown if there's Close header in the request. The response is also sending a Close header, and so shutdown is called a second time in the response. I assumed it'd be a no-op if it was already closed...

seanmonstar added a commit that referenced this issue May 7, 2015
On OSX, calling shutdown a second time will return a NotConnected error.
This commit will just ignore it, since we can agree that if a stream is
"not connected", it is in fact "closed".

Closes #508
seanmonstar added a commit that referenced this issue May 7, 2015
On OSX, calling shutdown a second time will return a NotConnected error.
This commit will just ignore it, since we can agree that if a stream is
"not connected", it is in fact "closed".

Closes #508
seanmonstar added a commit that referenced this issue May 7, 2015
On OSX, calling shutdown a second time will return a NotConnected error.
This commit will just ignore it, since we can agree that if a stream is
"not connected", it is in fact "closed".

Closes #508
@wezm
Copy link
Author

wezm commented May 8, 2015

Cheers, thanks for your help and responsiveness.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-client Area: client. C-bug Category: bug. Something is wrong. This is bad!
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants