Encoding error doesn't show up in tutorial example

[khaledkbadr]

In the first example of Tokio's tutorial, the decode function returns an error if it has invalid UTF-8. I hacked the decode function a bit to return that error no matter what, but when I ran the server and simulated the error the connection was dropped (which I surely want) but that error showed up neither in the stderr nor in the response.

I don't really know if it's omitted in the example for simplicity but I went through documentation to find how an answer to how to show that error but couldn't.

[kamyuentse]

Seems this issues related to tokio-io, I think you can get some logs like attempting to decode a frame and attempting to decode a frame if you open the trace level log.

[khaledkbadr]

@kamyuentse nope, I didn't get anything new output using trace level log.

[kamyuentse]

@khaledkbadr Can you provide your code snippet and the current trace level log you got?

[khaledkbadr]

@kamyuentse this is my snippet

main.rs

extern crate bytes;
extern crate futures;
extern crate tokio_io;
extern crate tokio_proto;
extern crate tokio_service;

use tokio_proto::TcpServer;


use std::io;
use std::str;
use bytes::BytesMut;
use tokio_io::codec::{Decoder, Encoder};
use tokio_proto::pipeline::ServerProto;
use tokio_service::Service;
use futures::{future, Future};

struct LineCodec;

impl Decoder for LineCodec {
    type Item = String;
    type Error = io::Error;

    fn decode(&mut self, buf: &mut BytesMut) -> io::Result<Option<String>> {
        if let Some(i) = buf.iter().position(|&b| b == b'\n') {
            // remove the serialized frame from the buffer.
            let line = buf.split_to(i);

            // Also remove the '\n'
            buf.split_to(1);

            // Turn this data into a UTF string and return it in a Frame.
            match str::from_utf8(&line) {
                Ok(_) => Err(io::Error::new(io::ErrorKind::ConnectionAborted, "invalid UTF-8")),
                Err(_) => Err(io::Error::new(io::ErrorKind::Other, "invalid UTF-8")),
            }
        } else {
            Ok(None)
        }
    }
}

impl Encoder for LineCodec {
    type Item = String;
    type Error = io::Error;

    fn encode(&mut self, msg: String, buf: &mut BytesMut) -> io::Result<()> {
        buf.extend(msg.as_bytes());
        buf.extend(b"\n");
        Ok(())
    }
}


struct LineProto;

use tokio_io::{AsyncRead, AsyncWrite};
use tokio_io::codec::Framed;

impl<T: AsyncRead + AsyncWrite + 'static> ServerProto<T> for LineProto {
    // For this protocol style, `Request` matches the `Item` type of the codec's `Decoder`
    type Request = String;

    // For this protocol style, `Response` matches the `Item` type of the codec's `Encoder`
    type Response = String;

    // A bit of boilerplate to hook in the codec:
    type Transport = Framed<T, LineCodec>;
    type BindTransport = Result<Self::Transport, io::Error>;
    fn bind_transport(&self, io: T) -> Self::BindTransport {
        Ok(io.framed(LineCodec))
    }
}

struct Echo;

impl Service for Echo {
    // These types must match the corresponding protocol types:
    type Request = String;
    type Response = String;

    // For non-streaming protocols, service errors are always io::Error
    type Error = io::Error;

    // The future for computing the response; box it for simplicity.
    type Future = Box<Future<Item = Self::Response, Error =  Self::Error>>;

    // Produce a future for computing a response from a request.
    fn call(&self, req: Self::Request) -> Self::Future {
        // In this case, the response is immediate.
        Box::new(future::ok(req))
    }
}

fn main() {
    // Specify the localhost address
    let addr = "0.0.0.0:12345".parse().unwrap();

    // The builder requires a protocol and an address
    let server = TcpServer::new(LineProto, addr);

    // We provide a way to *instantiate* the service for each new
    // connection; here, we just immediately return a new instance.
    server.serve(|| Ok(Echo));
}

But when I run the app with RUST_LOG=trace cargo run; which I think is how to set log level to trace; I get nothing when sending the requests.

[kamyuentse]

Guide to enable logger:

• Add this line pretty_env_logger = "0.1" to your Cargo.toml under [dependencies] entry
• Add extern crate pretty_env_logger; to main.rs
• Finally, add pretty_env_logger::init().unwrap(); at the begining of main function then run again

[khaledkbadr]

This is the logs result when I made the request that returned the error

DEBUG:tokio_core::reactor                       : loop poll - Duration { secs: 6, nanos: 939381975 }
DEBUG:tokio_core::reactor                       : loop time - Instant { tv_sec: 8464, tv_nsec: 677245678 }
TRACE:tokio_core::reactor                       : event Readable | Writable Token(4)
DEBUG:tokio_core::reactor                       : notifying a task handle
DEBUG:tokio_core::reactor                       : loop process - 1 events, Duration { secs: 0, nanos: 417173 }
DEBUG:tokio_core::reactor                       : loop poll - Duration { secs: 0, nanos: 48439 }
DEBUG:tokio_core::reactor                       : loop time - Instant { tv_sec: 8464, tv_nsec: 677776873 }
TRACE:tokio_core::reactor                       : event Readable Token(3)
TRACE:tokio_proto::streaming::pipeline::advanced: Pipeline::tick
TRACE:tokio_io::framed_read                     : attempting to decode a frame
DEBUG:tokio_core::reactor                       : loop process - 1 events, Duration { secs: 0, nanos: 680599 }
DEBUG:tokio_core::reactor                       : loop poll - Duration { secs: 0, nanos: 39568 }
DEBUG:tokio_core::reactor                       : loop time - Instant { tv_sec: 8464, tv_nsec: 678582855 }
TRACE:tokio_core::reactor                       : event Readable Token(0)
DEBUG:tokio_core::reactor                       : consuming notification queue
DEBUG:tokio_core::reactor                       : dropping I/O source: 1
DEBUG:tokio_core::reactor                       : loop process - 1 events, Duration { secs: 0, nanos: 378371 }
DEBUG:tokio_core::reactor                       : loop poll - Duration { secs: 0, nanos: 27528 }
DEBUG:tokio_core::reactor                       : loop time - Instant { tv_sec: 8464, tv_nsec: 679084894 }
DEBUG:tokio_core::reactor                       : loop process - 0 events, Duration { secs: 0, nanos: 107200 }

[kamyuentse]

Notice those lines: TRACE:tokio_io::framed_read : attempting to decode a frame

If succeed in decoding something, you can see the following pair:

TRACE:tokio_io::framed_read                     : attempting to decode a frame
...
TRACE:tokio_io::framed_read                     : frame decoded from buffer

Refer https://github.com/tokio-rs/tokio-io/blob/master/src/framed_read.rs#L274 for more detail.

[khaledkbadr]

yup, I reached the same point debugging. And it didn't reach the second trace frame decoded from buffer meaning there was an error alright. Actually, I'm suspecting

fn bind_transport(&self, io: T) -> Self::BindTransport {
        Ok(io.framed(LineCodec))
    }

It always returns an Ok

[kamyuentse]

If you return an error in decode function, the connection would be closed silently. So, for now, what is your problem?

[khaledkbadr]

the silently part, shouldn't it log the error message or return it. Or should I change something to allow that to happen?

[kamyuentse]

In my opinion, if your decode function returns an error, that means your server got into trouble when handling this request, I think closing the connection is right behavior.

If you want to keep the incoming bytes, I think you can buffer them (do not consume those bytes in buf: &mut BytesMutor create your own buffer area), then return a Ok(None) instead.

[khaledkbadr]

no no, I agree with you. it should close the connection alright (which I want). but in the example, the decode method returns an error with message Err(io::Error::new(io::ErrorKind::Other, "invalid UTF-8")), hence I was under the impression that along with closing the connection, I'd see invalid UTF-8 somewhere.

[kamyuentse]

You can add error!(".....") in your decode() function.

cc @alexcrichton

Should we add error!("....") in tokio-io::framed_read to log this error?

[alexcrichton]

Thanks for the report! Unfortunately I believe this is a bug with tokio-proto which at the framing level currently drops some errors on the floor. Is there an isolated tokio-core/tokio-io example though that exhibits this behavior?