alexcrichton/tokio-curl

Timeout occurs immediately after scheduled in example/two.rs

Closed this issue · 3 comments

wfrisby commented

Using the armv7-unknown-linux-gnueabihf rustc 1.13.0-nightly (1fca1ab0e 2016-09-10)

I get the following error running cargo run --release --example two :

     Running `target/release/examples/two`
thread 'main' panicked at 'timeout done immediately?', src/unix.rs:193
note: Run with `RUST_BACKTRACE=1` for a backtrace.
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PerformError { error: Error { repr: Custom(Custom { kind: Other, error: Error { description: "Failed writing received data to disk/application", code: 23 } }) } }', /buildslave/rust-buildbot/slave/nightly-dist-rustc-cross-host-linux/build/src/libcore/result.rs:783
error: Process didn't exit successfully: `target/release/examples/two` (exit code: 101)

Not sure what to do to prevent the timeout from occurring before it should. This might be an issue in tokio-core timeout.rs poll function.

alexcrichton commented

Thanks for the report! This is somewhat of a legitimate bug, albeit obscure and difficult I think. I wonder though, could you enable logging and see what this debug statement prints? I'm curious what the duration of the timeout is to finish immediately...

wfrisby commented

Here is the output running with RUST_LOG=debug

   Finished release [optimized] target(s) in 0.3 secs
     Running `target/release/examples/two`
DEBUG:tokio_core::reactor: adding a new I/O source
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 13833 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 81468, tv_nsec: 797016504 }
DEBUG:tokio_curl::imp: -------------------------- driver poll start
DEBUG:tokio_curl::imp: executing a new request
DEBUG:tokio_curl::imp: scheduling a new timeout in Duration { secs: 0, nanos: 1000000 }
DEBUG:tokio_core::reactor: added a timeout: 0
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: updating a timeout: 0
DEBUG:tokio_curl::imp: executing a new request
DEBUG:tokio_core::reactor::timeout_token: cancel timeout 0
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: cancel a timeout: 0
DEBUG:tokio_curl::imp: scheduling a new timeout in Duration { secs: 0, nanos: 0 }
DEBUG:tokio_core::reactor: added a timeout: 0
DEBUG:tokio_core::reactor::timeout: When Instant { tv_sec: 81468, tv_nsec: 802309421 } Now Instant { tv_sec: 81468, tv_nsec: 802563004 }
thread 'main' panicked at 'timeout done immediately?', src/unix.rs:193
note: Run with `RUST_BACKTRACE=1` for a backtrace.
DEBUG:tokio_core::reactor::timeout_token: cancel timeout 0
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: cancel a timeout: 0
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_curl::imp:  event cancel 1
DEBUG:tokio_curl::imp:  event cancel 0
DEBUG:tokio_core::reactor: loop process - 2 events, Duration { secs: 0, nanos: 9197666 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 4333 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 81468, tv_nsec: 806687379 }
DEBUG:tokio_core::reactor: loop process - 0 events, Duration { secs: 0, nanos: 709 }

I appears that the duration is being set to 0.

alexcrichton commented

Oh right I forgot the piece of curl documentation where a 0 duration has a special meaning. Will fix!