last day (19 days later) » 

11:05 AM
1
Q: Why does tokio::io::read returns 0 if there is still data to read from the stream?

NickI have a TCP server and multiple TCP clients written in Rust that use tokio for asynchronous networking. The goal of what I am trying to do is to Send a request from the client to the server to download a file. The server will send back the (file size and the) file content. The code in the se...

 
Before going any further - how are you checking for success/failure? "Close to 10MB" isn't a very descriptive test.
 
@SébastienRenauld after reading the file data in the client I expect few more data from the server that indicates that the file download has been completed successfully, but reading from the stream returns no further data so the request is not successful, in which case my HTTP server running these futures will return a 500 instead of a 200. Besides, I can also check the logs printed by the client with the value of the accumulator (that when it fails is lower than 10MB). Please let me know if I am been clear.
 
The 500 will most likely indicate that the Future returned with an error, not an Ok(0). That's where you should be digging first, not tokio::io::read itself. Plan some suitable breakpoints, put a recover_with() on the loop so you can catch and recover the error, and edit your question when you have more info as to what is happening.
 
@SébastienRenauld the 500 is a value that I return following the tokio::io::read not returning the data that I am expecting. Moreover, I log each possible read error in read.map_err(...), as well in any other possible future, but no error is ever raised.
 
I've just spent 5 minutes setting up every possible failure case except spurious file descriptor closes and cannot replicate your issue (I was testing on a 5.5GB file); as such, it leads me to believe it isn't due to tokio::io::read (your usage of it is sane) but something else either in your application, or at the OS level, messing with file descriptors.
 
11:05 AM
@SébastienRenauld could you list such every possible failure case so that it would be easier for me to check if any of these is actually the reason of the failure? Especially because I don't get any error in the server, as well as in the client, the only issue is that read returns 0 when it shouldn't. I tried in different machines with Ubuntu, and the behavior is always the same.
 
Hold up for a second. I'm re-reading your code; this is happening on the client and it's a TcpStream
This is seriously puzzling, actually; it's... Wait up.
Your file is 10MB, yeah?
 
Yes, 10Mb
but I tested it with several different sizes and the behavior is always the same
for example now with a 20MB file I 'am seeing fs::get] WRONG SIZE 19991966 and similar other logs, with sizes very close to the 20MB
 
Can you run a little experiment on the server?
 
Sure
 
if you have access to the TcpStream, call set_nodelay(true) on it
that'll disable packet bunching and immediately send each packet
I want to see if that has any effect on the error rate
if it does, then it's your underlying OS playing tricks on you
 
11:12 AM
Ok, I'm going to try, is it when right after I get the TcpStream or just before the tokio::io::copy?
 
The moment you get the TcpStream for the client
so, before the copy
it returns Result<()>, which you don't particularly care about
 
ok let me try
 
I'm getting more and more convinced what you're getting is a broken pipe
since it materializes as Async::Ready(0)
 
unfortunately sometimes it still happens
 
Does it happen less, though?
 
11:15 AM
I have the feeling something improved though
 
but it's just a feeling
 
We're on the right track
So this means that the socket isn't being flushed
that's literally what it is
 
I was thinking the same, like I would need to flush manually
 
you can't with copy since it consumes your streams
 
11:17 AM
do you know if there's another way to do it?
no wait, I still have the stream after copy
it's one of the item in the tuple returned
(stream, buffer, size)
 
Not on the server side you don't
the problem is server-side, not client-side
 
yes, I'm talking server side
 
Wait, you do?
Thinking face
 
the copy is on the server copy(file, stream)
 
Okay then, poll_flush on it when you're done
 
11:19 AM
while the client read(stream buffer)
 
and this should massively reduce your errors
 
how do I use it?
I see it returns an Async not a Future
should I just try it once and see?
 
I'm trying to find how to call the actual flush in tokio, it's been ages since I had to deal with this
 
yup
that'd work
 
