Client DNS or Connect hangs

[iddm]

Hey all. I have a bot which uses hyper 0.9.14.
Now, for some endpoints (or just sometimes, dunno) it hangs for 30 seconds and more (up to few minutes). I have decided to measure how my bot works:

[2016-12-21][23:17:35.675620678][DEBUG] in (discord_pickupbot::pickupbot::bot) at src/pickupbot/bot.rs:673 message: !rating
[2016-12-21][23:17:35.676652464][DEBUG] in (hyper::http::h1) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/http/h1.rs:156 request line: Get "/api/v6/channels/178864995889577985" Http11
[2016-12-21][23:17:35.676675390][DEBUG] in (hyper::http::h1) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/http/h1.rs:171 headers=Headers { Host: discordapp.com, Content-Type: application/json, Authorization: <HIDDEN>), }
[2016-12-21][23:17:35.839778416][DEBUG] in (hyper::client::response) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/client/response.rs:47 version=Http11, status=Ok
[2016-12-21][23:17:35.839847853][DEBUG] in (hyper::client::response) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/client/response.rs:48 headers=Headers { Date: Wed, 21 Dec 2016 15:17:35 GMT, Content-Type: application/json, Transfer-Encoding: chunked, Connection: keep-alive, Set-Cookie: __cfduid=d58e3a8ea07b3487a7cdd2117c5363ab91482333455; expires=Thu, 21-Dec-17 15:17:35 GMT; path=/; domain=.discordapp.com; HttpOnly, Strict-Transport-Security: max-age=31536000; includeSubDomains, Via: 1.1 google, Alt-Svc: clear, Server: cloudflare-nginx, CF-RAY: 314c4d41eb164f20-DME, }
[2016-12-21][23:17:35.854009364][DEBUG] in (discord_pickupbot::pickupbot::qlbalancer) at src/pickupbot/qlbalancer.rs:571 Requesting: http://host:3331/ratings/177850249858121729
[2016-12-21][23:17:35.854136679][DEBUG] in (hyper::net) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/net.rs:374 http scheme
[2016-12-21][23:17:36.054907226][DEBUG] in (hyper::http::h1) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/http/h1.rs:156 request line: Get "/ratings/177850249858121729" Http11
[2016-12-21][23:17:36.054990058][DEBUG] in (hyper::http::h1) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/http/h1.rs:171 headers=Headers { Host: host:3331, }
[2016-12-21][23:17:36.133366026][DEBUG] in (hyper::client::response) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/client/response.rs:47 version=Http11, status=Ok
[2016-12-21][23:17:36.133435895][DEBUG] in (hyper::client::response) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/client/response.rs:48 headers=Headers { X-Powered-By: Express, Connection: close, Content-Type: application/json; charset=utf-8, Content-Length: 937, ETag: W/"3a9-QDd1oVGfW2b7RRZ05AuQag", Date: Wed, 21 Dec 2016 15:17:35 GMT, }
[2016-12-21][23:17:36.150468687][DEBUG] in (hyper::net) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/net.rs:374 http scheme
[2016-12-21][23:17:57.206281042][DEBUG] in (hyper::net) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/net.rs:597 https scheme

Pay all of your attention to last two lines:

[2016-12-21][23:17:36.150468687][DEBUG] in (hyper::net) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/net.rs:374 http scheme

[2016-12-21][23:17:57.206281042][DEBUG] in (hyper::net) at /home/vitya/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.9.14/src/net.rs:597 https scheme

I don't know what do this lines mean but I am sure this takes all the time my bot hangs because exactly after that my bot continue to work okay. Personally, I think this is something in client's destructor.
Also, this log clearly shows when I sent the request and when I received the response. So this absolutely mean the remote host works okay, also, it's log clearly corroborates that fact. So the problem is exactly in hyper's client.
Also, note, that my remote host does not work with https and the url includes http:// part so there is no any need to try to use https scheme, so I don't understand the last line also because of that.

This is my code. Note that it worked good for a long time with almost no change and I agree it is weird:

pub fn rating(id: UserId) -> Option<UserStats> {
    let mut client = Client::new();
    client.set_read_timeout(Some(Duration::from_secs(5)));
    client.set_write_timeout(Some(Duration::from_secs(5)));
    let url = &format!("http://host:3331/ratings/{}", id.0);
    debug!("Requesting: {}", url);
    if let Ok(mut res) = client.get(url).send() {
        trace!("Response status: {:?}", res.status);
        let mut string = String::new();
        let _ = res.read_to_string(&mut string);
        trace!("Response body: {:?}", string);
        let mut res_status = false;
        let json_opt: Result<Value, _> = serde_json::from_str(&string);
        if let Ok(json) = json_opt {
            if let Value::Object(mut obj) = json {
                if let Some(ok) = obj.get_mut("ok") {
                    if let &mut Value::Bool(status) = ok {
                        res_status = status;
                    }
                }
                if res_status {
                    if let Some(mut stats) = obj.remove("stats") {
                        if let Some(mut array) = stats.as_array_mut() {
                            return Some(UserStats::decode(array))
                        }
                    }
                }
            }
        }
    } else {
        trace!("Unable to unpack response.");
    }
    None
}

I also have this problem in the library I use, discord-rs.

OS: Debian 8 (latest updates)
Rust: Latest stable (1.13)

[seanmonstar]

The http log line comes just before calling TcpStream::connect, which internally (in std::net) does a DNS lookup before trying to connect to the resolved socket address. This definitely looks like the internal call to getaddrinfo is blocking for 30 seconds. There is nothing that can be done in hyper 0.9, as it relies on std::net::TcpStream for DNS lookup, and there is no way of setting a timeout for it.

While not perfectly fixed in the developing 0.10, it is mitigated by using a thread pool of DNS lookups. The best would be to make use of an actual asynchronous DNS library.

[iddm]

@seanmonstar Are not you gonna say that the problem is that my server's dns lookup process takes too long? If so, what could be the reason of it? How can I fix this? Also, I still don't see how this answers the question "why does it print https scheme in the log if I don't use https at all?".

I've just checked: nslookup host works perfectly fine and fast. Do you mean the problem is exactly in getaddrinfo? If so, the question is the same, how do I fix it and why does this problem happen?

I'm experiencing this problem as well. Currently benching using cargo run and cargo run --release https://github.com/SergioBenitez/rocket and it will hang for thirty seconds or more using:

$ ab -n 10000 -c 100 http://localhost:8000/

Currently on Rust nightly. Always happens after 16000 requests.

Benchmarking localhost (be patient)
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests

[seanmonstar]

Closing as duplicate of #721