sometimes feature=full fails to read from socket

[ultrasaurus]

Version

cargo tree | grep tokio

└── tokio v0.2.6
    └── tokio-macros v0.2.1

Platform

$ uname -a
Darwin newair.local 18.7.0 Darwin Kernel Version 18.7.0: Sun Dec  1 18:59:03 PST 2019; root:xnu-4903.278.19~1/RELEASE_X86_64 x86_64 i386 MacBookAir8,1 Darwi

Description

I wrote a minimal app to test deploying on heroku. It works fine with features = ["full"] but if I specify a list of features, then it doesn't respond to listener.accept()

I think this happened when I added tokio::spawn to handle processing multiple sockets concurrently. The full app is here

Here's the core part of the code which I think isn't working:

#[tokio::main]
async fn main() {
    // Get the port number to listen on (required for heroku deployment).
    let port = env::var("PORT").unwrap_or_else(|_| "1234".to_string());

    let addr = format!("0.0.0.0:{}", port);
    let mut listener = TcpListener::bind(addr).await.unwrap();

    loop {
        println!("listening on port {}...", port);
        let result = listener.accept().await;
        match result {
            Err(e) => println!("listen.accept() failed, err: {:?}", e),
            Ok(listen) => {
                let (socket, addr) = listen;
                println!("socket connection accepted, {}", addr);
                // Process each socket concurrently.
                tokio::spawn(process_socket(socket));
            }
        }
    }
}

I can't repro the issue locally, but on heroku I get a timeout on the second socket connection:

2020-01-05T02:51:45.419982+00:00 app[web.1]: listening on port 11513...
2020-01-05T02:51:47.203983+00:00 heroku[web.1]: State changed from starting to up
2020-01-05T02:51:47.153785+00:00 app[web.1]: socket connection accepted, 10.63.79.21:59580
2020-01-05T02:51:47.153817+00:00 app[web.1]: listening on port 11513...
2020-01-05T02:52:24.000000+00:00 app[api]: Build succeeded
2020-01-05T02:52:25.409190+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/" host=peaceful-gorge-05620.herokuapp.com request_id=4edaf94c-7277-4818-8b6c-6fa2c7bf9b7a fwd="69.181.194.59" dyno=web.1 connect=0ms service=30001ms status=503 bytes=0 protocol=https

Locally it works fine. (I know this is not an optimal HTTP server, just trying to demonstrate a very simple/stupid HTTP request/response without additional crates and as few tokio features as possible.)

[ultrasaurus]

FYI: changed the original line:

tokio::spawn(async move { process_socket(socket).await });

to simpler:

tokio::spawn(process_socket(socket))

which didn't make a difference -- still works locally and on heroku with features=full

but with current Cargo.toml:

features = ["tcp", "dns", "macros", "io-util"]

it works locally and the request times out on heroku as describe above

[ultrasaurus]

There's a bug in async fn process_socket....

    loop {
        result = buffed_socket.read_line(&mut request).await;

        if let Ok(num_bytes) = result {
            if num_bytes > 0 {
                if request.len() >= 4 {
                    let end_chars = &request[request.len() - 4..];
                    if end_chars == "\r\n\r\n" {
                        break;
                    };
                }
            }
        }
    }

num_bytes == 0 signals that the socket is closed. The loop should break, but it doesn't. On Heroku, when the app starts up, there is a socket connection which is closed with no bytes written and the second request times out because .await doesn't give up time to the scheduler for a completed future.

The other unexpected tokio behavior is that feature=full makes it so tokio uses threads -- would be good if there was no change in behavior just by turning features on and off.

[Darksonn]

Forgetting to handle the read-zero bytes case is a common failure case, but I'm not quite sure we can do much more than we are doing now.