11:22 AM
ok let me try
no same error rate :(
 
Huh.
So nagle reduces it, but flushing doesn't
 
and as usual all the sizes I get are very close 19993877, 19997973 etc
 
and it's just raw tokio::io TcpStreams, yeah?
nothing in between
 
yes, the communication between client and server it's done just using tokio streams
in particular for the file data
 
And you're not closing the process the moment you're done - correct?
as in, you keep listening server-side
 
11:27 AM
yes, the server is always running ready for future connections
also the connections are handled sequentially in the server
and the stranger thing is that both client and server don't raise any error at all
 
Is everything running locally?
 
yes
the address is also localhost
for server and client connections
 
And the OS is...?
if it's not linux I won't be able to assist any further, as I know next to nothing about MacOS internals and windows is very fucky on sockets
 
it's linux
I'm on Ubuntu
is there a way to know if it's a problem with the socket?
such as the socket was closed for any other reason? but it is weird that it always fails when very close to the whole file data..
 
it's not an erroneous closure, you'd be getting an error otherwise
so it's the rust side closing it but then the OS "forgetting" about some of the data
that's why I asked you if you were immediately shutting the process down after sending the data
 
11:35 AM
I see
just so you have an idea
```100 19.0M 0 19.0M 0 0 238M 0 --:--:-- --:--:-- --:--:-- 238M
100 77 100 77 0 0 652 0 --:--:-- --:--:-- --:--:-- 652
100 77 100 77 0 0 435 0 --:--:-- --:--:-- --:--:-- 435
100 19.0M 0 19.0M 0 0 71.7M 0 --:--:-- --:--:-- --:--:-- 71.7M
100 19.0M 0 19.0M 0 0 56.2M 0 --:--:-- --:--:-- --:--:-- 56.2M
100 19.0M 0 19.0M 0 0 46.1M 0 --:--:-- --:--:-- --:--:-- 46.0M
100 19.0M 0 19.0M 0 0 39.0M 0 --:--:-- --:--:-- --:--:-- 39.0M
this is an example
where you see 77 instead of 19MB there was an error
(using curl as a client to the http server)
do you have any other idea on why this could happen?
 
there's plenty of possibilities tbh
 
maybe we can go by exclusion then
 
This question is worth a read: stackoverflow.com/questions/10249677/…
reducing the Nagle window to 0 helped so it's definitely in the right direction
Tell you what
Do you have 20MB of RAM to spare?
if so, set your exact file length
use read_exact() with a large enough buffer
and see if the errors go to 0
 
I have just for the purpose of testing if that's what you mean
but if it goes to 0 what would we know?
 
If errors go to 0 then the client side is at fault
if the errors remain then the server side is at fault
since by doing this the client side knows exactly how many bytes to read
 
11:48 AM
ok will have a try, but I have a feeling it's a client issue
 
That'll allow us to know where to dig
:-)
Debugging is often not about knowledge but about fact-finding and limiting the scope of failure
 
so
now instead of read = 0 I get a different error
ERROR Io { message: "early eof", kind: UnexpectedEof }
not always as usual
some of the times it succeeds
and this time is a real error I can log in map_err after read_exact
 
Okay
So it's server-side
I need to pop out for a couple of hours; will be back in a bit and we can continue this
can you try replacing the copy and doing it explicitly?
i.e. read -> write loop
so you can check if it's a problem with you reading the source file
or you writing to the socket
 
ok I will have to leave, but I'll continue later in the evening thanks for your help! The server side for this is very simple now (I'll show you), but I'll try to do it manually, as I would like to avoid having to re-implement tokio::io::copy
```tokio::fs::File::open(path)
.and_then(move |file| {
tokio::io::copy(file, stream).map(move |(n, _, stream)| {
stream
})
.and_then(|stream| {
tokio::io::flush(stream)
})
})```
plese let me know if you spot any error, and text you later
 
 
4 hours later…
3:52 PM
I tried to setup a minimal example to reproduce the issue with server and client
use failure::Error;
use futures::future::Future;
use futures::stream::Stream;
use std::net::{IpAddr, Ipv4Addr, SocketAddr};
use std::path::PathBuf;
use tokio::net::{TcpListener, TcpStream};

fn main() -> Result<(), Error> {
env_logger::init();
log::info!("TCP server");

let localhost = SocketAddr::new(IpAddr::V4(Ipv4Addr::LOCALHOST), 55555);
let listener = TcpListener::bind(&localhost)?
.incoming()
.map_err(Error::from)
.for_each(|stream| {
log::info!("Accepted connection from: {:?}", stream.peer_addr());
and this is the client
use futures::future::Future;
use futures::lazy;
use std::net::{IpAddr, Ipv4Addr, SocketAddr};
use tokio::io::read_exact;
use tokio::net::TcpStream;

fn main() {
env_logger::init();
log::info!("TCP client");

tokio::run(lazy(|| {
for _ in 0..10 {
tokio::spawn(client());
}
Ok(())
}))
}

fn client() -> impl Future<Item = (), Error = ()> {
let localhost = SocketAddr::new(IpAddr::V4(Ipv4Addr::LOCALHOST), 55555);
log::info!("Client connecting");
TcpStream::connect(&localhost)
.and_then(|stream| {
log::info!("Client connected");
but obviously it works without any issue
I can't say why the other one has the problems I described..
 
4:24 PM
So, I made more tests and it look like setting no_delat to true actually improves
with 100 concurrent client requests, with 20MB files if no delay is false I get over 5 tries a number of failures equal to 13, 10, 13, 15, 9 (/100)
while with no delay set to true I get 5, 9, 9, 4, 3 (/100) failures
 
Hold on
100 concurrent client requests
that's 400 pipes
i.e. 400 open file descriptors
 
that was just for this specific tests
 
is the box being used for anything else?
if so, you could be running into socket exhaustion
 
it usually fails with 5 concurrent requests
I confirm that even with 5 concurrent requests and no_delay true it may fail
the box you mean my host machine?
(these tests were made by keeping the read_exact call)
besides, even if I send the request sequentially it still fails with the same error
with error rate similar to when no_delay is set to false for sequential requests..
more info, if I add a sleep 0.5 after every sequential request I get 0 errors
that would let me think that there is no error in the logic of my program, but it something else
what do you think?
(almost 0 errors)
 
4:46 PM
Oh, I had zero doubts it was something else
can you check TCP parameters on the box?
i.e. TCP socket reuse, TCP socket recycle, current socket count etc
I suspect you have TCP socket recycle turned on and that's causing linux to just drop sockets actively in use
 
how can I do that?
let me google it
is there a command or is it by using a Rust method?
 
 
2 hours later…
6:58 PM
it's linux kernel parameters
you'll find it in /sys or /proc if procfs is mounted @Nick
sysctl should also tell you it
 

  last day (19 days later) »