Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Instant::elapsed() fails unexpectedly in metrics. #2428

Closed
peilun-conflux opened this issue Feb 16, 2022 · 0 comments · Fixed by #2429
Closed

Instant::elapsed() fails unexpectedly in metrics. #2428

peilun-conflux opened this issue Feb 16, 2022 · 0 comments · Fixed by #2429

Comments

@peilun-conflux
Copy link
Contributor

The backtrace is as follows

thread 'network_eventloop' panicked at 'supplied instant is later than self', library/std/src/time.rs:281:48
stack backtrace:
   0:     0x5645b3db32f0 - std::backtrace_rs::backtrace::libunwind::trace::ha0ad43e8a952bfe7
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
   1:     0x5645b3db32f0 - std::backtrace_rs::backtrace::trace_unsynchronized::h6830419c0c4130dc
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5645b3db32f0 - std::sys_common::backtrace::_print_fmt::h8f3516631ffa1ef5
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x5645b3db32f0 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::he1640d5f0d93f618
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x5645b3ddc20c - core::fmt::write::h88012e1f01caeebf
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/fmt/mod.rs:1115:17
   5:     0x5645b3daa965 - std::io::Write::write_fmt::h360fa85b30182555
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/io/mod.rs:1665:15
   6:     0x5645b3db597b - std::sys_common::backtrace::_print::ha1f00492f406a015
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x5645b3db597b - std::sys_common::backtrace::print::hd54561b13feb6af3
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x5645b3db597b - std::panicking::default_hook::{{closure}}::h84fe124cd0864662
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/panicking.rs:208:50
   9:     0x5645b3db5451 - std::panicking::default_hook::h5a8e74a76ce290a7
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/panicking.rs:225:9
  10:     0x5645b3db6044 - std::panicking::rust_panic_with_hook::h67c812a4fe9d4c91
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/panicking.rs:622:17
  11:     0x5645b3db5b27 - std::panicking::begin_panic_handler::{{closure}}::h33f9c1b96af300d7
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/panicking.rs:519:13
  12:     0x5645b3db37ec - std::sys_common::backtrace::__rust_end_short_backtrace::h51bae64be5921f0e
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/sys_common/backtrace.rs:141:18
  13:     0x5645b3db5a89 - rust_begin_unwind
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/panicking.rs:515:5
  14:     0x5645b21fb151 - core::panicking::panic_fmt::h12a3a3c256485fca
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/panicking.rs:92:14
  15:     0x5645b21fb043 - core::option::expect_failed::h7db74b1e3f5289b2
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/option.rs:1578:5
  16:     0x5645b3db2cfb - core::option::Option<T>::expect::h065a4b9904843553
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/option.rs:685:21
  17:     0x5645b3db2cfb - std::time::Instant::duration_since::hd53abd8aeb35af76
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/time.rs:281:9
  18:     0x5645b3db2cfb - <std::time::Instant as core::ops::arith::Sub>::sub::hb011b7f33830dc36
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/time.rs:406:9
  19:     0x5645b3db2cfb - std::time::Instant::elapsed::ha9954b30ffc6b968
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/time.rs:345:9
  20:     0x5645b3322f1a - metrics::histogram::Histogram::update_since::h7f0a825eecfa476f
  21:     0x5645b31674b2 - network::connection::GenericConnection<Socket>::writable::hb9639cbfe4978018
  22:     0x5645b3159a11 - <network::service::NetworkServiceInner as io::IoHandler<network::NetworkIoMessage>>::stream_writable::h91b25c094d486502
  23:     0x5645b317c1a6 - std::sys_common::backtrace::__rust_begin_short_backtrace::h969c9cf40e1629af
  24:     0x5645b31a4138 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h5c242c42265b1b1d
  25:     0x5645b3dbdb37 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h6bff7798948b1075
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/alloc/src/boxed.rs:1572:9
  26:     0x5645b3dbdb37 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hc2d25ac38f6b2342
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/alloc/src/boxed.rs:1572:9
  27:     0x5645b3dbdb37 - std::sys::unix::thread::Thread::new::thread_start::hbba5bc368baac205
                               at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/sys/unix/thread.rs:74:17
  28:     0x7f98baefe6db - start_thread
  29:     0x7f98ba265a3f - __clone
  30:                0x0 - <unknown>

The Instant instance that calls elapsed() is Packet::creation_time and is created with Instant::now(), so this panic is not supposed to happen. Related discussion indicate that this may be a kernel bug: rust-lang/rust#86470

The current plan is to use Instant::saturating_duration_since for metrics to circumvent this specific possible panic. Since elapsed is also called in many dependencies, we cannot circumvent all use cases and rely on the node runner to fix this OS issue if it happens.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant