Sometimes the worker will panic with "specified instant was later than self"

[dylanede]

The trace points to

tokio-timer/src/worker.rs

Line 170 in c944a24

thread::park_timeout(next - now);

This only happens very occasionally, but it's enough to be a serious problem for a company internal tool I'm in the process of writing. This tool implements a protocol on top of UDP, and it uses Sleeps to wait between resending packets while waiting for ACKs. The time being slept for is 500ms, and there may be many sleeps happening at once.

Other than this problem, futures-rs and the tokio ecosystem have been great to work with!

Full trace for the thread is

thread '<unnamed>' panicked at 'specified instant was later than self', ../src/libcore\option.rs:705
stack backtrace:
   0:        0x13fb85dba - std::panicking::default_hook::{{closure}}
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:252
   1:        0x13fb852c6 - std::panicking::default_hook
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:263
   2:        0x13fb88c9d - std::panicking::rust_panic_with_hook
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:451
   3:        0x13fb88b38 - std::panicking::begin_panic<collections::string::String>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:413
   4:        0x13fb88a54 - std::panicking::begin_panic_fmt
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:397
   5:        0x13fb889e9 - std::panicking::rust_begin_panic
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:373
   6:        0x13fb8db27 - core::panicking::panic_fmt
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libcore\panicking.rs:69
   7:        0x13fb8db8f - core::option::expect_failed
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libcore\option.rs:705
   8:        0x13fb8088c - std::time::Instant::duration_since
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\time\mod.rs:144
   9:        0x13fb80aba - std::time::{{impl}}::sub
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\time\mod.rs:208
  10:        0x13fa889f4 - tokio_timer::worker::run
                        at C:\Users\DEde\.cargo\git\checkouts\tokio-timer-d282e7d6c658dca8\4acaed628ec796350490fe36ed16169a3bb1e143\src\worker.rs:170
  11:        0x13fa87004 - tokio_timer::worker::{{impl}}::spawn::{{closure}}
                        at C:\Users\DEde\.cargo\git\checkouts\tokio-timer-d282e7d6c658dca8\4acaed628ec796350490fe36ed16169a3bb1e143\src\worker.rs:64
  12:        0x13fa7f88e - std::panic::{{impl}}::call_once<(),closure>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panic.rs:295
  13:        0x13fa78137 - std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:356
  14:        0x13fb89af1 - panic_unwind::__rust_maybe_catch_panic
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libpanic_unwind\lib.rs:97
  15:        0x13fa77cb2 - std::panicking::try<(),std::panic::AssertUnwindSafe<closure>>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panicking.rs:332
  16:        0x13fa76a2b - std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\panic.rs:351
  17:        0x13fa7783d - std::thread::{{impl}}::spawn::{{closure}}<closure,()>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\thread\mod.rs:287
  18:        0x13fa7c2cf - alloc::boxed::{{impl}}::call_box<(),closure>
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\liballoc\boxed.rs:595
  19:        0x13fb8380e - std::sys::imp::thread::{{impl}}::new::thread_start
                        at C:\bot\slave\nightly-dist-rustc-win-msvc-64\build\src\libstd\sys\windows\thread.rs:50
  20:         0x770f59cc - BaseThreadInitThunk

[46bit]

@dylanede Have you debugged this further? I'm thinking of using tokio-timer but this issue being outstanding worries me.

stdlib promises that this panic will only occur if line 170 next is earlier than now.

It looks like next_timeout is variable time and makes no strict protections against this case. It does however print the relevant instants. We can use env_logger to print those debug! to stdout.

I'm going to use this and try to provoke the panic. I'm not entirely sure what to do if I prove the above as the problem but there are some obvious choices.

[carllerche]

I'm going to look at this some now.

[carllerche]

Ok, it looks like there should be a guard there to prevent going negative... should be a simple fix.

[carllerche]

This should be fixed by c933447. Sorry for the delay.