search

seanmonstar / reqwest

An easy and powerful Rust HTTP Client
https://docs.rs/reqwest
Apache License 2.0
9.74k stars 1.09k forks source link

Program is stuck after calling .text() on Response in WSL 2 #1604

Open Tobias-Scholz opened 2 years ago

Tobias-Scholz commented 2 years ago

The following issue seems to only be reproducable in WSL 2 (Ubuntu 20.04).

Rust version: 1.63.0

cargo.toml

[dependencies]
reqwest = { version = "0.11", features = ["json"] }
tokio = { version = "1", features = ["full"] }

main.rs

#[tokio::main]
async fn main() {
    println!("Start");

    let url = "https://query1.finance.yahoo.com/v7/finance/download/MSF.DE?period1=0&period2=1660519459&interval=1d&events=history";
    let response = reqwest::get(url).await.unwrap();
    println!("Response finished");

    let response = response.text().await.unwrap();
    println!("{:?}", response); // The program never reaches this point
}

Output:

Start
Response finished

The last println!() never executes and there is no panic.

Further information:

I also enabled the RUST_LOG=debug logging. This is the only output I am seeing:

[2022-08-15T01:13:51Z DEBUG reqwest::connect] starting new connection: https://query1.finance.yahoo.com/
[2022-08-15T01:13:51Z DEBUG reqwest::async_impl::client] response '200 OK' for https://query1.finance.yahoo.com/v7/finance/download/MSF.DE?period1=0&period2=1660519459&interval=1d&events=history
seanmonstar commented 2 years ago

Does the response text ever end? Or does it just download more text forever (normally)? What if you stream the body in chunks?

Tobias-Scholz commented 2 years ago

@seanmonstar - The response body has a finite length. When doing a curl request, you will get the whole response at once.

I just tried using the .chunks() method and it actually returns some data now.

while let Some(chunk) = response.chunk().await.unwrap() {
    println!("Chunk: {:?}", chunk);
}

println!("finished");

But, it stops execution at around 15% of the data. The last record I can see in the logs is 2010-06-02,14.670000,14.670000,14.670000,14.670000,10.741135, and the rest is missing. Also note that the println!("finished") is not printed so it still gets stuck somewhere.

ensc commented 2 years ago

I am seeing a similar behaviour; epoll_wait() does not return although data is available. Smells like a linux kernel bug with edge triggered epoll (here: kernel 5.18.13).

E.g.

17:07:34.032095 epoll_ctl(5<anon_inode:[eventpoll]>, EPOLL_CTL_ADD, 8<TCP:[138895589]>, {events=EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, data={u32=100663298, u64=100663298}}) = 0

17:07:34.034879 writev(8<TCP:[138895589]>, [{iov_base="GET "..., iov_len=122}], 1) = 122
17:07:34.035374 epoll_wait(3<anon_inode:[eventpoll]>, [{events=EPOLLIN|EPOLLOUT, data={u32=100663298, u64=100663298}}], 1024, -1) = 1
17:07:34.035557 recvfrom(8<TCP:[138895589]>, "HTTP"..., 8192, 0, NULL, NULL) = 8192
17:07:34.036444 recvfrom(8<TCP:[138895589]>, "\355Ca\277"..., 16384, 0, NULL, NULL) = 16384
17:07:34.036962 epoll_wait(3<anon_inode:[eventpoll]>, [{events=EPOLLIN|EPOLLOUT, data={u32=100663298, u64=100663298}}, {events=EPOLLIN|EPOLLOUT, data={u32=100663297, u64=100663297}}, {events=EPOLLIN, data={u32=2147483648, u64=2147483648}}], 1024, 2960) = 3

...

17:07:34.042521 recvfrom(7<UDPv6:[138895588]>, "\0\4\0.", ...) = 4
17:07:34.042639 recvfrom(7<UDPv6:[138895588]>, "\0\4\0/", ...) = 4

### A: reqwest chunk() call
17:07:34.042754 recvfrom(8<TCP:[138895589]>, "L\3639C"..., 32768, 0, NULL, NULL) = 8382
17:07:34.043340 recvfrom(7<UDPv6:[138895588]>, "\0\4\0000", ...) = 4
17:07:34.043466 recvfrom(7<UDPv6:[138895588]>, "\0\4\0001", ...) = 4
... more fd 7 related traffic
17:07:34.045128 recvfrom(7<UDPv6:[138895588]>, "\0\4\0?", ...) = 4
17:07:34.045246 recvfrom(7<UDPv6:[138895588]>, "\0\4\0@", ...) = 4

### B: reqwest chunk() call
17:07:34.045341 recvfrom(8<TCP:[138895589]>, 0x5633a0d32de0, 49152, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
17:07:34.045841 epoll_wait(3<anon_inode:[eventpoll]>, [{events=EPOLLOUT, data={u32=100663297, u64=100663297}}], 1024, -1) = 1   ### related to traffic on fd 7
17:07:34.045873 epoll_wait(3<anon_inode:[eventpoll]>,

### ------->  timeout timer (related to fd 7 traffic)

[{events=EPOLLIN|EPOLLOUT, data={u32=100663298, u64=100663298}}], 1024, -1) = 1

### C: reqwest chunk() call
17:07:39.031351 recvfrom(8<TCP:[138895589]>, "\344\217\vB"..., 49152, 0, NULL, NULL) = 32522
17:07:39.032401 recvfrom(7<UDPv6:[138895588]>, "\0\4\0A", ...) = 4
17:07:39.032692 recvfrom(7<UDPv6:[138895588]>, "\0\4\0B", ...) = 4

There is an tokio::time::timeout() of 5 seconds (related to fd 7 traffic) which recovers the reqwest http transfer between "B" and "C".

The other site (busybox httpd) runs on the same host and sends data with sendfile().

17:50:10.285978 write(1, "HTTP/1.1 2"..., 190) = 190
17:50:10.286033 sendfile(1, 3, [0] => [65536], 9223372036854710272) = 65536
17:50:10.286104 sendfile(1, 3, [65536], 9223372036854710271) = 0
17:50:10.286127 shutdown(1, SHUT_WR) = 0
17:50:10.286157 exit_group(0) = ?

(I ran this later, but relation of timestamps is always the same: server sends data within <100ms but client goes in a 5 seconds timeout).

ensc commented 2 years ago

my problem seems to be caused by slirp4netns (rootless containers, https://github.com/rootless-containers/slirp4netns/issues/302)