search

hjr3 / hyper-timeout

A timeout connector for the hyper client
Other
25 stars 10 forks source link

Always timing out #12

Closed augustocdias closed 9 months ago

augustocdias commented 4 years ago

In my application I'm seeing this in the logs every time I make a request:

{"timestamp": 1580818502769, "level": "DEBUG","target": "hyper::client","message": "client connection error: connection error: timed out"}

The request is successful and this is printed after everything is done.

hjr3 commented 4 years ago

Strange, the Timeout future is being dropped properly. This is happening inside hyper. Maybe I violated some invariant that I did not realize.

hjr3 commented 4 years ago

I am unable to reproduce this. I modified my example client to spawn a background task and then wait on the main thread to see if the log message shows up. Here is my branch: https://github.com/hjr3/hyper-timeout/tree/issue-12

Please look at the output below and let me know if the log messages are similar.

Here is the output:

RUST_LOG=debug cargo run --example client https://www.example.com/
    Finished dev [unoptimized + debuginfo] target(s) in 0.09s
     Running `target/debug/examples/client 'https://www.example.com/'`
[2020-02-06T15:25:29Z DEBUG hyper::client::connect::dns] resolving host="www.example.com"
[2020-02-06T15:25:29Z DEBUG hyper::client::connect::http] connecting to [2606:2800:220:1:248:1893:25c8:1946]:443
[2020-02-06T15:25:29Z DEBUG hyper::client::connect::http] connected to Some(V6([2606:2800:220:1:248:1893:25c8:1946]:443))
[2020-02-06T15:25:30Z DEBUG hyper::proto::h1::io] flushed 41 bytes
[2020-02-06T15:25:31Z DEBUG hyper::proto::h1::io] read 356 bytes
[2020-02-06T15:25:31Z DEBUG hyper::proto::h1::io] parsed 12 headers
[2020-02-06T15:25:31Z DEBUG hyper::proto::h1::conn] incoming body is content-length (1256 bytes)
[2020-02-06T15:25:31Z DEBUG hyper::proto::h1::io] read 1256 bytes
[2020-02-06T15:25:31Z DEBUG hyper::proto::h1::conn] incoming body completed
[2020-02-06T15:25:31Z DEBUG hyper::client::pool] pooling idle connection for "https://www.example.com"
Status: 200 OK
Headers:
{
    "accept-ranges": "bytes",
    "age": "457746",
    "cache-control": "max-age=604800",
    "content-type": "text/html; charset=UTF-8",
    "date": "Thu, 06 Feb 2020 15:25:30 GMT",
    "etag": "\"3147526947+gzip\"",
    "expires": "Thu, 13 Feb 2020 15:25:30 GMT",
    "last-modified": "Thu, 17 Oct 2019 07:18:26 GMT",
    "server": "ECS (bsa/EB24)",
    "vary": "Accept-Encoding",
    "x-cache": "HIT",
    "content-length": "1256",
}
<!doctype html>
<html>
<head>
    <title>Example Domain</title>

    <meta charset="utf-8" />
    <meta http-equiv="Content-type" content="text/html; charset=utf-8" />
    <meta name="viewport" content="width=device-width, initial-scale=1" />
    <style type="text/css">
    body {
        background-color: #f0f0f2;
        margin: 0;
        padding: 0;
        font-family: -apple-system, system-ui, BlinkMacSystemFont, "Segoe UI", "Open Sans", "Helvetica Neue", Helvetica, Arial, sans-serif;

    }
    div {
        width: 600px;
        margin: 5em auto;
        padding: 2em;
        background-color: #fdfdff;
        border-radius: 0.5em;
        box-shadow: 2px 3px 7px 2px rgba(0,0,0,0.02);
    }
    a:link, a:visited {
        color: #38488f;
        text-decoration: none;
    }
    @media (max-width: 700px) {
        div {
            margin: 0 auto;
            width: auto;
        }
    }
    </style>
</head>

<body>
<div>
    <h1>Example Domain</h1>
    <p>This domain is for use in illustrative examples in documents. You may use this
    domain in literature without prior coordination or asking for permission.</p>
    <p><a href="https://www.iana.org/domains/example">More information...</a></p>
</div>
</body>
</html>
augustocdias commented 4 years ago

I basically have a web server that receives URL's, I fetch it with hyper, process and send back in the response. There's no chance of timeout in this test as I have the image server in a local docker (and I have it configured for 2s). The weird part is that it writes the timeout in the log after everything is finished... This is what I have in the logs:

dali_1   | {"timestamp": 1580899024436, "level": "DEBUG","target": "dali","message": "Request parameters: ProcessImageRequest { image_address: "http://http/img-test", size: Size { width: Some(100), height: Some(100) }, format: Jpeg, quality: 75, watermarks: [], rotation: None }"}
dali_1   | {"timestamp": 1580899024436, "level": "DEBUG","target": "dali::commons::http","message": "Fetching image from url http://http/img-test"}
dali_1   | {"timestamp": 1580899024436, "level": "DEBUG","target": "hyper::client::pool","message": "reuse idle connection for ("http", http)"}
dali_1   | {"timestamp": 1580899024437, "level": "DEBUG","target": "hyper::proto::h1::io","message": "flushed 38 bytes"}
http_1   | 172.20.0.2 - - [05/Feb/2020:10:37:04 +0000] "GET /img-test HTTP/1.1" 200 79936 "-" "-" "-"
dali_1   | {"timestamp": 1580899024441, "level": "DEBUG","target": "hyper::proto::h1::io","message": "read 257 bytes"}
dali_1   | {"timestamp": 1580899024441, "level": "DEBUG","target": "hyper::proto::h1::io","message": "parsed 8 headers"}
dali_1   | {"timestamp": 1580899024441, "level": "DEBUG","target": "hyper::proto::h1::conn","message": "incoming body is content-length (79936 bytes)"}
dali_1   | {"timestamp": 1580899024442, "level": "DEBUG","target": "hyper::proto::h1::io","message": "read 79936 bytes"}
dali_1   | {"timestamp": 1580899024442, "level": "DEBUG","target": "hyper::proto::h1::conn","message": "incoming body completed"}
dali_1   | {"timestamp": 1580899024443, "level": "DEBUG","target": "hyper::client::pool","message": "pooling idle connection for ("http", http)"}
dali_1   | {"timestamp": 1580899024444, "level": "DEBUG","target": "dali::image_processor","message": "Resizing image to Size { width: Some(100), height: Some(100) }"}
dali_1   | {"timestamp": 1580899024444, "level": "DEBUG","target": "dali::image_processor","message": "Resizing image. Original size: 1000x563. Desired: Size { width: Some(100), height: Some(100) }"}
dali_1   | {"timestamp": 1580899024444, "level": "DEBUG","target": "dali::image_processor","message": "Final size: 100x56"}
dali_1   | {"timestamp": 1580899024449, "level": "DEBUG","target": "dali::image_processor","message": "Encoding to: jpeg"}
dali_1   | {"timestamp": 1580899024584, "level": "INFO","target": "actix_web::middleware::logger","message": {"remote-addr": "172.20.0.4:46616","status": 200,"content-length": "2270","request-duration": 148.456900,"client-id": "-","x-trace": "-","referer": "-","user-agent": "Actix-web"}}
cargo_1  | test test_get_resized ... ok
dali_1   | {"timestamp": 1580899024621, "level": "DEBUG","target": "dali","message": "Request parameters: ProcessImageRequest { image_address: "http://http/img-test", size: Size { width: None, height: None }, format: Jpeg, quality: 75, watermarks: [], rotation: Some(R270) }"}
dali_1   | {"timestamp": 1580899024621, "level": "DEBUG","target": "dali::commons::http","message": "Fetching image from url http://http/img-test"}
dali_1   | {"timestamp": 1580899024621, "level": "DEBUG","target": "hyper::client::pool","message": "reuse idle connection for ("http", http)"}
dali_1   | {"timestamp": 1580899024621, "level": "DEBUG","target": "hyper::proto::h1::io","message": "flushed 38 bytes"}
dali_1   | {"timestamp": 1580899024624, "level": "DEBUG","target": "hyper::proto::h1::io","message": "read 257 bytes"}
dali_1   | {"timestamp": 1580899024624, "level": "DEBUG","target": "hyper::proto::h1::io","message": "parsed 8 headers"}
dali_1   | {"timestamp": 1580899024624, "level": "DEBUG","target": "hyper::proto::h1::conn","message": "incoming body is content-length (79936 bytes)"}
http_1   | 172.20.0.2 - - [05/Feb/2020:10:37:04 +0000] "GET /img-test HTTP/1.1" 200 79936 "-" "-" "-"
dali_1   | {"timestamp": 1580899024625, "level": "DEBUG","target": "hyper::proto::h1::io","message": "read 65536 bytes"}
dali_1   | {"timestamp": 1580899024625, "level": "DEBUG","target": "hyper::proto::h1::io","message": "read 14400 bytes"}
dali_1   | {"timestamp": 1580899024626, "level": "DEBUG","target": "hyper::proto::h1::conn","message": "incoming body completed"}
dali_1   | {"timestamp": 1580899024626, "level": "DEBUG","target": "hyper::client::pool","message": "pooling idle connection for ("http", http)"}
dali_1   | {"timestamp": 1580899024628, "level": "DEBUG","target": "dali::image_processor","message": "Rotating image to Some(R270)"}
dali_1   | {"timestamp": 1580899024628, "level": "DEBUG","target": "dali::image_processor","message": "Encoding to: jpeg"}
dali_1   |
dali_1   | (dali:1): VIPS-WARNING **: 10:37:04.629: ignoring optimize_scans
dali_1   | {"timestamp": 1580899024698, "level": "DEBUG","target": "hyper::client","message": "client connection error: connection error: timed out"}
dali_1   | {"timestamp": 1580899024699, "level": "DEBUG","target": "hyper::client","message": "client connection error: connection error: timed out"}

And if you wanna check the code: Here I create the connector: https://github.com/olxgroup-oss/dali/blob/master/src/main.rs#L243 Here I use it: https://github.com/olxgroup-oss/dali/blob/master/src/commons/http.rs The calls to fetch the images are here https://github.com/olxgroup-oss/dali/blob/master/src/main.rs#L108

hjr3 commented 4 years ago

Thanks for the code! My guess is that the connector is never getting consumed. I am not sure if it is something I am doing wrong or not. Let me play with this and see if I can resolve the issue.

hjr3 commented 4 years ago

I tried getting this working, but libvips is giving me non-stop problems. My running theory is that web::Data is Arc under the hood, there is a connection that is never explicitly used but that same connection is never dropped. This is the connection that is timing out.

augustocdias commented 4 years ago

I have a feeling that resources are not being properly cleaned by hyper as I getting way too many timeouts in my production application... I still haven't managed to find any proof that it is the case. But this timeouts left me suspicious about this...

hjr3 commented 4 years ago

@augustocdias have you updated to the latest version?

augustocdias commented 4 years ago

I will do it this week and test again

hjr3 commented 3 years ago

Hi @augustocdias,

The hyper v0.14 release is now supported. If you have time, try that and see if the issue persists.

augustocdias commented 3 years ago

Hi. I'm unable to test this as I don't have access to the system that uses it anymore.