panic related to timeout - repeat of #2

[donhcd]

I'm getting an intermittent panic here: https://github.com/tokio-rs/tokio-curl/blob/a5788cd2079b873ce0938fca59f5e1affa9208b6/src/unix.rs#L204

I was getting the panic mentioned in #2 when I was using the crates.io dependency, so I switched to master's sha but it seems like I'm still hitting the same (or similar) case.

I'll try enabling logging and see if I can repro, but I wanted to give a heads up about this

[alexcrichton]

Thanks for the report!

Can you get a log of a failure with RUST_LOG=debug?

[FoundOne]

I have the same problem. RUST_LOG=debug gives nothing more than:

.thread 'main' panicked at 'timeout done immediately?', /home/dwolf/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-curl-0.1.0/src/unix.rs:193
note: Run with `RUST_BACKTRACE=1` for a backtrace.

RUST_BACKTRACE=1 gives me this: https://gist.github.com/FoundOne/9b50c819fc6a6c23523142d73dbdcc86#file-tokio_curl_backtrace-txt

[alexcrichton]

@FoundOne oh you may have to set up the env_logger crate in your project with env_logger::init, then perhaps the logs will come out?

I'd also recommend using the git master version of this crate which has the fix for #2. I'll be sure to make a release after this is fixed.

[donhcd]

@alexcrichton unfortunately so far I haven't been able to repro this panic... a coworker got it yesterday at .cargo/git/checkouts/tokio-curl-54e764422eb98a95/a5788cd/src/unix.rs:204 so he definitely had the git master version. Here is the backtrace for that panic if that's of any use... I turned on logging for tokio-curl and tokio-core and asked him to do the same, but AFAIK neither of us has encountered this since ☹️

[FoundOne]

With the git master version it just hangs out and the debug output looks like this:

     Running `target/debug/curl_check`
DEBUG:tokio_core::reactor: adding a new I/O source
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 21295 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 794523, tv_nsec: 185292589 }
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: 0 }
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_curl::imp:  event cancel 0
DEBUG:tokio_curl::imp: timeout fired
DEBUG:tokio_curl::imp: scheduling a new timeout in Duration { secs: 0, nanos: 0 }
DEBUG:tokio_core::reactor: loop process - 2 events, Duration { secs: 0, nanos: 262366 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 5198 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 794523, tv_nsec: 185579441 }
DEBUG:tokio_core::reactor: loop process - 0 events, Duration { secs: 0, nanos: 1052 }

Edit: btw the program is just the example from the documentation.

[donhcd]

@FoundOne what do you mean by "hangs out"? Is your program hanging?

[FoundOne]

@donhcd Yes. It just stays and does nothing.

[alexcrichton]

@donhcd hm is there perhaps a small gist of what's going on to reproduce this I could try out locally? Also, what platform are you on?

@FoundOne could you gist the program you're compiling there? Also, what platform are you on as well?

[FoundOne]

I'm on Arch Linux x86_64 hybrid. Here is the gist of the program: https://gist.github.com/FoundOne/470766d266eed5ead5908e6cacb7991a#file-main-rs

[alexcrichton]

hm, @FoundOne could you try bumping the log level up to RUST_LOG=trace and see what it prints when it hangs?

[FoundOne]

That's the output from RUST_LOG=trace RUST_BACKTRACE=1 https://gist.github.com/FoundOne/26579a679bc20e87bcbf17d605bab32e#file-debug_trace-txt

[donhcd]

@alexcrichton I have a bunch of code surrounding where I use tokio-curl, but the gist of it is pretty much identical to your test. I think the only difference is that it runs on another thread.

My coworker got the panic on the latest OSX (10.12 sierra)

[alexcrichton]

Hm let's perhaps try another angle, what version of libcurl is being used? Is the system library coming into play, and in case what version? If not, is the bundled libcurl getting compiled and being used?

[FoundOne]

The curl library is libcurl.so.4.4.0 (pacman says curl 7.50.3-1 about curl) and the crate is v0.3.7. I tried just the curl crate yesterday and it worked. Here is the list of all dependancies compiled.

   Compiling winapi v0.2.8
   Compiling log v0.3.6
   Compiling regex-syntax v0.3.5
   Compiling winapi-build v0.1.1
   Compiling void v1.0.2
   Compiling slab v0.3.0
   Compiling lazycell v0.4.0
   Compiling scoped-tls v0.1.0
   Compiling utf8-ranges v0.1.3
   Compiling pkg-config v0.3.8
   Compiling bitflags v0.4.0
   Compiling libc v0.2.16
   Compiling semver v0.1.20
   Compiling gcc v0.3.35
   Compiling kernel32-sys v0.2.2
   Compiling futures v0.1.2
   Compiling cfg-if v0.1.0
   Compiling openssl-sys v0.7.17
   Compiling libz-sys v1.0.6
   Compiling curl-sys v0.2.3
   Compiling rustc_version v0.1.7
   Compiling memchr v0.1.11
   Compiling thread-id v2.0.0
   Compiling thread_local v0.2.7
   Compiling aho-corasick v0.5.3
   Compiling nix v0.6.0
   Compiling net2 v0.2.26
   Compiling curl v0.3.7
   Compiling regex v0.1.77
   Compiling mio v0.6.0
   Compiling tokio-core v0.1.0
   Compiling tokio-curl v0.1.0 (https://github.com/tokio-rs/tokio-curl.git#a5788cd2)
   Compiling env_logger v0.3.5

[alexcrichton]

gah I have no idea why I can't reproduce this :(

@FoundOne did you ever get env_logger to work with RUST_LOG=trace output?

[FoundOne]

@alexcrichton this is the only output from RUST_LOG=trace and it gives "TRACE:" mesages. I made some tests. It's doing 0 seconds timeout for some reason. I'm still seraching for the problem. It's strange that the event loop continues.

[alexcrichton]

The 0 second timeouts are expected as they're curl's way of saying "inform me of a timeout ASAP", so those are at least expected.

Out of curiosity, does this patch help at all?

[FoundOne]

It works. Thank you!

[donhcd]

@alexcrichton seems like I'm encountering the same bug on 0.1.2... I didn't have the tokio_curl=trace set at the time though. I'd guess that perhaps turning on the logging reduces the chances of the panic occurring?

backtrace

I'm on osx 10.11.5, with the curl crate at 0.3.7 and the curl-sys crate at 0.2.3. I'm not sure whether the bundled version of libcurl is being used, but curl-config --version gives me libcurl 7.43.0

in the meantime I've switched tokio-curl tracing back on but I'm not sure if I'll be able to repro with it on

[alexcrichton]

@donhcd if you apply this patch does it work for you? Note that that may have a chance to busy wait, so you may want to also check to ensure the CPU usage isn't too high.

[donhcd]

@alexcrichton thanks! I'll try applying it and removing logging and seeing if there are issues. unfortunately I seem to be hitting that case quite rarely, so I can only confidently say if that patch doesn't work

[alexcrichton]

Ok, I've pushed that to master and I'll try to deal with #5 before publishing.