Cargo: Downloading can panic with "supplied instant is later than self"

[alexcrichton]

I just saw this happen on CI, where during cargo fetch --locked I saw:

 Downloading crates ...
  Downloaded wat v1.0.12
thread 'main' panicked at 'supplied instant is later than self', src/libstd/time.rs:263:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
error: failed to download from `https://crates.io/api/v1/crates/clicolors-control/1.0.1/download`

Caused by:
  [42] Operation was aborted by an application callback (Callback aborted)

That's very bad!

Unfortunately this is likely going to be notoriously hard to reproduce and try to fix, but I wanted to open an issue at least as a TODO item to try to audit all time-related tracking in the downloading.

[ehuss]

It's not clear from the link which job failed (it looks like they ran again), so I'm not sure which platform this was on. I assume it was one of the Linux builders.

I assume this was triggered by this line.

I don't see how updated_at could be in the future. There is this where it is moved forward, but that shouldn't be more than the amount of time elapsed since it was last updated.

The only other thing I can think of is that CLOCK_MONOTONIC was not monotonic. I know in the (distant) past, vm's tended to be buggy where clocks were concerned, but I don't know what the current state of modern VMs is. I assume GitHub actions uses azure's custom hyper-v? Google doesn't reveal any people reporting issues in recent times, so I would assume that is less likely.

[alexcrichton]

Bah sorry I forgot that perma-linking for github actions builds doesn't actually perma-link. If I see this again I'll try to capture more context, but tbh the only other relevant context at the time was probably the Cargo/rustc version, which probably wasn't going to help all that much.

I agree that the likely-ish culprit is a non-monotonic monotonic clock (oxymoron much?). I believe GH actions uses Azure yeah, though.

I've gone ahead and tried to fix that line at least in https://github.com/rust-lang/cargo/pull/8114 and we can try to collect more info in the future if it shows up again.

[motecshine]

Linux 5.7.19-2-MANJARO

info: removing previous version of component 'rustc'
warning: during uninstall component rustc was not found
info: removing previous version of component 'cargo'
warning: during uninstall component cargo was not found
info: removing previous version of component 'rust-std'
warning: during uninstall component rust-std was not found
info: removing previous version of component 'rust-docs'
warning: during uninstall component rust-docs was not found
info: removing previous version of component 'rustfmt'
warning: during uninstall component rustfmt was not found
info: removing previous version of component 'clippy'
warning: during uninstall component clippy was not found
info: installing component 'rustc'
info: Defaulting to 500.0 MiB unpack ram
 66.5 MiB /  66.5 MiB (100 %)   8.3 MiB/s in  8s ETA:  0s
info: installing component 'cargo'
info: installing component 'rust-std'
thread 'CloseHandle' panicked at 'supplied instant is later than self', src/libstd/time.rs:263:9
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1069
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1504
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:198
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:218
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:515
  11: rust_begin_unwind
             at src/libstd/panicking.rs:419
  12: core::panicking::panic_fmt
             at src/libcore/panicking.rs:111
  13: core::option::expect_failed
             at src/libcore/option.rs:1260
  14: core::option::Option<T>::expect
             at /rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/libcore/option.rs:347
  15: std::time::Instant::duration_since
             at src/libstd/time.rs:263
  16: <std::time::Instant as core::ops::arith::Sub>::sub
             at src/libstd/time.rs:390
  17: std::time::Instant::elapsed
             at src/libstd/time.rs:327
  18: rustup::diskio::perform
  19: <F as threadpool::FnBox>::call_box
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[alexcrichton]

@motecshine that's a backtrace from rustup, not Cargo.

(and this is the Cargo repository, not rustup)